search

Darkness4 / fc2-live-dl-go

Automatically download FC2 livestream. Fast and light.
MIT License
9 stars 0 forks source link

Possible memory leak at concatenation #45

Closed Darkness4 closed 2 weeks ago

Darkness4 commented 1 month ago

Could be memory cache, files are all heathy. Difficult to replicate.

image

Logs:

2:01PM WRN github.com/Darkness4/fc2-live-dl-go/utils/try/try.go:155 > try failed error="server did not return a valid playlist" maxTries=10 try=0
2:01PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2_websocket.go:129 > ws fully connected url=wss://us-west-1-media-worker1058.live.fc2.com/control/channels/[REDACTED: ChannelID]?control_token=[REDACTED: control-token]
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/utils/try/try.go:155 > try failed error="requested quality is not available" maxTries=10 try=1
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/utils/try/try.go:155 > try failed error="requested quality is not available" maxTries=10 try=2
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/utils/try/try.go:155 > try failed error="requested quality is not available" maxTries=10 try=3
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/utils/try/try.go:155 > try failed error="requested quality is not available" maxTries=10 try=4
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/utils/try/try.go:155 > try failed error="requested quality is not available" maxTries=10 try=5
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/utils/try/try.go:155 > try failed error="requested quality is not available" maxTries=10 try=6
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/utils/try/try.go:155 > try failed error="requested quality is not available" maxTries=10 try=7
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/utils/try/try.go:155 > try failed error="requested quality is not available" maxTries=10 try=8
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:705 > requested quality is not available, will do... available_playlists=[{"Latency":3,"Quality":30},{"Latency":2,"Quality":30},{"Latency":1,"Quality":30},{"Latency":3,"Quality":20},{"Latency":2,"Quality":20},{"Latency":1,"Quality":20},{"Latency":3,"Quality":0},{"Latency":2,"Quality":0},{"Latency":1,"Quality":0},{"Latency":3,"Quality":0},{"Latency":3,"Quality":90},{"Latency":2,"Quality":90},{"Latency":2,"Quality":0},{"Latency":1,"Quality":0},{"Latency":1,"Quality":90}] channelID=[REDACTED: ChannelID] expected_latency=mid expected_quality=3Mbps got_latency=mid got_quality=1.2Mbps
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/utils/try/try.go:155 > try failed error="requested quality is not expected" maxTries=10 try=9
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/utils/try/try.go:160 > failed all tries error="requested quality is not expected"
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:385 > quality is not expected, will retry during download channelID=[REDACTED: ChannelID]
2:01PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:509 > received new HLS info channelID=[REDACTED: ChannelID] playlist={"mode":32,"status":0,"url":"https://us-west-1-media.live.fc2.com/a/stream/[REDACTED: ChannelID]/32/playlist?[REDACTED: unknown params]"}
2:01PM INF github.com/Darkness4/fc2-live-dl-go/hls/hls_downloader.go:125 > downloading channelID=[REDACTED: ChannelID]
2:01PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:509 > received new HLS info channelID=[REDACTED: ChannelID] playlist={"mode":52,"status":1,"url":"https://us-west-1-media.live.fc2.com/a/stream/[REDACTED: ChannelID]/52/playlist?[REDACTED: unknown params]"}
2:01PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:519 > QUALITY UPGRADE! Wait for new stream to be ready... channelID=[REDACTED: ChannelID]
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/hls/hls_downloader.go:415 > stream not ready channelID=[REDACTED: ChannelID]  method=GET response.body="Not found." response.status=404 url=https://us-west-1-media.live.fc2.com/a/stream/[REDACTED: ChannelID]/52/playlist?[REDACTED: unknown params]
2:01PM WRN github.com/Darkness4/fc2-live-dl-go/hls/hls_downloader.go:415 > stream not ready channelID=[REDACTED: ChannelID]  method=GET response.body="Not found." response.status=404 url=https://us-west-1-media.live.fc2.com/a/stream/[REDACTED: ChannelID]/52/playlist?[REDACTED: unknown params]
2:01PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:535 > switching downloader seamlessly... channelID=[REDACTED: ChannelID]
2:01PM INF github.com/Darkness4/fc2-live-dl-go/hls/hls_downloader.go:361 > canceled hls read channelID=[REDACTED: ChannelID]
2:01PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:564 > downloader canceled channelID=[REDACTED: ChannelID]
2:01PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:538 > downloader switched
2:01PM INF github.com/Darkness4/fc2-live-dl-go/hls/hls_downloader.go:125 > downloading channelID=[REDACTED: ChannelID]
4:33PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:352 > ws listen finished channelID=[REDACTED: ChannelID]
4:33PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:466 > cancelling... channelID=[REDACTED: ChannelID]
4:33PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:419 > download stream canceled channelID=[REDACTED: ChannelID]
4:33PM ERR github.com/Darkness4/fc2-live-dl-go/hls/hls_downloader.go:352 > a packet failed to be downloaded, skipping error="Get \"https://us-west-1-media-worker1096.live.fc2.com/a/stream/v3/[REDACTED: ChannelID]/52/data/9103.ts?time=1720715640&hash=9181d237cc2350c36225fc813f4c51b1bc561aebaa538c23205c01ddd28a020e\": context canceled" channelID=[REDACTED: ChannelID] error.count=1 error.max=20
4:33PM INF github.com/Darkness4/fc2-live-dl-go/hls/hls_downloader.go:361 > canceled hls read channelID=[REDACTED: ChannelID]
4:33PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:336 > healthcheck canceled channelID=[REDACTED: ChannelID]
4:33PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:468 > cancelled. channelID=[REDACTED: ChannelID]
4:33PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:224 > post-processing... channelID=[REDACTED: ChannelID]
4:33PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:263 > concatenating stream... channelID=[REDACTED: ChannelID] output="/output/[REDACTED: output]/[REDATED: video-title].combined.mp4" prefix="/output/[REDACTED: output]/[REDATED: video-title]"
4:33PM INF github.com/Darkness4/fc2-live-dl-go/video/concat/concat.go:94 > concat inputs=["/output/[REDACTED: output]/[REDATED: video-title].ts"] options={} output="/output/[REDACTED: output]/[REDATED: video-title].combined.mp4"
Input 0, mapping stream 0 (video) to output stream 0
Created output stream (video)
Input 0, mapping stream 1 (audio) to output stream 1
Created output stream (audio)
input#0, stream #0 discontinuity, last.dts=2787000, pkt.dts=531000, new offset=2259000
input#0, stream #1 discontinuity, last.dts=1486848, pkt.dts=283344, new offset=1204528
4:33PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:564 > downloader canceled channelID=[REDACTED: ChannelID]
4:36PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:280 > concatenating audio stream... channelID=[REDACTED: ChannelID] output="/output/[REDACTED: output]/[REDATED: video-title].combined.m4a" prefix="/output/[REDACTED: output]/[REDATED: video-title]"
4:36PM INF github.com/Darkness4/fc2-live-dl-go/video/concat/concat.go:94 > concat inputs=["/output/[REDACTED: output]/[REDATED: video-title].ts"] options={} output="/output/[REDACTED: output]/[REDATED: video-title].combined.m4a"
Blacklisted stream #0 (video)
Input 0, mapping stream 1 (audio) to output stream 0
Created output stream (audio)
input#0, stream #0 discontinuity, last.dts=1486848, pkt.dts=283344, new offset=1204528
4:38PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:301 > done channelID=[REDACTED: ChannelID]
4:38PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2.go:68 > watching channel channelID=[REDACTED: ChannelID] params={"AllowQualityUpgrade":true,"Concat":true,"CookiesFile":"/config/cookies.txt","CookiesRefreshDuration":86400000000000,"DeleteCorrupted":true,"EligibleForCleaningAge":10800000000000,"ExtractAudio":true,"KeepIntermediates":false,"Labels":{"EnglishName":"Kagura Maimai"},"Latency":3,"OutFormat":"/output/{{ .ChannelName }} {{ .Labels.EnglishName }}/{{ .Date }} {{ .Title }}.{{ .Ext }}","PacketLossMax":20,"PollQualityUpgradeInterval":10000000000,"Quality":50,"Remux":false,"RemuxFormat":"mp4","ScanDirectory":"/output","WaitForLive":true,"WaitForQualityMaxTries":10,"WaitPollInterval":10000000000,"WriteChat":false,"WriteInfoJSON":false,"WriteThumbnail":false}
4:38PM INF github.com/Darkness4/fc2-live-dl-go/fc2/fc2_livestream.go:56 > waiting for stream channelID=[REDACTED: ChannelID]

Update:

Memory cleared itself after memory dumping.

image

The program became unhealthy and kubernetes decided to kill it.

Darkness4 commented 1 month ago

Issue is being traced with Pyroscope (release v1.8.0-alpha.1).

Darkness4 commented 1 month ago

Memory leaks were found at the wrapper function: calling cstr = C.CString(gostr) without calling C.free(unsafe.Pointer(cstr)). Fix in commit c8dc8bc533571721507dfec1fc186513e7045f05.

This only proves "slight" memory leakage, but not the big memory chunk seen in the screenshot.

Darkness4 commented 1 month ago

Profiling report:

Container memory usage image

Goroutines image

Alloc objects image

Alloc space image

Inuse objects image

Inuse space image

CPU usage via pprof image

Overshooting of the limit could be cause be GC cache + mem leak. Closing until further proof.

Darkness4 commented 3 weeks ago

Memory leak without free found (dts_offset). Fixed via arena allocation (https://github.com/Darkness4/fc2-live-dl-go/commit/17972632547105566c6fb39fc3d1f4840ed5b8ad)