Nvidida Shield dropping frames/skipping while watching live TV

Try turning off in the channels app. Just want to know if that changes behavior or not for troubleshooting.

Absolutely anything I can do to test/debug/help just let me know!

Watching with surround sound off the format changed to "floatp" and "ac3 (ATSC A/52A (AC-3))"

And it did happen again back to back as well however I did refresh log after first... as you can probably see, not sure if that caused second or not. But refreshing log, I don't think has messed it up before. :man_shrugging:

10-18 22:37:16.813 32546 32546 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
10-18 22:37:18.505 32546 32576 V mpv     : event: unpause
10-18 22:37:18.505 32546 32576 V mpv     : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
10-18 22:37:18.558 32546 32576 V mpv     : property: buffering = true
10-18 22:37:18.558 32546 32546 V PlayerActivity: state PLAYING -> BUFFERING
10-18 22:37:18.586 32546 32576 V mpv     : [cplayer] Still buffering (buffer went from 0% -> 76%) [0.384000s].
10-18 22:37:18.629 32546 32546 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1054.8764110000047, end=1069.055999888893}], cache-end=1069.0879998888922, reader-pts=1069.0879998888922, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=33142224, fw-bytes=1376928, debug-low-level-seeks=0, debug-ts-last=65047.92263344445, ts-per-stream=[{type=video, duration=0.6172777777755982, reader=65047.956000000006, end=65048.57327777778}, {type=audio, duration=0.0, reader=65048.25368888889, end=65048.25368888889}]}
10-18 22:37:18.706 32546 32576 V mpv     : [cplayer] Still buffering (buffer went from 76% -> 95%) [0.480000s].
10-18 22:37:18.818 32546 32576 V mpv     : event: unpause
10-18 22:37:18.818 32546 32576 V mpv     : [cplayer] End buffering (waited 0.302853 secs) [0.607978s].
10-18 22:37:18.820 32546 32576 V mpv     : property: buffering = false
10-18 22:37:18.876 32546 32546 V PlayerActivity: state BUFFERING -> PLAYING
10-18 22:37:18.881 32546 32546 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1055.1266554444446, end=1069.6639776666707}], cache-end=1069.69597766667, reader-pts=1069.247977666666, cache-duration=0.4480000000039581, eof=false, underrun=false, idle=false, total-bytes=34043200, fw-bytes=2206544, debug-low-level-seeks=0, debug-ts-last=65048.18956677778, ts-per-stream=[{type=video, duration=0.9509555555559928, reader=65048.206244444445, end=65049.1572}, {type=audio, duration=0.4480000000039581, reader=65048.41366666667, end=65048.86166666667}]}
10-18 22:37:19.534 32546 32546 V mpvstats: AV: 1069.574 A-V: 0.000 Dropped: 148 Cache: 0.576s + 0KB
10-18 22:37:19.814 32546 32546 V mpvstats: AV: 1069.858 A-V: 0.000 Dropped: 148 Cache: 0.480s + 0KB
10-18 22:37:19.814 32546 32546 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
10-18 22:37:22.814 32546 32546 V mpvstats: AV: 1072.861 A-V: 0.000 Dropped: 148 Cache: 0.480s + 0KB
10-18 22:37:22.815 32546 32546 V streamstats: strength=100% quality=100% symbol=100% rate=17.5Mb/sec
10-18 22:37:23.324 32546  1797 V ApiServer: REQUEST: GET /log
10-18 22:37:23.629 32546 32576 V mpv     : event: unpause
10-18 22:37:23.629 32546 32576 V mpv     : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
10-18 22:37:23.629 32546 32576 V mpv     : property: buffering = true
10-18 22:37:23.629 32546 32546 V PlayerActivity: state PLAYING -> BUFFERING
10-18 22:37:23.629 32546 32546 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1059.914777666665, end=1074.0159776666696}], cache-end=1074.0479776666689, reader-pts=1074.0479776666689, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=32946912, fw-bytes=1581968, debug-low-level-seeks=0, debug-ts-last=65052.844211222226, ts-per-stream=[{type=video, duration=0.650655555560661, reader=65052.87757777778, end=65053.52823333334}, {type=audio, duration=0.0, reader=65053.21366666667, end=65053.21366666667}]}
10-18 22:37:24.030 32546 32576 V mpv     : [cplayer] Still buffering (buffer went from 0% -> 44%) [0.224022s].
10-18 22:37:24.092 32546 32576 V mpv     : event: unpause
10-18 22:37:24.092 32546 32576 V mpv     : [cplayer] End buffering (waited 0.454711 secs) [0.896000s].
10-18 22:37:24.092 32546 32576 V mpv     : property: buffering = false
10-18 22:37:24.093 32546 32546 V PlayerActivity: state BUFFERING -> PLAYING
10-18 22:37:24.099 32546 32546 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1059.914777666665, end=1074.9119776666703}], cache-end=1074.9439776666695, reader-pts=1074.1759998888883, cache-duration=0.7679777777811978, eof=false, underrun=false, idle=false, total-bytes=34890064, fw-bytes=3515456, debug-low-level-seeks=0, debug-ts-last=65052.87757788889, ts-per-stream=[{type=video, duration=1.5015000000057626, reader=65052.87757777778, end=65054.37907777778}, {type=audio, duration=0.7679777777811978, reader=65053.34168888889, end=65054.10966666667}]}
10-18 22:37:24.542 32546 32546 V mpvstats: AV: 1074.262 A-V: 0.000 Dropped: 150 Cache: 0.800s + 0KB
10-18 22:37:25.823 32546 32546 V mpvstats: AV: 1075.530 A-V: 0.000 Dropped: 150 Cache: 0.768s + 0KB
10-18 22:37:25.823 32546 32546 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec

