Yes please do and let me know if the logs look correct now. You can also click Settings > Support > Submit Diagnostics > Video Player and I can take a look.
It would also be helpful if you can try with surround on and describe the results.
I'm uploading a new alpha now with fixes to surround sound issues I was seeing on some channels. This build should work in both modes and hopefully not enter BUFFERING anymore during playback.
Without surround sound I think it looks GREAT!
I looked at logs quite a bit and did more test. I also submitted logs if you want to look at it.
I do (in logs see it drop a few frames when it switches from 5.1 to stereo then back to 5.1) However it is ONLY noticeable in logs. I don't notice it all just watching TV like a normal person. So in my opinion its perfect 
Sorry I didn't get your message about surround sound till now :-p (I just updated alpha) and I will move on to that next. Thank you again! Amazingly fast bug fixes.
3 Likes
Thanks! Very curious to hear your results with surround on.
I would call it a success! Noticed nothing at all in the show we watched today. And logs looked great as well!
We will be watching a ton live TV tomorrow, so I will let you know if anything changes but I don't expect it will.
Again thank you. I really do appreciate it. The app is super slick and am excited to migrate to it from my old windows media center setup
2 Likes
That's great news. I will look at bringing this back into the beta channel and out to release soon. Hopefully we can get some more folks around here with CCGTV and other devices to try it out and confirm it works there too.
I submitted video logs of it happening again. Hopefully it was a one off issue and not an actual problem. I will keep an eye on it however. I am only posting so you know I submitted logs.
Its a smaller station I normally don't watch so no clue if that is related.
Also pasting logs I grabbed just in-case.
10-23 13:00:19.772 17386 17386 V streamstats: strength=100% quality=100% symbol=100% rate=17.6Mb/sec
10-23 13:00:22.774 17386 17386 V mpvstats: AV: 1960.282 A-V: 0.000 Dropped: 38 Cache: 0.160s + 0KB
10-23 13:00:22.774 17386 17386 V streamstats: strength=100% quality=100% symbol=100% rate=17.6Mb/sec
10-23 13:00:23.290 17386 17422 W mpv : [cplayer] Audio device underrun detected.
10-23 13:00:23.290 17386 17422 V mpv : event: unpause
10-23 13:00:23.290 17386 17422 V mpv : property: buffering = true
10-23 13:00:23.290 17386 17422 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
10-23 13:00:23.290 17386 17386 V PlayerActivity: state PLAYING -> BUFFERING
10-23 13:00:23.291 17386 17386 V mpvstats: demuxer-cache-state: {cache-end=1960.9076226666657, reader-pts=1960.9076226666657, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=95449040, fw-bytes=0, raw-input-rate=2290957, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=60752.26988844445, ts-per-stream=[{type=video, duration=0.0, reader=60752.70365555556, end=60752.70365555556}, {type=audio, duration=0.0, reader=60752.37796666667, end=60752.37796666667}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=1919.2580448888912, end=1960.7661782222203}]}
10-23 13:00:23.336 17386 17422 V mpv : [cplayer] Still buffering (buffer went from 0% -> 57%) [0.288000s].
10-23 13:00:23.336 17386 17422 V mpv : [cplayer] Still buffering (buffer went from 57% -> 12%) [0.064000s].
10-23 13:00:23.341 17386 17422 V mpv : [cplayer] Still buffering (buffer went from 12% -> 95%) [0.479989s].
10-23 13:00:23.346 17386 17422 V mpv : event: unpause
10-23 13:00:23.346 17386 17422 V mpv : property: buffering = false
10-23 13:00:23.346 17386 17422 V mpv : [cplayer] End buffering (waited 0.055490 secs) [0.575989s].
10-23 13:00:23.346 17386 17422 V mpv : [cplayer] restarting audio after underrun
10-23 13:00:23.379 17386 17386 V PlayerActivity: state BUFFERING -> PLAYING
10-23 13:00:23.380 17386 17386 V mpvstats: demuxer-cache-state: {cache-end=1961.7076115555537, reader-pts=1961.3556115555548, cache-duration=0.35199999999895226, eof=false, underrun=false, idle=false, total-bytes=95268608, fw-bytes=1821632, raw-input-rate=2290957, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=60752.30325511111, ts-per-stream=[{type=video, duration=0.867533333330357, reader=60752.70365555556, end=60753.57118888889}, {type=audio, duration=0.35199999999895226, reader=60752.825955555556, end=60753.177955555555}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=1920.2590448888877, end=1961.6756115555545}]}
10-23 13:00:24.081 17386 17386 V mpvstats: AV: 1961.600 A-V: 0.000 Dropped: 40 Cache: 0.352s + 0KB
10-23 13:00:25.777 17386 17386 V mpvstats: AV: 1963.285 A-V: 0.000 Dropped: 40 Cache: 0.288s + 0KB
10-23 13:00:25.778 17386 17386 V streamstats: strength=100% quality=100% symbol=100% rate=17.6Mb/sec`
and
`10-23 13:02:14.470 17386 17426 V libchannels: libchannels: rolling over reader to segment with idx=70
10-23 13:02:16.988 17386 17386 V mpvstats: AV: 2074.496 A-V: 0.000 Dropped: 40 Cache: 0.320s + 0KB
10-23 13:02:16.988 17386 17386 V streamstats: strength=100% quality=100% symbol=100% rate=17.6Mb/sec
10-23 13:02:19.988 17386 17386 V mpvstats: AV: 2077.499 A-V: 0.000 Dropped: 40 Cache: 0.320s + 0KB
10-23 13:02:19.988 17386 17386 V streamstats: strength=100% quality=100% symbol=100% rate=17.6Mb/sec
10-23 13:02:21.661 17386 17422 W mpv : [cplayer] Audio device underrun detected.
10-23 13:02:21.677 17386 17422 V mpv : event: unpause
10-23 13:02:21.677 17386 17422 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
10-23 13:02:21.677 17386 17422 V mpv : property: buffering = true
10-23 13:02:21.677 17386 17386 V PlayerActivity: state PLAYING -> BUFFERING
10-23 13:02:21.678 17386 17386 V mpvstats: demuxer-cache-state: {cache-end=2079.4023559999987, reader-pts=2079.4023559999987, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=95480880, fw-bytes=387616, raw-input-rate=2345194, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=60870.65482177778, ts-per-stream=[{type=video, duration=0.20019999999931315, reader=60871.088588888895, end=60871.288788888894}, {type=audio, duration=0.0, reader=60870.8727, end=60870.8727}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=2037.876544888888, end=2079.3703559999994}]}
10-23 13:02:21.745 17386 17422 V mpv : [cplayer] Still buffering (buffer went from 0% -> 6%) [0.031989s].
10-23 13:02:21.745 17386 17422 V mpv : [cplayer] Still buffering (buffer went from 6% -> 12%) [0.063989s].
10-23 13:02:21.750 17386 17422 V mpv : [cplayer] Still buffering (buffer went from 12% -> 6%) [0.032000s].
10-23 13:02:21.750 17386 17422 V mpv : [cplayer] Still buffering (buffer went from 6% -> 12%) [0.064000s].
10-23 13:02:21.751 17386 17422 V mpv : [cplayer] Still buffering (buffer went from 12% -> 6%) [0.032000s].
10-23 13:02:21.751 17386 17422 V mpv : [cplayer] Still buffering (buffer went from 6% -> 0%) [0.000000s].
10-23 13:02:21.760 17386 17422 V mpv : [cplayer] Still buffering (buffer went from 0% -> 31%) [0.160000s].
10-23 13:02:22.025 17386 17422 W mpv : [ao/audiotrack] getLatency: written=18153984 playhead=18156281 diff=4294964999 delay=89478.437479
10-23 13:02:22.046 17386 17422 V mpv : event: unpause
10-23 13:02:22.046 17386 17422 V mpv : property: buffering = false
10-23 13:02:22.046 17386 17422 V mpv : [cplayer] End buffering (waited 0.368407 secs) [0.704000s].
10-23 13:02:22.046 17386 17422 V mpv : [cplayer] restarting audio after underrun
10-23 13:02:22.046 17386 17386 V PlayerActivity: state BUFFERING -> PLAYING
10-23 13:02:22.047 17386 17386 V mpvstats: demuxer-cache-state: {cache-end=2080.330344888891, reader-pts=2079.626344888893, cache-duration=0.7039999999979045, eof=false, underrun=false, idle=false, total-bytes=95167616, fw-bytes=2381456, raw-input-rate=2345194, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=60870.688188444445, ts-per-stream=[{type=video, duration=1.034366666666756, reader=60871.088588888895, end=60872.12295555556}, {type=audio, duration=0.7039999999979045, reader=60871.096688888894, end=60871.80068888889}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=2038.8775448888919, end=2080.2983448888917}]}
10-23 13:02:22.126 17386 18863 W AudioTrack: releaseBuffer() track 0x2f2289f000 disabled due to previous underrun, restarting
10-23 13:02:22.881 17386 17386 V mpvstats: AV: 2080.169 A-V: 0.000 Dropped: 53 Cache: 0.608s + 0KB
10-23 13:02:22.989 17386 17386 V mpvstats: AV: 2080.269 A-V: 0.000 Dropped: 53 Cache: 0.704s + 0KB
10-23 13:02:22.989 17386 17386 V streamstats: strength=100% quality=100% symbol=100% rate=17.6Mb/sec`FYI we had mostly been using ESPN as our test channel. And was able to go almost 2 hours with no issues on Friday using ESPN.
Today it only really happened on one channel, but it was also my most watched channel for a large portion of time. Notes below
12:30-1:25pm - Channel: MASN (Stopped to Buffer 3 times, logs of the first in post above) 1:25pm - Force stopped app (and double checked I was using alpha app) including making sure other apps were stopped. All was correct. 1:25-2:05pm - Channel: MASN (Stopped to Buffer 2 times) 2:05-2:25pm - Channel: ABC (Zero issues) 2:25-4:05pm - Channel: MASN (Stopped to Buffer 9 times) I feel like it started happening more and more the longer the station was on first 45 minutes I think only had a few 4:05-5:20pm - Channel hopping: (Zero issues)
Sorry for the bad news 
The good news is I do think it is better than before. I didn't keep track but last weekend(mostly ESPN but also other channels) it felt more like it was happening every 5 minutes or so.
Won't be able to test more till tomorrow. But hopefully I can figure out if other channels are fine before you are back to work Monday.
Didn't have the issue at all today watched ABC for about 2.5 hours no issues at all. So I am pretty sure it is that station or the content on at the time that created a new unique situation.
So happy this is being worked on! Gonna install the Alpha and test!
2 Likes
I ended up watching another football game on MASN today which was almost 3 hours and probably only noticed it once, I didn't feel the need to monitor logs because it was working well. I have also spent several hours on ABC, Fox, ESPN and seems to be working overall.
However, I did have it happen twice just now on ESPN (posted below) but again the buffering seems to be rare now versus how it was before. Also looks like the logging says Audio device underrun detected which I don't think was there before so my guess is this is a different more rare scenario.
10-30 17:28:11.000 31441 31441 V mpvstats: AV: 3613.764 A-V: 0.000 Dropped: 66 Cache: 0.320s + 0KB
10-30 17:28:11.000 31441 31441 V streamstats: strength=100% quality=100% symbol=100% rate=17.8Mb/sec
10-30 17:28:12.967 31441 963 V libchannels: libchannels: creating new segment at idx=122
10-30 17:28:12.968 31441 31493 V libchannels: libchannels: pruning segment with idx=103
10-30 17:28:13.052 31441 31495 V libchannels: libchannels: rolling over reader to segment with idx=122
10-30 17:28:14.001 31441 31441 V mpvstats: AV: 3616.767 A-V: 0.000 Dropped: 66 Cache: 0.288s + 0KB
10-30 17:28:14.001 31441 31441 V streamstats: strength=100% quality=100% symbol=100% rate=17.8Mb/sec
10-30 17:28:16.893 31441 31486 W mpv : [cplayer] Audio device underrun detected.
10-30 17:28:16.895 31441 31486 V mpv : event: unpause
10-30 17:28:16.924 31441 31486 V mpv : property: buffering = true
10-30 17:28:16.925 31441 31486 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
10-30 17:28:16.946 31441 31441 V PlayerActivity: state PLAYING -> BUFFERING
10-30 17:28:16.964 31441 31441 V mpvstats: demuxer-cache-state: {cache-end=3619.808022555557, reader-pts=3619.808022555557, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=95958448, fw-bytes=907504, raw-input-rate=2308954, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=33427.89255522222, ts-per-stream=[{type=video, duration=0.5005000000019209, reader=33427.925922222224, end=33428.42642222223}, {type=audio, duration=0.0, reader=33428.03095555556, end=33428.03095555556}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=3578.3283225555533, end=3619.7760225555576}]}
10-30 17:28:17.029 31441 31486 V mpv : [cplayer] Still buffering (buffer went from 0% -> 6%) [0.032000s].
10-30 17:28:17.032 31441 31486 V mpv : [cplayer] Still buffering (buffer went from 6% -> 0%) [0.000000s].
10-30 17:28:17.079 31441 31486 V mpv : event: unpause
10-30 17:28:17.079 31441 31486 V mpv : [cplayer] End buffering (waited 0.184246 secs) [0.544000s].
10-30 17:28:17.079 31441 31486 V mpv : property: buffering = false
10-30 17:28:17.079 31441 31486 V mpv : [cplayer] restarting audio after underrun
10-30 17:28:17.093 31441 9290 W AudioTrack: releaseBuffer() track 0x2f1c1ed800 disabled due to previous underrun, restarting
10-30 17:28:17.341 31441 31441 V mpvstats: AV: 3620.103 A-V: 0.000 Dropped: 72 Cache: 0.320s + 0KB
10-30 17:28:17.341 31441 31441 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
10-30 17:28:17.341 31441 31441 V PlayerActivity: state BUFFERING -> PLAYING
10-30 17:28:17.343 31441 31441 V mpvstats: demuxer-cache-state: {cache-end=3620.7680447777784, reader-pts=3620.4480447777787, cache-duration=0.31999999999970896, eof=false, underrun=false, idle=false, total-bytes=95559360, fw-bytes=1945200, raw-input-rate=2308954, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=33428.32632188889, ts-per-stream=[{type=video, duration=0.9509444444483961, reader=33428.37637777778, end=33429.32732222223}, {type=audio, duration=0.31999999999970896, reader=33428.67097777778, end=33428.99097777778}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=3579.329322555557, end=3620.736044777779}]}
10-30 17:28:17.517 31441 31441 V mpvstats: AV: 3620.287 A-V: 0.000 Dropped: 72 Cache: 0.320s + 0KB
10-30 17:28:20.341 31441 31441 V mpvstats: AV: 3623.056 A-V: 0.000 Dropped: 72 Cache: 0.384s + 0KB
10-30 17:28:20.341 31441 31441 V streamstats: strength=100% quality=100% symbol=100% rate=16.8Mb/sec
10-30 17:28:21.613 31441 9408 V ApiServer: REQUEST: GET /log
10-30 17:28:23.359 31441 31441 V mpvstats: AV: 3626.026 A-V: 0.000 Dropped: 72 Cache: 0.256s + 0KB
10-30 17:28:23.360 31441 31441 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
and
10-30 17:38:18.604 31441 31441 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
10-30 17:38:21.606 31441 31441 V mpvstats: AV: 4224.324 A-V: 0.000 Dropped: 72 Cache: 0.384s + 0KB
10-30 17:38:21.606 31441 31441 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
10-30 17:38:22.884 31441 31494 V libchannels: libchannels: creating new segment at idx=143
10-30 17:38:22.884 31441 31495 V libchannels: libchannels: pruning segment with idx=124
10-30 17:38:22.908 31441 963 V libchannels: libchannels: rolling over reader to segment with idx=143
10-30 17:38:24.607 31441 31441 V mpvstats: AV: 4227.310 A-V: 0.000 Dropped: 72 Cache: 0.352s + 0KB
10-30 17:38:24.607 31441 31441 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
10-30 17:38:25.993 31441 31486 W mpv : [cplayer] Audio device underrun detected.
10-30 17:38:25.993 31441 31486 V mpv : event: unpause
10-30 17:38:25.994 31441 31486 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
10-30 17:38:25.994 31441 31486 V mpv : property: buffering = true
10-30 17:38:25.994 31441 31441 V PlayerActivity: state PLAYING -> BUFFERING
10-30 17:38:25.995 31441 31441 V mpvstats: demuxer-cache-state: {cache-end=4228.832022555554, reader-pts=4228.832022555554, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=95572896, fw-bytes=908432, raw-input-rate=2254486, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=34036.93432188889, ts-per-stream=[{type=video, duration=0.45044444444647525, reader=34036.98437777778, end=34037.434822222225}, {type=audio, duration=0.0, reader=34037.054955555555, end=34037.054955555555}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=4187.169889222223, end=4228.800022555555}]}
10-30 17:38:26.069 31441 31486 V mpv : [cplayer] Still buffering (buffer went from 0% -> 57%) [0.288000s].
10-30 17:38:26.069 31441 31486 V mpv : [cplayer] Still buffering (buffer went from 57% -> 63%) [0.320000s].
10-30 17:38:26.069 31441 31486 V mpv : [cplayer] Still buffering (buffer went from 63% -> 19%) [0.096000s].
10-30 17:38:26.094 31441 31486 V mpv : event: unpause
10-30 17:38:26.094 31441 31486 V mpv : property: buffering = false
10-30 17:38:26.094 31441 31486 V mpv : [cplayer] End buffering (waited 0.100758 secs) [0.576000s].
10-30 17:38:26.094 31441 31486 V mpv : [cplayer] restarting audio after underrun
10-30 17:38:26.096 31441 31441 V PlayerActivity: state BUFFERING -> PLAYING
10-30 17:38:26.097 31441 31441 V mpvstats: demuxer-cache-state: {cache-end=4229.632022555557, reader-pts=4229.056022555556, cache-duration=0.5760000000009313, eof=false, underrun=false, idle=false, total-bytes=95510400, fw-bytes=2596272, raw-input-rate=1636148, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=34036.96768855555, ts-per-stream=[{type=video, duration=1.2178777777808136, reader=34036.98437777778, end=34038.20225555556}, {type=audio, duration=0.5760000000009313, reader=34037.27895555556, end=34037.85495555556}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=4187.92064477778, end=4229.600022555558}]}
10-30 17:38:26.192 31441 9290 W AudioTrack: releaseBuffer() track 0x2f1c1ed800 disabled due to previous underrun, restarting
10-30 17:38:26.282 31441 31441 V mpvstats: AV: 4228.978 A-V: 0.000 Dropped: 74 Cache: 0.448s + 0KB
10-30 17:38:27.607 31441 31441 V mpvstats: AV: 4230.246 A-V: 0.000 Dropped: 74 Cache: 0.416s + 0KB
Again wanted to say thanks for the patch, hopefully it helps others as well!
2 Likes
Just installed and I can already see a difference. On the non-HD OTA channels with surround sound on it would constantly buffer and be unwatchable unless i turned off Surround Sound.. Now it did it once as the channels starts and then it did it once about 15min so far.
You are on the right track for sure. As posted above it may not be 100% but it is about 90-95% there.
2 Likes
I can test this later on as I have one. I haven't used it much because of the bugs it has which google hasn't fixed yet.
1 Like
Installed and working well on my CCwGTV. Been watching NBC OTA (Saturday Night Live) for the last 30 minutes without a single issue.
EDIT because I can't post more than 3 in a row......
@tmm1
I have been watching an NBC-HD OTA channel on for the last 30 min and the time bar came up for a couple seconds and the video/sound briefly paused
Here is a log:
10-31 12:09:14.695 10534 10534 V mpvstats: AV: 2406.781 A-V: 0.000 Dropped: 9 Cache: 0.512s + 0KB
10-31 12:09:14.695 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=7.1Mb/sec
10-31 12:09:17.697 10534 10534 V mpvstats: AV: 2409.784 A-V: 0.000 Dropped: 9 Cache: 0.544s + 0KB
10-31 12:09:17.697 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=6.9Mb/sec
10-31 12:09:20.697 10534 10534 V mpvstats: AV: 2412.787 A-V: 0.000 Dropped: 9 Cache: 0.416s + 0KB
10-31 12:09:20.697 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=8.1Mb/sec
10-31 12:09:23.698 10534 10534 V mpvstats: AV: 2415.757 A-V: 0.000 Dropped: 9 Cache: 0.352s + 0KB
10-31 12:09:23.698 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=8.7Mb/sec
10-31 12:09:26.699 10534 10534 V mpvstats: AV: 2418.760 A-V: 0.000 Dropped: 9 Cache: 0.416s + 0KB
10-31 12:09:26.699 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=12.8Mb/sec
10-31 12:09:29.701 10534 10534 V mpvstats: AV: 2421.763 A-V: 0.000 Dropped: 9 Cache: 0.288s + 0KB
10-31 12:09:29.701 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=7.3Mb/sec
10-31 12:09:30.344 10534 10565 V mpv : event: unpause
10-31 12:09:30.344 10534 10565 V mpv : property: buffering = true
10-31 12:09:30.345 10534 10534 V PlayerActivity: state PLAYING -> BUFFERING
10-31 12:09:30.346 10534 10534 V mpvstats: demuxer-cache-state: {cache-end=2422.815999666669, reader-pts=2422.815999666669, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=94029176, fw-bytes=499144, raw-input-rate=796347, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=25175.101100333333, ts-per-stream=[{type=video, duration=0.6339666666681296, reader=25175.167833333333, end=25175.8018}, {type=audio, duration=0.0, reader=25175.486966666667, end=25175.486966666667}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=2329.103566333335, end=2422.4301330000017}]}
10-31 12:09:30.347 10534 10565 W mpv : [cplayer] Audio device underrun detected.
10-31 12:09:30.347 10534 10565 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
10-31 12:09:30.925 10534 10565 W mpv : [ao/audiotrack] getLatency: written=116250624 playhead=116255132 diff=4294962788 delay=89478.391417
10-31 12:09:30.931 10534 10534 I Choreographer: Skipped 34 frames! The application may be doing too much work on its main thread.
10-31 12:09:30.996 10534 10565 V mpv : [cplayer] Still buffering (buffer went from 0% -> 8%) [0.064000s].
10-31 12:09:30.996 10534 10565 V mpv : [cplayer] Still buffering (buffer went from 8% -> 4%) [0.032000s].
10-31 12:09:31.000 10534 10565 V mpv : [cplayer] Still buffering (buffer went from 4% -> 0%) [0.000000s].
10-31 12:09:31.011 10534 10565 V mpv : [cplayer] Still buffering (buffer went from 0% -> 76%) [0.576000s].
10-31 12:09:31.011 10534 10565 V mpv : [cplayer] Still buffering (buffer went from 76% -> 81%) [0.608000s].
10-31 12:09:31.203 10534 10565 V mpv : event: unpause
10-31 12:09:31.203 10534 10565 V mpv : property: buffering = false
10-31 12:09:31.204 10534 10534 V PlayerActivity: state BUFFERING -> PLAYING
10-31 12:09:31.204 10534 10565 V mpv : [cplayer] End buffering (waited 0.859183 secs) [1.376000s].
10-31 12:09:31.204 10534 10565 V mpv : [cplayer] restarting audio after underrun
10-31 12:09:31.208 10534 10534 V mpvstats: demuxer-cache-state: {cache-end=2424.4159996666713, reader-pts=2423.039999666671, cache-duration=1.3760000000002037, eof=false, underrun=false, idle=false, total-bytes=95993128, fw-bytes=2589040, raw-input-rate=416058, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=25175.134467, ts-per-stream=[{type=video, duration=2.769433333334746, reader=25175.167833333333, end=25177.937266666668}, {type=audio, duration=1.3760000000002037, reader=25175.71096666667, end=25177.08696666667}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=2329.103566333335, end=2424.3839996666684}]}
10-31 12:09:31.953 10534 10534 V mpvstats: AV: 2423.598 A-V: 0.000 Dropped: 20 Cache: 0.960s + 0KB
10-31 12:09:32.702 10534 10534 V mpvstats: AV: 2424.332 A-V: 0.000 Dropped: 20 Cache: 0.800s + 0KB
10-31 12:09:32.702 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=7.9Mb/sec
10-31 12:09:33.822 10534 10534 W Glide : Load failed for http://192.168.5.101:8089/tmsimg/assets/p500805_b_h9_aa.jpg?w=720&h=540 with size [-2147483648x-2147483648]
10-31 12:09:33.822 10534 10534 W Glide : class com.bumptech.glide.load.engine.GlideException: Failed to load resource
10-31 12:09:35.703 10534 10534 V mpvstats: AV: 2427.335 A-V: 0.000 Dropped: 20 Cache: 0.992s + 0KB
10-31 12:09:35.703 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=8.5Mb/sec
10-31 12:09:38.704 10534 10534 V mpvstats: AV: 2430.305 A-V: 0.000 Dropped: 20 Cache: 0.896s + 0KB
10-31 12:09:38.705 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=11.6Mb/sec
10-31 12:09:41.705 10534 10534 V mpvstats: AV: 2433.308 A-V: 0.000 Dropped: 20 Cache: 0.928s + 0KB
10-31 12:09:41.705 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=13.1Mb/sec
10-31 12:09:44.705 10534 10534 V mpvstats: AV: 2436.311 A-V: 0.000 Dropped: 20 Cache: 0.960s + 0KB
10-31 12:09:44.706 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=5.6Mb/sec
10-31 12:09:47.706 10534 10534 V mpvstats: AV: 2439.314 A-V: 0.000 Dropped: 20 Cache: 0.832s + 0KB
10-31 12:09:47.706 10534 10534 V streamstats: strength=100% quality=94% symbol=100% rate=9.5Mb/sec
10-31 12:09:50.706 10534 10534 V mpvstats: AV: 2442.317 A-V: 0.000 Dropped: 20 Cache: 0.896s + 0KB
10-31 12:09:50.707 10534 10534 V streamstats: strength=100% quality=92% symbol=100% rate=7.8Mb/sec
10-31 12:09:53.708 10534 10534 V mpvstats: AV: 2445.320 A-V: 0.000 Dropped: 20 Cache: 0.928s + 0KB
10-31 12:09:53.708 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=7.8Mb/sec
10-31 12:09:54.883 10534 12153 V ApiServer: REQUEST: GET /log
This time it happened where the timebar came on the screen BUT the video/sound did not pause at all.
Here is that log:
10-31 12:20:17.985 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=6.3Mb/sec
10-31 12:20:19.835 10534 10544 I s.dvr.app.alph: Background concurrent copying GC freed 279402(10MB) AllocSpace objects, 6(120KB) LOS objects, 49% free, 10MB/21MB, paused 215us total 100.732ms
10-31 12:20:20.985 10534 10534 V mpvstats: AV: 3072.613 A-V: 0.000 Dropped: 20 Cache: 0.832s + 0KB
10-31 12:20:20.986 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=6Mb/sec
10-31 12:20:23.986 10534 10534 V mpvstats: AV: 3075.616 A-V: 0.000 Dropped: 20 Cache: 0.864s + 0KB
10-31 12:20:23.986 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=8.5Mb/sec
10-31 12:20:26.987 10534 10534 V mpvstats: AV: 3078.619 A-V: 0.000 Dropped: 20 Cache: 0.896s + 0KB
10-31 12:20:26.987 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=7.9Mb/sec
10-31 12:20:29.988 10534 10534 V mpvstats: AV: 3081.622 A-V: 0.000 Dropped: 20 Cache: 0.768s + 0KB
10-31 12:20:29.988 10534 10534 V streamstats: strength=100% quality=85% symbol=100% rate=5.5Mb/sec
10-31 12:20:32.989 10534 10534 V mpvstats: AV: 3084.625 A-V: 0.000 Dropped: 20 Cache: 1.088s + 0KB
10-31 12:20:32.989 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=11Mb/sec
10-31 12:20:35.990 10534 10534 V mpvstats: AV: 3087.628 A-V: 0.000 Dropped: 20 Cache: 0.000s + 0KB
10-31 12:20:35.990 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=10.4Mb/sec
10-31 12:20:35.996 10534 10565 W mpv : [cplayer] Audio device underrun detected.
10-31 12:20:35.999 10534 10565 V mpv : event: unpause
10-31 12:20:35.999 10534 10565 V mpv : property: buffering = true
10-31 12:20:35.999 10534 10534 V PlayerActivity: state PLAYING -> BUFFERING
10-31 12:20:36.001 10534 10565 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
10-31 12:20:36.002 10534 10534 V mpvstats: demuxer-cache-state: {cache-end=3088.095999666668, reader-pts=3088.095999666668, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=94598800, fw-bytes=1121136, raw-input-rate=1307576, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=25840.332333666665, ts-per-stream=[{type=video, duration=1.067733333333308, reader=25840.432433333335, end=25841.50016666667}, {type=audio, duration=0.0, reader=25840.766966666666, end=25840.766966666666}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=3019.459899666668, end=3088.0639996666687}]}
10-31 12:20:36.127 10534 10565 V mpv : [cplayer] Still buffering (buffer went from 0% -> 8%) [0.064000s].
10-31 12:20:36.127 10534 10565 V mpv : [cplayer] Still buffering (buffer went from 8% -> 21%) [0.160000s].
10-31 12:20:36.128 10534 10565 V mpv : [cplayer] Still buffering (buffer went from 21% -> 12%) [0.096000s].
10-31 12:20:36.179 10534 10565 V mpv : event: unpause
10-31 12:20:36.180 10534 10565 V mpv : property: buffering = false
10-31 12:20:36.180 10534 10565 V mpv : [cplayer] End buffering (waited 0.178965 secs) [1.056000s].
10-31 12:20:36.180 10534 10565 V mpv : [cplayer] restarting audio after underrun
10-31 12:20:36.186 10534 10534 V PlayerActivity: state BUFFERING -> PLAYING
10-31 12:20:36.191 10534 10534 V mpvstats: demuxer-cache-state: {cache-end=3089.3759996666704, reader-pts=3088.31999966667, cache-duration=1.0560000000004948, eof=false, underrun=false, idle=false, total-bytes=95873568, fw-bytes=2032896, raw-input-rate=739645, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=25840.432433666665, ts-per-stream=[{type=video, duration=2.0353666666669596, reader=25840.599266666668, end=25842.634633333335}, {type=audio, duration=1.0560000000004948, reader=25840.990966666668, end=25842.04696666667}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=3019.459899666668, end=3089.343999666671}]}
10-31 12:20:36.782 10534 10534 V mpvstats: AV: 3088.395 A-V: 0.000 Dropped: 21 Cache: 0.896s + 0KB
10-31 12:20:38.992 10534 10534 V mpvstats: AV: 3090.598 A-V: 0.000 Dropped: 21 Cache: 0.768s + 0KB
10-31 12:20:38.992 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=10.2Mb/sec
10-31 12:20:41.995 10534 10534 V mpvstats: AV: 3093.634 A-V: 0.000 Dropped: 21 Cache: 0.960s + 0KB
10-31 12:20:41.995 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=9.8Mb/sec
10-31 12:20:44.997 10534 10534 V mpvstats: AV: 3096.604 A-V: 0.000 Dropped: 21 Cache: 0.832s + 0KB
10-31 12:20:44.997 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=10.6Mb/sec
10-31 12:20:47.998 10534 10534 V mpvstats: AV: 3099.607 A-V: 0.000 Dropped: 21 Cache: 0.896s + 0KB
10-31 12:20:47.999 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=8.1Mb/sec
10-31 12:20:50.999 10534 10534 V mpvstats: AV: 3102.610 A-V: 0.000 Dropped: 21 Cache: 0.928s + 0KB
10-31 12:20:50.999 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=6.2Mb/sec
10-31 12:20:53.999 10534 10534 V mpvstats: AV: 3105.613 A-V: 0.000 Dropped: 21 Cache: 0.960s + 0KB
10-31 12:20:53.999 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=8.5Mb/sec
10-31 12:20:56.999 10534 10534 V mpvstats: AV: 3108.616 A-V: 0.000 Dropped: 21 Cache: 0.832s + 0KB
10-31 12:20:56.999 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=9.3Mb/sec
10-31 12:20:57.335 10534 10574 V libchannels: libchannels: creating new segment at idx=63
10-31 12:20:57.335 10534 11192 V libchannels: libchannels: pruning segment with idx=59
10-31 12:20:57.370 10534 10574 V libchannels: libchannels: rolling over reader to segment with idx=63
10-31 12:20:59.999 10534 10534 V mpvstats: AV: 3111.619 A-V: 0.000 Dropped: 21 Cache: 0.896s + 0KB
10-31 12:20:59.999 10534 10534 V streamstats: strength=100% quality=90% symbol=100% rate=7.8Mb/sec
10-31 12:21:03.001 10534 10534 V mpvstats: AV: 3114.622 A-V: 0.000 Dropped: 21 Cache: 0.928s + 0KB
10-31 12:21:03.002 10534 10534 V streamstats: strength=100% quality=98% symbol=100% rate=8.1Mb/sec
10-31 12:21:04.501 10534 12409 V ApiServer: REQUEST: GET /log
1 Like
I still think things are better but definitely happens from time to time. Watching the football game tonight I decided to grab logs as it happened back to back. The second one was long pause... like 2-3 seconds logs below! I do hope we are helping!
Also definitely let us know if we need to update to a latest alpha for more logging or any patches I just realized I hadn't updated since your first patch.
11-05 22:03:05.038 12586 12586 V mpvstats: AV: 9115.926 A-V: 0.000 Dropped: 141 Cache: 0.640s + 0KB
11-05 22:03:05.038 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
11-05 22:03:08.039 12586 12586 V mpvstats: AV: 9118.929 A-V: 0.001 Dropped: 141 Cache: 0.512s + 0KB
11-05 22:03:08.039 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
11-05 22:03:09.427 12586 12621 W mpv : [cplayer] Audio device underrun detected.
11-05 22:03:09.428 12586 12621 V mpv : event: unpause
11-05 22:03:09.428 12586 12621 V mpv : property: buffering = true
11-05 22:03:09.428 12586 12586 V PlayerActivity: state PLAYING -> BUFFERING
11-05 22:03:09.429 12586 12586 V mpvstats: demuxer-cache-state: {cache-end=9120.480066333337, reader-pts=9120.480066333337, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=95709040, fw-bytes=1085104, raw-input-rate=2286788, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=48598.18922255555, ts-per-stream=[{type=video, duration=0.5004999999946449, reader=48598.205911111116, end=48598.70641111111}, {type=audio, duration=0.0, reader=48598.338833333335, end=48598.338833333335}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=9078.755588555563, end=9120.448066333338}]}
11-05 22:03:09.430 12586 12621 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
11-05 22:03:09.573 12586 12621 V mpv : [cplayer] Still buffering (buffer went from 0% -> 44%) [0.223978s].
11-05 22:03:09.573 12586 12621 V mpv : [cplayer] Still buffering (buffer went from 44% -> 6%) [0.032000s].
11-05 22:03:09.579 12586 12621 V mpv : [cplayer] Still buffering (buffer went from 6% -> 57%) [0.288022s].
11-05 22:03:09.623 12586 12621 V mpv : event: unpause
11-05 22:03:09.623 12586 12621 V mpv : [cplayer] End buffering (waited 0.195389 secs) [0.864022s].
11-05 22:03:09.623 12586 12621 V mpv : property: buffering = false
11-05 22:03:09.623 12586 12621 V mpv : [cplayer] restarting audio after underrun
11-05 22:03:09.627 12586 12586 V PlayerActivity: state BUFFERING -> PLAYING
11-05 22:03:09.629 12586 12586 V mpvstats: demuxer-cache-state: {cache-end=9121.56806633334, reader-pts=9120.704044111117, cache-duration=0.8640222222238663, eof=false, underrun=false, idle=false, total-bytes=95935680, fw-bytes=3482672, raw-input-rate=1223875, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=48598.22258922222, ts-per-stream=[{type=video, duration=1.5515444444463355, reader=48598.23927777778, end=48599.790822222225}, {type=audio, duration=0.8640222222238663, reader=48598.562811111115, end=48599.42683333334}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=9079.75658855556, end=9121.536066333341}]}
11-05 22:03:09.666 12586 16402 W AudioTrack: releaseBuffer() track 0x2f24245000 disabled due to previous underrun, restarting
11-05 22:03:10.300 12586 12586 V mpvstats: AV: 9121.181 A-V: 0.000 Dropped: 146 Cache: 0.544s + 0KB
11-05 22:03:11.039 12586 12586 V mpvstats: AV: 9121.865 A-V: 0.000 Dropped: 146 Cache: 0.704s + 0KB
11-05 22:03:11.039 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
11-05 22:03:14.039 12586 12586 V mpvstats: AV: 9124.868 A-V: 0.000 Dropped: 146 Cache: 0.640s + 0KB
11-05 22:03:14.039 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
11-05 22:03:17.039 12586 12586 V mpvstats: AV: 9127.871 A-V: 0.000 Dropped: 146 Cache: 0.608s + 0KB
11-05 22:03:17.039 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
11-05 22:03:20.040 12586 12586 V mpvstats: AV: 9130.874 A-V: 0.000 Dropped: 146 Cache: 0.640s + 0KB
11-05 22:03:20.040 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=17.3Mb/sec
11-05 22:03:23.040 12586 12586 V mpvstats: AV: 9133.877 A-V: 0.000 Dropped: 146 Cache: 0.640s + 0KB
11-05 22:03:23.040 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=16.4Mb/sec
11-05 22:03:24.059 12586 12624 V libchannels: libchannels: creating new segment at idx=309
11-05 22:03:24.060 12586 12630 V libchannels: libchannels: pruning segment with idx=291
11-05 22:03:24.085 12586 12630 V libchannels: libchannels: rolling over reader to segment with idx=309
11-05 22:03:26.040 12586 12586 V mpvstats: AV: 9136.864 A-V: 0.000 Dropped: 146 Cache: 0.704s + 0KB
11-05 22:03:26.040 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=17.8Mb/sec
11-05 22:03:29.041 12586 12586 V mpvstats: AV: 9139.867 A-V: 0.000 Dropped: 146 Cache: 0.640s + 0KB
11-05 22:03:29.041 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
11-05 22:03:32.042 12586 12586 V mpvstats: AV: 9142.870 A-V: 0.000 Dropped: 146 Cache: 0.544s + 0KB
11-05 22:03:32.043 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=17.8Mb/sec
11-05 22:03:32.793 12586 12621 W mpv : [cplayer] Audio device underrun detected.
11-05 22:03:32.793 12586 12621 V mpv : event: unpause
11-05 22:03:32.793 12586 12621 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
11-05 22:03:32.793 12586 12621 V mpv : property: buffering = true
11-05 22:03:32.794 12586 12586 V PlayerActivity: state PLAYING -> BUFFERING
11-05 22:03:32.794 12586 12586 V mpvstats: demuxer-cache-state: {cache-end=9143.872066333337, reader-pts=9143.872066333337, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=95913904, fw-bytes=1116064, raw-input-rate=2020201, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=48621.495844777775, ts-per-stream=[{type=video, duration=0.48381111110938946, reader=48621.595944444445, end=48622.079755555555}, {type=audio, duration=0.0, reader=48621.730833333335, end=48621.730833333335}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=9102.395877444447, end=9143.840066333338}]}
11-05 22:03:33.221 12586 12621 W mpv : [ao/audiotrack] getLatency: written=36915200 playhead=36920270 diff=4294962226 delay=76695.754036
11-05 22:03:34.358 12586 12621 V mpv : [cplayer] Still buffering (buffer went from 0% -> 6%) [0.032000s].
11-05 22:03:34.361 12586 12621 V mpv : [cplayer] Still buffering (buffer went from 6% -> 0%) [0.000000s].
11-05 22:03:34.366 12586 12621 V mpv : [cplayer] Still buffering (buffer went from 0% -> 51%) [0.256022s].
11-05 22:03:34.566 12586 12621 V mpv : event: unpause
11-05 22:03:34.566 12586 12621 V mpv : property: buffering = false
11-05 22:03:34.566 12586 12621 V mpv : [cplayer] End buffering (waited 1.772402 secs) [2.368022s].
11-05 22:03:34.566 12586 12586 V PlayerActivity: state BUFFERING -> PLAYING
11-05 22:03:34.566 12586 12621 V mpv : [cplayer] restarting audio after underrun
11-05 22:03:34.568 12586 12586 V mpvstats: demuxer-cache-state: {cache-end=9146.464066333341, reader-pts=9144.096044111116, cache-duration=2.368022222224681, eof=false, underrun=false, idle=false, total-bytes=95423328, fw-bytes=7044048, raw-input-rate=1270241, debug-low-level-seeks=0, debug-byte-level-seeks=1, debug-ts-last=48621.51252255555, ts-per-stream=[{type=video, duration=3.0363666666671634, reader=48621.595944444445, end=48624.63231111111}, {type=audio, duration=2.368022222224681, reader=48621.954811111114, end=48624.32283333334}], bof-cached=false, eof-cached=false, seekable-ranges=[{start=9105.198677444452, end=9146.432066333335}]}
11-05 22:03:34.630 12586 16402 W AudioTrack: releaseBuffer() track 0x2f24245000 disabled due to previous underrun, restarting
11-05 22:03:35.043 12586 12586 V mpvstats: AV: 9144.271 A-V: 0.000 Dropped: 161 Cache: 2.272s + 0KB
11-05 22:03:35.043 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
11-05 22:03:35.347 12586 12586 V mpvstats: AV: 9144.588 A-V: 0.000 Dropped: 161 Cache: 2.272s + 0KB
11-05 22:03:38.044 12586 12586 V mpvstats: AV: 9147.274 A-V: 0.000 Dropped: 161 Cache: 2.208s + 0KB
11-05 22:03:38.044 12586 12586 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
2 Likes
Just when I start to see progress we get radio silence. This has happened before. I'm just glad we have some progress with Android.
Thanks for the logs.
I've made some more improvements and am uploading a new alpha v2021.11.11.1948 now for testing.
3 Likes
Anxiously awaiting results. I really hope this fixes the issue once and for all.
@tmm1 Thanks for the build!
I tested a mini amount and nothing bad to report but was a short test. Saturday we watch the most live TV so I will have an update tomorrow!
And as always thanks a bunch!
1 Like