Nvidida Shield dropping frames/skipping while watching live TV

thors1982 · October 16, 2021, 9:40pm

I have a 2017 Nvidia shield that is dropping frames (only on live TV, the recording seem great!). It isn't very frequent but enough to be annoying. When it happens the timeline pops up at the bottom as well. Using the show stats I see about 66 dropped frames in the past 30 minutes and when it skips the dropped frames jumps up about 17 frames or so. Also I don't notice any skipping when using the HD HomeRun application.

My setup:

Shield running over ethernet.
HD HomeRun Prime also on ethernet
The same Shield is also running the DVR server (Have a friend doing this so I thought it would be fine if this is a problem let me know)
Verizon Fios is the TV provider
Tuner sharing is off
Test speed to DVR Server (1478 Mbit/s, Latency, 2ms, Jitter 5.6 ms)
Streaming Quality is set to Original

Things I have tried:

I changed the shield to cool mode from quiet and changed to maximum performance (Also added a small USB computer case fan underneath it to cool it more just in-case)
I tried hardware, hybrid, and software decoding. In the Channels app
Different channels
Restarting shield and Force stopping/Clearing cache of the app
During these hiccups no other devices were watching/streaming TV

Any ideas/suggestions would be greatly appreciated. Also if there is anymore information or things I try let me know! Thanks for all the help in advance!

I also submitted video diagnostics at 5:14pm EST (about 26 minutes before this was posted) if that helps. (However I can do it again not a problem at all!)

speedingcheetah · October 17, 2021, 1:18am

Back when i heavily watched live tv, i would see the same thing. My mother, who uses Channels more than I, complains about the same thing. It infrequent enough to not be a bother, but still can be annoying.

Some channels its worse, and an other problem there it fully freezes, but the buffer keeps going, or will even jump around and back. Only way to resolve the issue is back out and reload the channels. That mostly happens on some TVE channels, and for a while, especially on Discovery stations during the commercials. One TVe station that still does it every time, is the 24/7 Rick and Morty channels, it will freeze every time when one ep ends, and a new one starts.

I have never had the server on the same machine as a client.
I have had server on an powerful Intel NUC for a while but now use 2x RPi4's.
I use multiple clients, 2019 Shield Pro & Tube, TiVo Stream 4K, and most recent, an Apple Tv 4K. All hardwired.
I have not watched Live TV enough on the Apple TV to see if it exabits this infrequent behavior of drop frames though, and there is no way to view player stats on Apple Tv version.

Recordings of the same program that had this glitch while watching live, were perfectly fine.

Pretty sure has to be something client side not server side.

I suggest, when it happens, check your sever logs to see if there in anything informative, and if it a HDHR stream, see what the signal stats are when the glitch happens.
And, submit diagnostics from the client app right after it happens and the devs can advise further.

psperry · October 17, 2021, 2:48am

For whatever it’s worth, I never have this issue. I have a simple Ethernet connected Linux server with a mixture of AppleTV and FireTV throughout the house. Most of my streamers are connected via WiFi. WiFi is nothing special. We use a three node google WiFi system to cover more than 3000 square feet. Works fine but we don’t do any large file transfers. Nothing fancy.

I share this only as I wonder if maybe you are dealing with a architectural problem rather than a problem with Channels. Nobody’s fault. There is no recommended configuration. Just tossing additional info out there for consideration.

thors1982 · October 17, 2021, 3:54am

@speedingcheetah just to be clear I don't see any issues when using HD HomeRun it works fine. On DVR server I went to support->logs almost nothing jumps out other than below (but that was only once during the entire 24 hours period where I saw hundreds of skips.

2021/10/16 17:13:43.226568 [DIAG] Could not package /providers/playon/library: 404 Not Found
2021/10/16 17:13:43.229288 [DIAG] Could not find file: /vendor/etc/media_codecs.xml: open /vendor/etc/media_codecs.xml: no such file or directory
2021/10/16 17:13:43.447161 [DIAG] Could not find file: channels-comskip-controller.log: open channels-comskip-controller.log: no such file or directory
2021/10/16 17:13:48.834034 New diagnostic log submitted under 0bab9a77-7008-4241-a853-c35a778b169e

And thank you so much for the help!

thors1982 · October 17, 2021, 3:55am

@psperry Definitely could be right, I am not discounting anything!

However I used a Windows Media Center to watch live TV for past 11 years (till about 3 weeks ago) and never had a single issue. I am able to use the HD HomeRun app on shield and multiple Windows pcs no problem at all.

I can try an android phone or a Chromecast with Google TV tomorrow as those are my only other devices that have a channel app.

We also use shield all the time to stream video from a nas and internet and haven't had any issues either.

And thank you so much for the help!

thors1982 · October 18, 2021, 11:36pm

