Premium TV Micro Pauses

Channels Apple TV
#1

Still seeing ongoing issues with micro pauses while watching the Premium TV channels. I only see this with Channels meaning not with the native SD app on a Mac and not with any other streaming services. I see it on both wired and wireless ATVs and also both ATV4s and ATV4Ks.

For a bit I thought I saw a correlation between micro pauses and tuner sharing, however, that was a red herring. I do believe that I've seen a reduction in the frequency by turning on "Match Frame Rate" on the ATV.

Here are some logs from an ATV showing the pauses:

2018-11-14 09:40:52.980 [cplayer] v: Starting playback... 2018-11-14 09:40:52.985 [vd] v: Decoder format: 1280x720 yuv420p auto/auto/auto/auto/auto CL=mpeg2/4/h264 (auto 0.000000/0.000000/0.000000) 2018-11-14 09:40:52.989 [vf] v: [in] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264 2018-11-14 09:40:52.992 [vf] v: [userdeint] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264 2018-11-14 09:40:52.995 [vf] v: [lavfi] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264 2018-11-14 09:40:52.998 [vf] v: [autorotate] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264 2018-11-14 09:40:53.001 [vf] v: [convert] 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264 2018-11-14 09:40:53.004 [af] v: [in] 48000Hz stereo 2ch floatp 2018-11-14 09:40:53.007 [af] v: format changed, draining filter chain 2018-11-14 09:40:53.010 [af] v: done format change draining 2018-11-14 09:40:53.015 [af] v: probing new format 2018-11-14 09:40:53.019 [af] v: [userspeed] 48000Hz stereo 2ch floatp 2018-11-14 09:40:53.022 [af] v: [convert] 48000Hz stereo 2ch floatp 2018-11-14 09:40:53.026 [af] v: got output format from probing 2018-11-14 09:40:53.030 [ao] v: Trying audio driver 'audiounit' 2018-11-14 09:40:53.034 [ao/audiounit] v: requested format: 48000 Hz, stereo channels, floatp 2018-11-14 09:40:53.038 [ao/audiounit] v: using soft-buffer of 9600 samples. 2018-11-14 09:40:53.042 [cplayer] info: AO: [audiounit] 48000Hz stereo 2ch floatp 2018-11-14 09:40:53.044 [cplayer] v: AO: Description: AudioUnit (iOS) 2018-11-14 09:40:53.046 [cplayer] info: VO: [libmpv] 1280x720 yuv420p 2018-11-14 09:40:53.048 [cplayer] v: VO: Description: render API for libmpv 2018-11-14 09:40:53.050 [vo/libmpv] v: reconfig to 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264 2018-11-14 09:40:53.052 [cplayer] v: first video frame after restart shown 2018-11-14 09:40:53.054 [cplayer] v: Enter buffering (buffer went from 100% -> 63%) [0.633967s]. 2018-11-14 09:40:53.056 [cplayer] info: (+) Video --vid=1 (h264) 2018-11-14 09:40:53.058 [cplayer] info: (+) Audio --aid=1 --alang=eng (aac) 2018-11-14 09:40:53.061 [cplayer] info: Subs --sid=1 (*) (eia_608) 2018-11-14 09:40:53.476 event: playback-restart 2018-11-14 09:40:53.482 Updating playState from LTVideoPlayerPlayStateLoading to LTVideoPlayerPlayStatePlaying 2018-11-14 09:40:53.488 [cplayer] v: starting audio playback 2018-11-14 09:40:53.492 [cplayer] v: playback restart complete 2018-11-14 09:40:54.007 event: unpause 2018-11-14 09:40:54.011 [cplayer] v: End buffering (waited 1.147000 secs) [1.045333s]. 2018-11-14 09:40:54.024 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStatePlaying 2018-11-14 09:47:43.214 event: unpause 2018-11-14 09:47:43.218 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-14 09:47:43.221 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-14 09:47:43.529 event: unpause 2018-11-14 09:47:43.532 [cplayer] v: End buffering (waited 0.328584 secs) [1.280000s]. 2018-11-14 09:47:43.541 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying 2018-11-14 09:47:45.197 event: unpause 2018-11-14 09:47:45.199 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-14 09:47:45.204 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-14 09:47:45.556 event: unpause 2018-11-14 09:47:45.558 [cplayer] v: End buffering (waited 0.343960 secs) [1.856000s]. 2018-11-14 09:47:45.567 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying 2018-11-14 09:47:47.457 event: unpause 2018-11-14 09:47:47.460 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-14 09:47:47.463 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-14 09:47:47.743 [cplayer] v: Still buffering (buffer went from 0% -> 8%) [0.085333s]. 2018-11-14 09:47:47.746 [cplayer] v: Still buffering (buffer went from 8% -> 21%) [0.213333s]. 2018-11-14 09:47:47.750 [cplayer] v: Still buffering (buffer went from 21% -> 27%) [0.277333s]. 2018-11-14 09:47:47.753 [cplayer] v: Still buffering (buffer went from 27% -> 96%) [0.960000s]. 2018-11-14 09:47:47.774 event: unpause 2018-11-14 09:47:47.777 [cplayer] v: End buffering (waited 0.309737 secs) [1.642667s]. 2018-11-14 09:47:47.791 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying 2018-11-14 09:47:51.769 event: unpause 2018-11-14 09:47:51.771 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-14 09:47:51.777 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-14 09:47:52.148 event: unpause 2018-11-14 09:47:52.151 [cplayer] v: End buffering (waited 0.376653 secs) [2.773333s]. 2018-11-14 09:47:52.158 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying 2018-11-14 09:47:55.290 event: unpause 2018-11-14 09:47:55.293 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-14 09:47:55.299 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-14 09:47:55.495 [cplayer] v: Still buffering (buffer went from 0% -> 4%) [0.042667s]. 2018-11-14 09:47:55.500 [cplayer] v: Still buffering (buffer went from 4% -> 2%) [0.021333s]. 2018-11-14 09:47:55.509 [cplayer] v: Still buffering (buffer went from 2% -> 27%) [0.277333s]. 2018-11-14 09:47:55.512 [cplayer] v: Still buffering (buffer went from 27% -> 32%) [0.320000s]. 2018-11-14 09:47:55.517 event: unpause 2018-11-14 09:47:55.522 [cplayer] v: End buffering (waited 0.238740 secs) [1.088000s]. 2018-11-14 09:47:55.527 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying 2018-11-14 09:50:04.260 [ffmpeg/audio] error: aac: Number of bands (43) exceeds limit (40). 2018-11-14 09:50:04.265 [ad] error: Error decoding audio. 2018-11-14 09:50:04.268 event: unpause 2018-11-14 09:50:04.271 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-14 09:50:04.274 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-14 09:50:06.774 event: unpause 2018-11-14 09:50:06.779 [cplayer] v: End buffering (waited 2.496504 secs) [-1.000000s]. 2018-11-14 09:50:06.782 [ffmpeg/audio] error: aac: Prediction is not allowed in AAC-LC. 2018-11-14 09:50:06.795 [ad] error: Error decoding audio. 2018-11-14 09:50:06.807 event: unpause 2018-11-14 09:50:06.812 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-14 09:50:06.836 event: unpause 2018-11-14 09:50:06.840 [cplayer] v: End buffering (waited 0.029817 secs) [4.842667s]. 2018-11-14 09:50:06.848 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying 2018-11-14 09:50:07.637 [cplayer] warn: Invalid video timestamp: 3452.296078 -> 3401.753178 (-50.542900 > 5.000000) 2018-11-14 09:50:07.646 [cplayer] warn: 2018-11-14 09:50:07.649 [cplayer] warn: Audio/Video desynchronisation detected! Possible reasons include too slow 2018-11-14 09:50:07.652 [cplayer] warn: hardware, temporary CPU spikes, broken drivers, and broken files. Audio 2018-11-14 09:50:07.655 [cplayer] warn: position will not match to the video (see A-V status field). 2018-11-14 09:50:07.659 [cplayer] warn:

