[mythtv-users] Odd playback behavior since 0.26

Sat Dec 8 04:57:18 UTC 2012

On 07/12/2012 11:26 AM, Dan Wilga wrote:
> Since upgrading to 0.26, I've been experiencing an occasional problem 
> with HD-PVR recordings. Following a brief bit of what looks like 
> corruption in the video, video playback starts to oscillate between 
> two portions of the video stream. One portion is a fraction of a 
> second behind the other. So if you think of the video stream as a 
> series of 1/2 second chunks like this:
>
> ABCDEFGH
>
> it seems to show chunks in the order ACBDCEDFEGFH. This all happens 
> very quickly. Needless to say, WAF is suffering.
>
> Audio is unaffected. If I stop playback, save bookmark, and resume, 
> it's fine until the next corruption. Has anyone else experienced this?
>
> This is the log, from around the time of a hiccup (hostname and 
> process name removed to conserve space):
>
> 22:11:44 I CoreContext tv_play.cpp:2155 (HandleStateChange) TV: 
> Attempting to change from None to WatchingPreRecorded
> 22:11:44 I CoreContext mythcorecontext.cpp:1191 (CheckProtoVersion) 
> Using protocol version 75
> 22:11:44 I CoreContext mythcorecontext.cpp:1191 (CheckProtoVersion) 
> Using protocol version 75
> 22:11:45 N CoreContext audioplayer.cpp:167 (ReinitAudio) AudioPlayer: 
> Enabling Audio
> 22:11:45 I CoreContext avformatdecoder.cpp:2141 (ScanStreams) AFD: 
> Opened codec 0x4fc3900, id(H264) type(Video)
> 22:11:45 I CoreContext avformatdecoder.cpp:1999 (ScanStreams) AFD: 
> codec AC3 has 2 channels
> 22:11:45 I CoreContext avformatdecoder.cpp:2141 (ScanStreams) AFD: 
> Opened codec 0x74d4c80, id(AC3) type(Audio)
> 22:11:45 I CoreContext audio/audiooutputbase.cpp:791 (Reconfigure) AO: 
> Opening audio device 'iec958:CARD=SB,DEV=0' ch 2(2) sr 48000 sf signed 
> 16 bit reenc 1
> 22:11:45 I CoreContext mythpainter_ogl.cpp:62 (ClearCache) Clearing 
> OpenGL painter cache.
> 22:11:46 I CoreContext mythrender_vdpau.cpp:1682 
> (CreatePresentationSurfaces) VDPAU: Created 2 output surfaces.
> 22:11:46 I CoreContext mythrender_vdpau.cpp:402 (Create) VDPAU: 
> Created VDPAU render device 1920x1080
> 22:11:46 N CoreContext mythplayer.cpp:520 (CheckExtraAudioDecode) 
> Player(1): Forcing decode extra audio option on (Video method requires 
> it).
> 22:11:46 I Decoder mythpainter_vdpau.cpp:108 (ClearCache) VDPAU 
> Painter: Clearing VDPAU painter cache.
> 22:11:46 I Decoder mythpainter_ogl.cpp:62 (ClearCache) Clearing OpenGL 
> painter cache.
> 22:11:46 I Decoder mythrender_vdpau.cpp:1682 
> (CreatePresentationSurfaces) VDPAU: Created 2 output surfaces.
> 22:11:46 I Decoder mythrender_vdpau.cpp:402 (Create) VDPAU: Created 
> VDPAU render device 1920x1080
> 22:11:46 N Decoder mythplayer.cpp:520 (CheckExtraAudioDecode) 
> Player(1): Forcing decode extra audio option on (Video method requires 
> it).
> 22:11:46 I Decoder videoout_vdpau.cpp:628 (DrawSlice) VidOutVDPAU: 
> Added 2 new buffers. New buffer size 16 (4 decode and 12 process)
> 22:11:48 I CoreContext mythplayer.cpp:1754 (InitAVSync) Player(1): 
> Video timing method: RTC
> 22:11:48 I CoreContext tv_play.cpp:5240 (StartPlayer) TV: Created player.
> 22:11:48 I CoreContext tv_play.cpp:2394 (HandleStateChange) TV: 
> Changing from None to WatchingPreRecorded
> 22:11:48 I CoreContext tv_play.cpp:2485 (HandleStateChange) TV: Main 
> UI disabled.
> 22:11:48 I CoreContext tv_play.cpp:403 (StartTV) TV: Entering main 
> playback loop.
> 22:11:48 I CoreContext mythrender_vdpau.cpp:588 (CheckOutputSurfaces) 
> VDPAU: Added 2 output surfaces (total 4, max 4)
> [big gap while we watch the show for a while]
> 22:23:53 I Decoder avformatdecoder.cpp:4285 (ProcessAudioPacket) AFD: 
> Audio stream changed
> 22:23:53 I Decoder audio/audiooutputbase.cpp:791 (Reconfigure) AO: 
> Opening audio device 'iec958:CARD=SB,DEV=0' ch 2(6) sr 48000 sf signed 
> 16 bit reenc 0
> 22:23:53 W Decoder avformatdecoder.cpp:4460 (GetFrame) AFD: Audio 
> 1842930 ms behind video but already 220 video frames queued. AV-Sync 
> might be broken.
> 22:23:53 W Decoder avformatdecoder.cpp:4460 (GetFrame) AFD: Audio 
> 1842931 ms behind video but already 220 video frames queued. AV-Sync 
> might be broken.
> 22:23:53 W Decoder avformatdecoder.cpp:4460 (GetFrame) AFD: Audio 
> 1842932 ms behind video but already 220 video frames queued. AV-Sync 
> might be broken.
> 22:23:54 E Decoder videobuffers.cpp:283 (GetNextFreeFrame) 
> GetNextFreeFrame() unable to lock frame 100 times. Discarding Frames.
> 22:23:55 E Decoder videobuffers.cpp:283 (GetNextFreeFrame) 
> GetNextFreeFrame() unable to lock frame 100 times. Discarding Frames.
> 22:23:56 E Decoder videobuffers.cpp:283 (GetNextFreeFrame) 
> GetNextFreeFrame() unable to lock frame 100 times. Discarding Frames.
> 22:23:57 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 1747ms for video buffers ALLLLLLLLLLLLLLf
> 22:23:57 N CoreContext mythplayer.cpp:2110 (PrebufferEnoughFrames) 
> Player(1): Timed out waiting for frames, and#012#011#011#011there are 
> not enough free frames. Discarding buffered frames.
> 22:23:58 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 103ms for video buffers AAAALAAAAALLLLAL
> 22:23:58 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 204ms for video buffers ALLALLLLALLLLLAL
> 22:23:58 E Decoder videobuffers.cpp:283 (GetNextFreeFrame) 
> GetNextFreeFrame() unable to lock frame 100 times. Discarding Frames.
> 22:23:58 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 307ms for video buffers AAAALAAAAAAAAAAA
> 22:23:58 E Decoder videobuffers.cpp:283 (GetNextFreeFrame) 
> GetNextFreeFrame() unable to lock frame 100 times. Discarding Frames.
> 22:23:59 E Decoder videobuffers.cpp:283 (GetNextFreeFrame) 
> GetNextFreeFrame() unable to lock frame 100 times. Discarding Frames.
> 22:24:01 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 1813ms for video buffers LLALLfLLLLLLLLLL
> 22:24:01 N CoreContext mythplayer.cpp:2110 (PrebufferEnoughFrames) 
> Player(1): Timed out waiting for frames, and#012#011#011#011there are 
> not enough free frames. Discarding buffered frames.
> 22:24:07 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 102ms for video buffers ALLLLLDLDLLLdLLL
> 22:24:07 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 204ms for video buffers ALLLLLDLDLLLdLLL
> 22:24:07 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 306ms for video buffers ALLLLLDLDLLLdLLL
> 22:24:07 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 408ms for video buffers ALLLLLDLDLLLdLLL
> 22:24:07 N CoreContext mythplayer.cpp:2110 (PrebufferEnoughFrames) 
> Player(1): Timed out waiting for frames, and#012#011#011#011there are 
> not enough free frames. Discarding buffered frames.
> 22:24:11 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 101ms for video buffers ALLLLdLLLLLDDLLL
> 22:24:11 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 203ms for video buffers ALLLLdLLLLLDDLLL
> 22:24:11 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 305ms for video buffers ALLLLdLLLLLDDLLL
> 22:24:11 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 407ms for video buffers ALLLLdLLLLLDDLLL
> 22:24:11 N CoreContext mythplayer.cpp:2110 (PrebufferEnoughFrames) 
> Player(1): Timed out waiting for frames, and#012#011#011#011there are 
> not enough free frames. Discarding buffered frames.
> 22:24:11 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 509ms for video buffers LAAAAAL(AU)AAADDAAA
> 22:24:16 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 102ms for video buffers LALLLLLLLLLLDdLD
> 22:24:16 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 204ms for video buffers LALLLLLLLLLLDdLD
> 22:24:16 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 307ms for video buffers LALLLLLLLLLLDdLD
> 22:24:17 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 408ms for video buffers LALLLLLLLLLLDdLD
> 22:24:17 N CoreContext mythplayer.cpp:2110 (PrebufferEnoughFrames) 
> Player(1): Timed out waiting for frames, and#012#011#011#011there are 
> not enough free frames. Discarding buffered frames.
> 22:24:19 E Decoder videobuffers.cpp:283 (GetNextFreeFrame) 
> GetNextFreeFrame() unable to lock frame 100 times. Discarding Frames.
> 22:24:20 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 105ms for video buffers AAALLAALLLALLAAA
> 22:24:20 N CoreContext mythplayer.cpp:2095 (PrebufferEnoughFrames) 
> Player(1): Waited 208ms for video buffers LLALLLALLLLLLLLA
> 22:24:20 E Decoder videobuffers.cpp:283 (GetNextFreeFrame) 
> GetNextFreeFrame() unable to lock frame 100 times. Discarding Frames.
I've been seeing something similar, except not only with corrupted 
segments in the recordings ( which I seem to get very rarely) but also 
on occasion watching livetv, it will *sometimes happen at program 
transitions.

FWIW: 3x HDPVR (different hardware revisions, all the same firmware), 
both with 0.26 and master. I've tried VDPAU Slim, Normal and HQ but 
haven't noticed any significant difference in what is triggering it.  My 
wife found that if it happens in livetv, she can just hit 'guide' and 
then immediately 'ok'.  For the odd recording which is messed up, 
generally the bookmark option works to get around the bad segment.