I tried my phone and the Chromecast with Google TV
My phone I don't think is powerful enough it was buffering constantly but had very few dropped frames. However some (Still doesn't seem like a fair comparison).

The Chromecast with Google TV also was dropping frames about 340 in 5 minutes or so (I didn't time it). I noticed 1 dropped frame every once in a while but no change in video. Then after some time I could see the video skip and the dropped frames jump up by 10-30. Also the timeline didn't pop up on the chromecast when it dropped frames. The chromecast was also much more sporadic than with the shield(The shield almost always jumps up the dropped frames by exactly 17. Also FYI left all the settings default on the chromecast. It is on wifi and a much less powerful device.

Also if it wasn't clear all the dropped frames are on the output. The decoding never has any.

Is there a way to get more logging? I keep checking logs in the DVR but nothing about the video ever shows up its usually just channel changes and recordings.

tmm1 · October 18, 2021, 11:51pm

You can access the player logs via the IP of your client device http://x.x.x.x:57000/log

thors1982 · October 19, 2021, 12:45am

I did manage to grab the logs when it happened back to back in a short period of time. Looks like it goes into a buffering state randomly.

In the logs my strength, quality and symbol are all 100%. I did see strength drop to 98% earlier but didn't see any issues during that time.

10-18 20:36:36.144  9072  9072 V mpvstats: AV: 1187.619 A-V: 0.000 Dropped: 100 Cache: 0.416s + 0KB
10-18 20:36:36.144  9072  9072 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
10-18 20:36:37.220  9072  9104 V mpv     : event: unpause
10-18 20:36:37.223  9072  9104 V mpv     : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
10-18 20:36:37.224  9072  9104 V mpv     : property: buffering = true
10-18 20:36:37.224  9072  9072 V PlayerActivity: state PLAYING -> BUFFERING
10-18 20:36:37.229  9072  9104 V mpv     : [cplayer] Still buffering (buffer went from 0% -> 38%) [0.192000s].
10-18 20:36:37.229  9072  9072 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1175.1062776666731, end=1189.3119998888942}], cache-end=1189.343977666671, reader-pts=1189.1519776666755, cache-duration=0.1919999999954598, eof=false, underrun=false, idle=false, total-bytes=33383600, fw-bytes=1893760, debug-low-level-seeks=0, debug-ts-last=57806.84566666667, ts-per-stream=[{type=video, duration=1.0010000000038417, reader=57806.2883, end=57807.289300000004}, {type=audio, duration=0.1919999999954598, reader=57806.65366666667, end=57806.84566666667}]}
10-18 20:36:37.245  9072  9104 V mpv     : [cplayer] Still buffering (buffer went from 38% -> 70%) [0.352022s].
10-18 20:36:37.370  9072  9104 V mpv     : [cplayer] Still buffering (buffer went from 70% -> 96%) [0.480022s].
10-18 20:36:37.482  9072  9104 V mpv     : event: unpause
10-18 20:36:37.482  9072  9104 V mpv     : [cplayer] End buffering (waited 0.243389 secs) [0.576022s].
10-18 20:36:37.491  9072  9104 V mpv     : property: buffering = false
10-18 20:36:37.491  9072  9072 V PlayerActivity: state BUFFERING -> PLAYING
10-18 20:36:37.491  9072  9072 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1175.1062776666731, end=1189.6959998888924}], cache-end=1189.7279998888916, reader-pts=1189.1519776666755, cache-duration=0.5760222222161246, eof=false, underrun=false, idle=false, total-bytes=34306608, fw-bytes=2816768, debug-low-level-seeks=0, debug-ts-last=57806.271622333334, ts-per-stream=[{type=video, duration=1.3179888888917048, reader=57806.2883, end=57807.60628888889}, {type=audio, duration=0.5760222222161246, reader=57806.65366666667, end=57807.22968888889}]}
10-18 20:36:37.988  9072  9072 V mpvstats: AV: 1189.471 A-V: 0.000 Dropped: 114 Cache: 0.384s + 0KB
10-18 20:36:39.143  9072  9072 V mpvstats: AV: 1190.622 A-V: 0.000 Dropped: 114 Cache: 0.288s + 0KB
10-18 20:36:39.143  9072  9072 V streamstats: strength=100% quality=100% symbol=100% rate=17.8Mb/sec
10-18 20:36:41.579  9072 29089 V ApiServer: REQUEST: GET /log
10-18 20:36:42.144  9072  9072 V mpvstats: AV: 1193.625 A-V: 0.000 Dropped: 114 Cache: 0.288s + 0KB
10-18 20:36:42.144  9072  9072 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
10-18 20:36:45.145  9072  9072 V mpvstats: AV: 1196.628 A-V: 0.000 Dropped: 114 Cache: 0.384s + 0KB
10-18 20:36:45.146  9072  9072 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
10-18 20:36:45.990  9072  9108 V libchannels: libchannels: creating new segment at idx=40
10-18 20:36:45.991  9072  9109 V libchannels: libchannels: pruning segment with idx=15
10-18 20:36:46.074  9072  9108 V libchannels: libchannels: rolling over reader to segment with idx=40
10-18 20:36:47.245  9072  9104 V mpv     : event: unpause
10-18 20:36:47.245  9072  9104 V mpv     : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
10-18 20:36:47.245  9072  9104 V mpv     : property: buffering = true
10-18 20:36:47.245  9072  9072 V PlayerActivity: state PLAYING -> BUFFERING
10-18 20:36:47.246  9072  9072 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1185.0995998888975, end=1199.103977666673}], cache-end=1199.1359776666723, reader-pts=1199.1359776666723, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=33099856, fw-bytes=1328400, debug-low-level-seeks=0, debug-ts-last=57816.23156677777, ts-per-stream=[{type=video, duration=0.6840222222162993, reader=57816.33166666667, end=57817.01568888889}, {type=audio, duration=0.0, reader=57816.63766666667, end=57816.63766666667}]}
10-18 20:36:47.609  9072  9104 V mpv     : [cplayer] Still buffering (buffer went from 0% -> 83%) [0.416022s].
10-18 20:36:47.609  9072  9104 V mpv     : [cplayer] Still buffering (buffer went from 83% -> 76%) [0.384022s].
10-18 20:36:47.638  9072  9104 V mpv     : event: unpause
10-18 20:36:47.638  9072  9104 V mpv     : [cplayer] End buffering (waited 0.372201 secs) [0.736022s].
10-18 20:36:47.639  9072  9104 V mpv     : property: buffering = false
10-18 20:36:47.640  9072  9072 V PlayerActivity: state BUFFERING -> PLAYING
10-18 20:36:47.652  9072  9072 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1185.0995998888975, end=1199.8719998888919}], cache-end=1199.9039998888911, reader-pts=1199.2639998888917, cache-duration=0.6399999999994179, eof=false, underrun=false, idle=false, total-bytes=34837648, fw-bytes=3056528, debug-low-level-seeks=0, debug-ts-last=57816.26493344444, ts-per-stream=[{type=video, duration=1.401399999995192, reader=57816.33166666667, end=57817.73306666667}, {type=audio, duration=0.6399999999994179, reader=57816.76568888889, end=57817.40568888889}]}
10-18 20:36:48.024  9072  9072 V mpvstats: AV: 1199.364 A-V: 0.000 Dropped: 129 Cache: 0.416s + 0KB
10-18 20:36:48.146  9072  9072 V mpvstats: AV: 1199.481 A-V: 0.000 Dropped: 129 Cache: 0.544s + 0KB
10-18 20:36:48.146  9072  9072 V streamstats: strength=100% quality=100% symbol=100% rate=17.7Mb/sec
10-18 20:36:51.146  9072  9072 V mpvstats: AV: 1202.484 A-V: 0.000 Dropped: 129 Cache: 0.416s + 0KB
10-18 20:36:51.147  9072  9072 V streamstats: strength=100% quality=100% symbol=100% rate=17.8Mb/sec

