[mythtv-users] Odd playback behavior since 0.26

Fri Dec 7 20:54:41 UTC 2012

On 07/12/12 16:26, 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.
> _______________________________________________
> mythtv-users mailing list
> mythtv-users at mythtv.org
> http://www.mythtv.org/mailman/listinfo/mythtv-users
I get this problem or similar about once every couple of days during 
H264 playback in the UK. It is exactly as you describe, create a 
bookmark and try again always works. It has never re-occurred for me 
while a record is actually playing.
When playback is started one of three problems can occur :-
The judder as you describe it.
No sound.
Frontend crash.
  I cannot reproduce any of these problems at will. I did some testing 
today of 50 playback initiations without a single fault. I am guessing 
that something is not being initialised consistently. Which vdpau 
playback profile are you using - mine is VDPAU High Quality?
I thought the issue might be related to corrupted data at the start of a 
stream but the fault is not linked to a specific recording.
When I can re-produce any of the above consistently I will file a bug.
I note that master has had a couple of h264 and audio stream selection 
bug fixes and am building up courage to test it. But without a 
reproducible fault it is pretty pointless:-( .