I've read in the SD forums that this might be their issue. And, of that's the case, then ultimately I'd expect them to fix the root cause. However, in the interest of user experience can Channels provide some additional buffering to make the effect? It does seem that if you pause a stream for a second or two that the issue no longer happens.

Thanks as always for your fantastic support!

#2

@tmm1

I posted about this issue over on the SD forums and Nick responded back that perhaps this is a rate adaption issue in the Channels app. I have no idea either way but it is a bit annoying.

Here's a link to the post:

https://forum.silicondust.com/forum/viewtopic.php?f=129&t=70221&p=333244#p333244

1 Like
#3

Is this something that usually happens once after starting a stream, or multiple times while watching?

FYI I'm moving next month to a location with DRM-only, and will be retiring my PRIME in favor of HDHR Premium TV. That will give me a chance to stress test premium tv playback in my own living room and hopefully solve a lot of these issues.

#4

It generally happens more than once and more often within the first 5 minutes or so of a stream. It can and does happen later in a stream as well. Overall, it is somewhat random.

Turning on Match Frame rate on the ATV seems to help but not eliminate the problem.

Pausing for a second or two also seems to more or less eliminate it.

I have checked the server logs but don't find any errors there at all. The only indication of the issue is in the client logs that I attached.

I am happy to try betas etc if it will help.

Thanks!

#5

Sent you a beta to try.

#6

Testing with the beta looks good so far. Let me run it a day or so. Curious, what did you change? Overall, performance apppears the same just no pauses.