I will keep poking around the logs but wanted to post this as I have no clue why that would happen. Any thoughts?

racameron · October 19, 2021, 12:47am

Strength of 100% can mean strength of far over 100%, which can affect reception.

tmm1 · October 19, 2021, 1:13am

This is the cause of the buffering event.

Are you playing ac3 bitstream? Does the same thing happen with surround off?

thors1982 · October 19, 2021, 1:29am

Looks like it the current audio format according to the "Show stats" is raw-ac3 and "raw_ac3 (raw audio pass-through decoder)". Note I also recorded the same channel earlier and its raw-ac3 and seems to play fine on the recording(I will record a longer segment so that I can triple check)

@tmm1 do you want me to turn surround sound off on the shield or in the channels app, both, or one then the other???

I absolutely don't mind testing like that or tweaking some settings once we figure out what is wrong but I have a home theater and would definitely want surround sound going forward. I hope that is understandable.

tmm1 · October 19, 2021, 2:09am

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

thors1982 · October 19, 2021, 2:43am

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.

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

tmm1 · October 19, 2021, 6:44pm

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

thors1982 · October 19, 2021, 9:39pm

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!

thors1982 · October 19, 2021, 10:52pm

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 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.

tmm1 · October 21, 2021, 1:43am

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.

thors1982 · October 21, 2021, 5:15pm

@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!

tmm1 · October 21, 2021, 5:53pm

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?

thors1982 · October 21, 2021, 6:22pm

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