Also thank you so much for your incredibly quick responses and incredibly great support. I am trying to help in anyway I can but I am clearly not an expert in this stuff :slight_smile:

1 Like

I would like to see what the line matching "Setting bufferSize =" looks like in both surround modes.

For surround sound off
10-19 17:15:46.418 28483 28519 V mpv : [ao/audiotrack] Setting bufferSize = 28800 (driver=12320, min=28800, max=57600)
Tried another channel and exact same

For surround sound on
10-19 17:26:15.820 28483 28519 V mpv : [ao/audiotrack] Setting bufferSize = 4800 (driver=1540, min=0, max=0)
Tried another channel and bufferSize went up to 5600 but driver/min/max were the same.

*Note I did not see it error on these values as I was just trying to get you a response quickly and didn't wait for it to happen. I will keep testing random stuff though!

I honestly don't know if I am making this worse or not.... yesterday I saw it drop the audio as you pointed out dozens and dozens of times. This time I see video drops not audio, if I am reading the
below correct :frowning: It has happened at least 10 times. I wanted to make sure it would happen more before I posted something completely random.

ALSO I kept surround sound off for tests.

Very first few I saved

    10-19 18:17:57.177 28483 28519 V mpv     : event: unpause
    10-19 18:17:57.177 28483 28519 V mpv     : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
    10-19 18:17:57.177 28483 28519 V mpv     : property: buffering = true
    10-19 18:17:57.177 28483 28483 V PlayerActivity: state PLAYING -> BUFFERING
    10-19 18:17:57.178 28483 28483 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=2399.8986888888903, end=2413.8559999999998}], cache-end=2413.887999999999, reader-pts=2413.887999999999, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=32829680, fw-bytes=1114880, debug-low-level-seeks=0, debug-ts-last=40445.12438888889, ts-per-stream=[{type=video, duration=0.5171777777795796, reader=40445.25785555556, end=40445.77503333334}, {type=audio, duration=0.0, reader=40445.4, end=40445.4}]}
    10-19 18:17:57.200 28483 28519 V mpv     : event: unpause
    10-19 18:17:57.200 28483 28519 V mpv     : [cplayer] End buffering (waited 0.023098 secs) [0.671978s].
    10-19 18:17:57.203 28483 28519 V mpv     : property: buffering = false
    10-19 18:17:57.220 28483 28483 V PlayerActivity: state BUFFERING -> PLAYING
    10-19 18:17:57.221 28483 28483 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=2399.8986888888903, end=2414.527977777776}], cache-end=2414.559977777775, reader-pts=2414.0800000000017, cache-duration=0.4799777777734562, eof=false, underrun=false, idle=false, total-bytes=34565264, fw-bytes=2835968, debug-low-level-seeks=0, debug-ts-last=40445.157755555556, ts-per-stream=[{type=video, duration=1.2512444444437278, reader=40445.25785555556, end=40446.5091}, {type=audio, duration=0.4799777777734562, reader=40445.592000000004, end=40446.07197777778}]}
    10-19 18:17:58.058 28483 28483 V mpvstats: AV: 2414.563 A-V: 0.000 Dropped: 41 Cache: 0.512s + 0KB
    10-19 18:17:58.059 28483 28483 V streamstats: strength=100% quality=100% symbol=100% rate=17.5Mb/sec
    10-19 18:17:58.097 28483 28483 V mpvstats: AV: 2414.597 A-V: 0.000 Dropped: 41 Cache: 0.512s + 0KB
    10-19 18:18:01.059 28483 28483 V mpvstats: AV: 2417.566 A-V: 0.000 Dropped: 41 Cache: 0.480s + 0KB
    10-19 18:18:01.059 28483 28483 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
    10-19 18:18:03.277 28483 29994 V ApiServer: REQUEST: GET /log
    10-19 18:18:03.466 28483 28494 I hannels.dvr.ap: Background concurrent copying GC freed 325920(12MB) AllocSpace objects, 19(1172KB) LOS objects, 49% free, 16MB/32MB, paused 100us total 156.552ms
    10-19 18:18:03.469 28483 28492 W System  : A resource failed to call end. 
    10-19 18:18:04.061 28483 28483 V mpvstats: AV: 2420.553 A-V: 0.000 Dropped: 41 Cache: 0.448s + 0KB
    10-19 18:18:04.061 28483 28483 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
    10-19 18:18:07.033 28483 28519 V mpv     : event: unpause
    10-19 18:18:07.033 28483 28519 V mpv     : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
    10-19 18:18:07.034 28483 28519 V mpv     : property: buffering = true
    10-19 18:18:07.034 28483 28483 V PlayerActivity: state PLAYING -> BUFFERING
    10-19 18:18:07.034 28483 28483 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=2409.7918999999965, end=2423.872000000003}], cache-end=2423.9040000000023, reader-pts=2423.9040000000023, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=33144272, fw-bytes=1475232, debug-low-level-seeks=0, debug-ts-last=40455.05096666667, ts-per-stream=[{type=video, duration=0.5505444444497698, reader=40455.067655555555, end=40455.618200000004}, {type=audio, duration=0.0, reader=40455.416000000005, end=40455.416000000005}]}
    10-19 18:18:07.177 28483 28483 V mpvstats: AV: 2423.539 A-V: 0.000 Dropped: 41 Cache: 0.224s + 0KB
    10-19 18:18:07.177 28483 28483 V streamstats: strength=100% quality=100% symbol=100% rate=17.1Mb/sec
    10-19 18:18:07.181 28483 28519 V mpv     : [cplayer] Still buffering (buffer went from 0% -> 57%) [0.288000s].
    10-19 18:18:07.252 28483 28519 V mpv     : event: unpause
    10-19 18:18:07.252 28483 28519 V mpv     : [cplayer] End buffering (waited 0.198625 secs) [0.639978s].
    10-19 18:18:07.254 28483 28519 V mpv     : property: buffering = false
    10-19 18:18:07.264 28483 28483 V PlayerActivity: state BUFFERING -> PLAYING
    10-19 18:18:07.270 28483 28483 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=2409.7918999999965, end=2424.51197777778}], cache-end=2424.543977777779, reader-pts=2424.0319999999992, cache-duration=0.5119777777799754, eof=false, underrun=false, idle=false, total-bytes=34711312, fw-bytes=2901056, debug-low-level-seeks=0, debug-ts-last=40455.101022222225, ts-per-stream=[{type=video, duration=1.1010999999998603, reader=40455.1177, end=40456.2188}, {type=audio, duration=0.5119777777799754, reader=40455.544, end=40456.05597777778}]}
    10-19 18:18:08.190 28483 28483 V mpvstats: AV: 2424.590 A-V: 0.000 Dropped: 44 Cache: 0.544s + 0KB

