[mythtv-users] Odd playback behavior since 0.26

[Dan Wilga]

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.