Thanks!

#7

Increased initial buffer from 1s to 1.5s

#8

Almost as soon as I hit enter on that reply I saw two short pauses. Overall, though it seems much better.

Here's a snippet of the log:

2018-11-18 18:36:51.718 event: unpause 2018-11-18 18:36:51.722 [cplayer] v: End buffering (waited 2.398583 secs) [1.749333s]. 2018-11-18 18:36:51.788 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStatePlaying 2018-11-18 18:44:41.781 event: unpause 2018-11-18 18:44:41.785 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-18 18:44:41.790 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-18 18:44:42.057 event: unpause 2018-11-18 18:44:42.060 [cplayer] v: End buffering (waited 0.254727 secs) [2.218667s]. 2018-11-18 18:44:42.068 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying 2018-11-18 18:44:49.998 event: unpause 2018-11-18 18:44:50.002 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-18 18:44:50.006 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-18 18:44:50.111 [cplayer] v: Still buffering (buffer went from 0% -> 4%) [0.021333s]. 2018-11-18 18:44:50.114 [cplayer] v: Still buffering (buffer went from 4% -> 0%) [0.000000s]. 2018-11-18 18:44:50.121 [cplayer] v: Still buffering (buffer went from 0% -> 46%) [0.234667s]. 2018-11-18 18:44:50.126 [cplayer] v: Still buffering (buffer went from 46% -> 51%) [0.256000s]. 2018-11-18 18:44:50.141 event: unpause 2018-11-18 18:44:50.146 [cplayer] v: End buffering (waited 0.134863 secs) [1.194667s]. 2018-11-18 18:44:50.152 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying 2018-11-18 18:46:15.011 [cplayer] v: Set property: pause=false -> 1 2018-11-18 18:46:15.016 read got (9) Bad file descriptor 2018-11-18 18:46:15.019 [cplayer] v: EOF code: 4 2018-11-18 18:46:15.022 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateStopped 2018-11-18 18:46:15.028 streamer stopping after 136100 packets and 1 timeouts (10456 waits) 2018-11-18 18:46:15.034 Guide Loaded: { Filter = "All Channels";

#9

Testing now with 2s buffer. i'll let you know how it goes.

#10

Got a pause almost immediately with this latest build.

2018-11-18 19:12:12.372 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-18 19:12:12.376 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-18 19:12:12.934 [cplayer] v: Still buffering (buffer went from 0% -> 2%) [0.021333s]. 2018-11-18 19:12:12.938 [cplayer] v: Still buffering (buffer went from 2% -> 22%) [0.170667s]. 2018-11-18 19:12:12.941 [cplayer] v: Still buffering (buffer went from 22% -> 48%) [0.362667s]

Just a thought,,,

Some of these pauses are so short that they'd likely be unnoticed if it weren't for the progress window popping up. Maybe blocking that from showing so quickly would help?

#11

2s is much better, but still seeing the pauses occasionally.

2018-11-18 19:43:04.954 event: unpause 2018-11-18 19:43:04.957 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-18 19:43:04.961 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-18 19:43:05.548 event: unpause 2018-11-18 19:43:05.552 [cplayer] v: End buffering (waited 0.583361 secs) [3.776000s]. 2018-11-18 19:43:05.566 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying 2018-11-18 19:45:56.096 [ffmpeg/audio] error: aac: Number of bands (60) exceeds limit (40). 2018-11-18 19:45:56.098 [ad] error: Error decoding audio. 2018-11-18 19:45:56.101 [ffmpeg/audio] error: aac: Reserved bit set. 2018-11-18 19:45:56.103 [ffmpeg/audio] error: aac: Prediction is not allowed in AAC-LC. 2018-11-18 19:45:56.105 [ad] error: Error decoding audio. 2018-11-18 19:45:56.107 [ad] warn: Invalid audio PTS: 3029.159733 -> 3032.690400 2018-11-18 19:45:56.127 [cplayer] warn: 2018-11-18 19:45:56.131 [cplayer] warn: Audio/Video desynchronisation detected! Possible reasons include too slow 2018-11-18 19:45:56.135 [cplayer] warn: hardware, temporary CPU spikes, broken drivers, and broken files. Audio 2018-11-18 19:45:56.139 [cplayer] warn: position will not match to the video (see A-V status field). 2018-11-18 19:45:56.142 [cplayer] warn: 2018-11-18 19:46:48.444 [ad] warn: Invalid audio PTS: 3085.202400 -> 3087.143733 2018-11-18 19:46:49.352 [ad] warn: Invalid audio PTS: 3088.039733 -> 3088.423733 2018-11-18 19:46:56.261 event: unpause 2018-11-18 19:46:56.264 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-18 19:46:56.269 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-18 19:46:56.752 [cplayer] v: Still buffering (buffer went from 0% -> 2%) [0.021333s]. 2018-11-18 19:46:56.754 [cplayer] v: Still buffering (buffer went from 2% -> 5%) [0.042667s]. 2018-11-18 19:46:56.758 [cplayer] v: Still buffering (buffer went from 5% -> 25%) [0.192000s]. 2018-11-18 19:46:56.762 [cplayer] v: Still buffering (buffer went from 25% -> 28%) [0.213333s]. 2018-11-18 19:46:56.766 [cplayer] v: Still buffering (buffer went from 28% -> 39%) [0.298667s]. 2018-11-18 19:46:56.770 [cplayer] v: Still buffering (buffer went from 39% -> 59%) [0.448000s]. 2018-11-18 19:46:57.413 event: unpause 2018-11-18 19:46:57.419 [cplayer] v: End buffering (waited 1.137247 secs) [0.938667s]. 2018-11-18 19:46:57.447 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying 2018-11-18 19:47:03.217 event: unpause 2018-11-18 19:47:03.221 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-18 19:47:03.223 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-18 19:47:04.968 [cplayer] v: Still buffering (buffer went from 0% -> 2%) [0.021333s]. 2018-11-18 19:47:04.969 [cplayer] v: Still buffering (buffer went from 2% -> 8%) [0.064000s]. 2018-11-18 19:47:04.974 [cplayer] v: Still buffering (buffer went from 8% -> 28%) [0.213333s]. 2018-11-18 19:47:04.979 [cplayer] v: Still buffering (buffer went from 28% -> 48%) [0.362667s]. 2018-11-18 19:47:04.984 [cplayer] v: Still buffering (buffer went from 48% -> 54%) [0.405333s]. 2018-11-18 19:47:05.669 event: unpause 2018-11-18 19:47:05.676 [cplayer] v: End buffering (waited 2.273969 secs) [0.810667s]. 2018-11-18 19:47:05.714 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying 2018-11-18 19:47:20.651 [ffmpeg/audio] error: aac: Number of bands (53) exceeds limit (40). 2018-11-18 19:47:20.654 [ad] error: Error decoding audio. 2018-11-18 19:47:20.659 [ffmpeg/audio] error: aac: TNS filter order 18 is greater than maximum 12. 2018-11-18 19:47:20.663 [ad] error: Error decoding audio. 2018-11-18 19:47:20.668 [ad] warn: Invalid audio PTS: 3116.253067 -> 3120.029067 2018-11-18 19:47:20.732 event: unpause 2018-11-18 19:47:20.736 [cplayer] v: Enter buffering (buffer went from 100% -> 0%) [0.000000s]. 2018-11-18 19:47:20.740 Updating playState from LTVideoPlayerPlayStatePlaying to LTVideoPlayerPlayStateBuffering 2018-11-18 19:47:22.565 event: unpause 2018-11-18 19:47:22.570 [cplayer] v: End buffering (waited 1.805694 secs) [0.810667s]. 2018-11-18 19:47:22.602 Updating playState from LTVideoPlayerPlayStateBuffering to LTVideoPlayerPlayStatePlaying

#12

I am also seeing this. Relatively new to th SD Premium TV service and it was flawless with the Channels ATV App at first, but within the last day or so I am seeing these pauses.

#13

The recent issues are on the PTV side: https://forum.silicondust.com/forum/viewtopic.php?f=129&t=70237&p=333416#p333416

#14

Yes, the problems people have reported over the last couple of days are different then what I have reported. My issue is persistent since the inception of PTV.

#15

Yeah, this has been a constant issue for me too. I have just gotten used to pausing the live stream for like 5 seconds every time I change channels. This is such a habit now that I'm sure I will continue to do this even after this issue is finally fixed. haha :slight_smile:

#16

There is a beta for the ATV (11.18.2351) that improves the situation quite a bit. It adds some buffering at the start of the stream automatically - 2s worth. You might try it out.

#17

I too have the issues being discussed in this thread and have had them since PTV was introduced. How can I obtain and install the ATV beta (11.18.2351) mentioned. I use the Channels DVR (3.2.10) client not the Channels client?

#18

There were some improvements rolled out to the Premium TV streams today, and these micro paused should no longer happen. Let me know if there are any more problems.

#19

@tmm1

Thanks for the update. I changed jobs recently and work from home now so I've had the TV running in the background all day today. I did see 1 or 2 micro pauses over the past 6 hours or so but that's nothing compared to the half dozen or so per hour that I used to see. BTW, that's using the released client, 3.2.10, not the beta.

On the whole, a huge improvement!

Now, if they (SD) can just get the contract issues resolved with Hallmark and Discovery life will be grand!

1 Like
#20

I have been getting these pauses a lot. Today has been really bad. I surely didn’t see any improvement.