Last one

    10-19 18:32:29.870 28483 28483 V streamstats: strength=100% quality=100% symbol=100% rate=17.8Mb/sec
    10-19 18:32:30.027 28483 28519 V mpv     : event: unpause
    10-19 18:32:30.027 28483 28519 V mpv     : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
    10-19 18:32:30.028 28483 28519 V mpv     : property: buffering = true
    10-19 18:32:30.028 28483 28483 V PlayerActivity: state PLAYING -> BUFFERING
    10-19 18:32:30.028 28483 28483 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=404.9752775555535, end=419.0399775555561}], cache-end=419.07197755555535, reader-pts=419.07197755555535, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=33051280, fw-bytes=1173840, debug-low-level-seeks=0, debug-ts-last=41317.92964466667, ts-per-stream=[{type=video, duration=0.533866666672111, reader=41318.04642222222, end=41318.580288888894}, {type=audio, duration=0.0, reader=41318.29595555556, end=41318.29595555556}]}
    10-19 18:32:30.129 28483 28519 V mpv     : event: unpause
    10-19 18:32:30.129 28483 28519 V mpv     : [cplayer] End buffering (waited 0.101319 secs) [0.736022s].
    10-19 18:32:30.129 28483 28519 V mpv     : property: buffering = false
    10-19 18:32:30.131 28483 28483 V PlayerActivity: state BUFFERING -> PLAYING
    10-19 18:32:30.134 28483 28483 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=404.9752775555535, end=419.7759997777757}], cache-end=419.80799977777497, reader-pts=419.2319997777813, cache-duration=0.5759999999936554, eof=false, underrun=false, idle=false, total-bytes=34784752, fw-bytes=2895232, debug-low-level-seeks=0, debug-ts-last=41317.96301133333, ts-per-stream=[{type=video, duration=1.2846222222215147, reader=41318.04642222222, end=41319.33104444444}, {type=audio, duration=0.5759999999936554, reader=41318.45597777778, end=41319.03197777778}]}
    10-19 18:32:30.915 28483 28483 V mpvstats: AV: 419.640 A-V: 0.000 Dropped: 48 Cache: 0.576s + 0KB
    10-19 18:32:32.871 28483 28483 V mpvstats: AV: 421.592 A-V: 0.000 Dropped: 48 Cache: 0.576s + 0KB
    10-19 18:32:32.871 28483 28483 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec

Lastly I saw what I purely guess to be a suggestion from a library? Probably meaningless but just in case
10-19 18:25:32.769 28483 28483 I ViewTarget: Glide treats LayoutParams.WRAP_CONTENT as a request for an image the size of this device's screen dimensions. If you want to load the original image and are ok with the corresponding memory cost and OOMs (depending on the input size), use override(Target.SIZE_ORIGINAL). Otherwise, use LayoutParams.MATCH_PARENT, set layout_width and layout_height to fixed dimension, or use .override() with fixed dimensions.

Finally I apologize I am making this worse by posting so much. I do just want to help but if especially this post is just noise I am sorry. Let me know and I can stop posting random things I find that you didn't ask for!

I am sure this is a very very difficult problem to isolate and track.

2 Likes

Thanks for the info. I have the details I need, and am looking into this issue.

I've put out a new alpha build of the app which has several audio related playback changes. It is currently not working correctly with surround sound, but I would like to know if it fixes the issue for you with surround off.

You will need to install the beta app via Settings > Support > Install Beta, then from the beta app select Install Alpha. Then turn off surround sound in that app and watch TV to see if it pauses to go into buffering or not.

@tmm1
I did a few more tests on my own and am now running the latest alpha build now as well (without surround sound).

I do believe the latest alpha build has fixed it! However I don't know how to look at the logs to "prove" it. Because the stream still gets dropped frames, HOWEVER I think those are switching from like national to local or something? Because they were happening in some of my other tests when I wasn't having the issue. AND those drop frames aren't noticeable or bothersome, also the log message was different and wasn't about buffering. So I don't think they matter :-).

If there is a link I can poke at for the alpha logs I would love to take a look and prove its not the state changing from PLAYING to BUFFERING.

Also feel free to let me know when you think surround sound is fixed and I can help test that as well.

Thank you again I really do appreciate it!

You should be able to load the alpha logs on 57000 as well, but you may need to force stop the other copies of the app first and restart the alpha so it can bind to that port.

Previously you were seeing the player pause and spinner icon come up on screen, right? Is that still happening?

1 Like

It used to stop for about 17 frames so I don't remember seeing the spinner, but the video did pause and the timeline popped up. That is NOT happening anymore so I am pretty sure its fixed!! I am happy with what I am seeing right now.

I just was going to poke around the logs and double check :slight_smile:

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 :slight_smile:

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 :slight_smile:

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 :frowning:
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