[mythtv-users] Failed to initialize A/V Sync

Mon Apr 4 18:13:05 UTC 2011

I've got a problem with changing channels in live tv often crashes the 
playback. The frontend exits to the menu with "failed to initialize A/V 
sync" It's not every time, but it can be quite frequent depending on the 
channel. It seems to be much worse when tuning to an h.264 channel. I've 
had this problem from .22 up to the current dev version. It's on an ION 
330 running vdpau. Any help please? Here's the frontend logs from when I 
changed the channel. I pruned out most of the duplicate h264 errors. Thanks

2011-04-04 10:38:42.593 TV: ChangeChannel(0, '441')
2011-04-04 10:38:42.615 TV: PauseLiveTV() player ctx 0
2011-04-04 10:38:44.119 TV: UnpauseLiveTV() player ctx 0
2011-04-04 10:38:44.123 LiveTVChain(live-mythiptv-2011-04-04T10:38:14): ReloadAll(): Added new recording
2011-04-04 10:38:44.132 LiveTVChain(live-mythiptv-2011-04-04T10:38:14): SwitchTo(-1)
2011-04-04 10:38:44.132 LiveTVChain(live-mythiptv-2011-04-04T10:38:14): Entry at 2: '2441_20110404103842'
2011-04-04 10:38:44.132 Player(0): Play(  1.0, normal 1, unpause audio 0)
2011-04-04 10:38:44.137 Player(0): JumpToProgram - start
2011-04-04 10:38:44.149 FilterManager: GetFilterInfo(convert) returning: 0x0
2011-04-04 10:38:44.149 Player(0): LoadFilters('vdpaucolorspace=auto'..) ->  0x0
2011-04-04 10:38:44.154 Player(0): Play speed: rate: 29.97 speed: 0 skip: 0 =>  new interval 33366
2011-04-04 10:38:44.172 Player(0): ClearAfterSeek(1)
2011-04-04 10:38:44.172 VidOutVDPAU: ClearAfterSeek()
2011-04-04 10:38:44.172 VidOutVDPAU: DiscardFrames(0)
2011-04-04 10:38:44.172 VideoBuffers::DiscardFrames(0): UAUUUUAUUUUUUUUUU
2011-04-04 10:38:44.173 VideoBuffers::DiscardFrames(0): AAAAAAAAAAAAAAAAA -- done
2011-04-04 10:38:44.174 VidOutVDPAU: DiscardFrames() 3: AAAAAAAAAAAAAAAAA -- done()
2011-04-04 10:38:44.174 Dec: Reset: Video 1, Seek 1, File 1
2011-04-04 10:38:44.441 LiveTVChain(live-mythiptv-2011-04-04T10:38:14): ReloadAll(): Added new recording
2011-04-04 10:38:44.444 LiveTVChain(live-mythiptv-2011-04-04T10:38:14): SwitchTo(3)
2011-04-04 10:38:44.445 LiveTVChain(live-mythiptv-2011-04-04T10:38:14): Entry at 3: '2441_20110404103844'
2011-04-04 10:38:44.445 Player(0): JumpToProgram - start
2011-04-04 10:38:44.457 FilterManager: GetFilterInfo(convert) returning: 0x0
2011-04-04 10:38:44.457 Player(0): LoadFilters('vdpaucolorspace=auto'..) ->  0x0
2011-04-04 10:38:44.458 Player(0): Play speed: rate: 29.97 speed: 0 skip: 0 =>  new interval 33366
2011-04-04 10:38:44.465 FileRingBuf(/var/video/2433_20110404103817.mpg): OpenFile(/var/video/2441_20110404103844.mpg, 10000 ms)
2011-04-04 10:38:45.402 RingBuf(/var/video/2441_20110404103844.mpg) Warning: Not starting read ahead thread, already running
2011-04-04 10:38:45.526 Player(0): Forcing decode extra audio option on (Video method requires it).
2011-04-04 10:38:45.982 AFD: Buffer size: 32768, streamed 1
2011-04-04 10:38:46.233 RingBuf(/var/video/2441_20110404103844.mpg): Waited 0.2 seconds for data
2011-04-04 10:38:46.483 RingBuf(/var/video/2441_20110404103844.mpg): Waited 0.5 seconds for data
2011-04-04 10:38:46.984 RingBuf(/var/video/2441_20110404103844.mpg): Waited 1.0 seconds for data
2011-04-04 10:38:47.984 RingBuf(/var/video/2441_20110404103844.mpg): Waited 2.0 seconds for data
2011-04-04 10:38:49.941 [h264 @ 0x7fddf8079ea0]non-existing PPS referenced
2011-04-04 10:38:49.942 [h264 @ 0x7fddf8079ea0]non-existing PPS 0 referenced
2011-04-04 10:38:49.942 [h264 @ 0x7fddf8079ea0]decode_slice_header error
2011-04-04 10:38:49.943 [h264 @ 0x7fddf8079ea0]no frame!
2011-04-04 10:38:49.943 [h264 @ 0x7fddf8079ea0]non-existing PPS referenced
2011-04-04 10:38:49.945 [h264 @ 0x7fddf8079ea0]non-existing PPS 0 referenced
2011-04-04 10:38:49.945 [h264 @ 0x7fddf8079ea0]decode_slice_header error
2011-04-04 10:38:49.945 [h264 @ 0x7fddf8079ea0]no frame!
2011-04-04 10:38:49.991 [h264 @ 0x7fddf8079ea0]non-existing PPS referenced
2011-04-04 10:38:49.992 [h264 @ 0x7fddf8079ea0]non-existing PPS 0 referenced
2011-04-04 10:38:49.992 [h264 @ 0x7fddf8079ea0]decode_slice_header error
2011-04-04 10:38:49.993 [h264 @ 0x7fddf8079ea0]no frame!
2011-04-04 10:38:50.060 [h264 @ 0x7fddf8079ea0]non-existing PPS referenced
2011-04-04 10:38:50.061 [h264 @ 0x7fddf8079ea0]non-existing PPS 0 referenced
2011-04-04 10:38:50.061 [h264 @ 0x7fddf8079ea0]decode_slice_header error
2011-04-04 10:38:50.062 [h264 @ 0x7fddf8079ea0]no frame!
2011-04-04 10:38:50.065 [h264 @ 0x7fddf8079ea0]non-existing PPS referenced
2011-04-04 10:38:50.066 [h264 @ 0x7fddf8079ea0]non-existing PPS 0 referenced
2011-04-04 10:38:50.066 [h264 @ 0x7fddf8079ea0]decode_slice_header error
2011-04-04 10:38:50.066 [h264 @ 0x7fddf8079ea0]no frame!
2011-04-04 10:38:50.366 [h264 @ 0x7fddf8079ea0]mmco: unref short failure
2011-04-04 10:38:50.366 [h264 @ 0x7fddf8079ea0]mmco: unref short failure
2011-04-04 10:38:50.370 AFD: Stream #0, has id 0x6e codec id H264, type Video, bitrate 0 at 0x344e660
2011-04-04 10:38:50.376 VDP: Accepting: cmp(>= 0 720) dec(vdpau) cpus(2) skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(disabled) deint(vdpauonefield,none) filt(vdpaucolorspace=auto)
2011-04-04 10:38:50.377 VDP: Accepting: cmp(>  0 0) dec(vdpau) cpus(2) skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(disabled) deint(vdpauonefield,vdpauadvanced) filt(vdpaucolorspace=auto)
2011-04-04 10:38:50.377 VDP: Accepting: cmp(>= 0 0) dec(ffmpeg) cpus(0) skiploop(enabled) rend(opengl) osd(opengl2) osdfade(disabled) deint(bobdeint,none) filt()
2011-04-04 10:38:50.377 VDP: LoadBestPreferences(2048x2048, 0)
2011-04-04 10:38:50.378 VDP: LoadBestPreferences(2048x2048, 60)
2011-04-04 10:38:50.378 VDP: LoadBestPreferences(1920x1080, 60)
2011-04-04 10:38:50.387 VDP: Accepting: cmp(>= 0 720) dec(vdpau) cpus(2) skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(disabled) deint(vdpauonefield,none) filt(vdpaucolorspace=auto)
2011-04-04 10:38:50.388 VDP: Accepting: cmp(>  0 0) dec(vdpau) cpus(2) skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(disabled) deint(vdpauonefield,vdpauadvanced) filt(vdpaucolorspace=auto)
2011-04-04 10:38:50.388 VDP: Accepting: cmp(>= 0 0) dec(ffmpeg) cpus(0) skiploop(enabled) rend(opengl) osd(opengl2) osdfade(disabled) deint(bobdeint,none) filt()
2011-04-04 10:38:50.389 VDP: LoadBestPreferences(2048x2048, 0)
2011-04-04 10:38:50.389 VDP: LoadBestPreferences(2048x2048, 60)
2011-04-04 10:38:50.389 VDP: LoadBestPreferences(1920x1080, 60)
2011-04-04 10:38:50.390 AFD: Using 1 CPUs for decoding
2011-04-04 10:38:50.390 AFD: InitVideoCodec() 0x3431650 id(H264) type (Video).
2011-04-04 10:38:50.390 AFD: Selected FPS is 29.97 (avg 0 stream 29.97 container 90000 estimated 59.9401)
2011-04-04 10:38:50.391 AFD: Using vdpau for video decoding
2011-04-04 10:38:50.391 AFD: Looking for decoder for H264
2011-04-04 10:38:50.392 AFD: Opened codec 0x3431650, id(H264) type(Video)
2011-04-04 10:38:50.392 AFD: Stream #1, has id 0x64 codec id AC3, type Audio, bitrate 448000 at 0x2b12c00
2011-04-04 10:38:50.392 AFD: codec AC3 has 6 channels
2011-04-04 10:38:50.392 AFD: Looking for decoder for AC3
2011-04-04 10:38:50.394 AFD: Opened codec 0x35a0aa0, id(AC3) type(Audio)
2011-04-04 10:38:50.394 AFD: Stream #2, has id 0xab codec id MP2, type Audio, bitrate 192000 at 0x3455d00
2011-04-04 10:38:50.395 AFD: codec MP2 has 2 channels
2011-04-04 10:38:50.395 AFD: Looking for decoder for MP2
2011-04-04 10:38:50.395 AFD: Opened codec 0x3084730, id(MP2) type(Audio)
2011-04-04 10:38:50.396 Dec: Selected track #1 in the Unknown language(0)
2011-04-04 10:38:50.396 Dec: Resyncing position map. posmapStarted = 0 livetv(1) watchingRec(0)
2011-04-04 10:38:50.399 Dec: Position map filled from DB to: 32
2011-04-04 10:38:50.399 Dec: SyncPositionMap watchingrecording, from DB: 2 entries
2011-04-04 10:38:50.399 Player(0): Filling position map from 33 to end
2011-04-04 10:38:50.403 Dec: Position map filled from Encoder to: 62
2011-04-04 10:38:50.403 Dec: SyncPositionMap watchingrecording total: 3 entries
2011-04-04 10:38:50.403 Dec: SyncPositionMap, new totframes: 62, new length: 2, posMap size: 3
2011-04-04 10:38:50.407 AFD: Partial position map found
2011-04-04 10:38:50.407 AFD: Successfully opened decoder for file: "/var/video/2441_20110404103844.mpg". novideo(0)
2011-04-04 10:38:50.429 AFD: Resetting byte context eof (livetv 1 was eof 0)
2011-04-04 10:38:50.629 Player(0): Play(  1.0, normal 1, unpause audio 1)
2011-04-04 10:38:50.629 Dec: Resyncing position map. posmapStarted = 0 livetv(1) watchingRec(1)
2011-04-04 10:38:50.743 Dec: Position map filled from DB to: 32
2011-04-04 10:38:50.743 Dec: SyncPositionMap watchingrecording, from DB: 2 entries
2011-04-04 10:38:50.744 Player(0): Filling position map from 33 to end
2011-04-04 10:38:50.746 Dec: Position map filled from Encoder to: 62
2011-04-04 10:38:50.746 Dec: SyncPositionMap watchingrecording total: 3 entries
2011-04-04 10:38:50.923 Player(0): Play speed: rate: 29.97 speed: 1 skip: 1 =>  new interval 33366
2011-04-04 10:38:50.923 Player(0): Stretch Factor 1, allow passthru
2011-04-04 10:38:50.923 Player(0): JumpToProgram - end
2011-04-04 10:38:50.924 Player(0): Waiting for video buffers...
2011-04-04 10:38:50.966 [h264_vdpau @ 0x7fddf8079ea0]mmco: unref short failure
2011-04-04 10:38:50.967 [h264_vdpau @ 0x7fddf8079ea0]mmco: unref short failure
2011-04-04 10:38:50.967 VidOutVDPAU Error: Picture format has changed.
2011-04-04 10:38:50.971 VidOutVDPAU Error: IsErrored() in DrawSlice
2011-04-04 10:38:50.975 VidOutVDPAU Error: IsErrored() in ProcessFrame
2011-04-04 10:38:50.975 Player(0), Error: AVSync: Unknown error in videoOutput, aborting playback.
2011-04-04 10:38:50.987 Player(0): Decoder thread exiting.
2011-04-04 10:38:51.180 TV: HandleStateChange(0) -- begin
2011-04-04 10:38:51.180 TV: Attempting to change from WatchingLiveTV to None
2011-04-04 10:38:51.180 TV: StopStuff() for player ctx 0 -- begin
2011-04-04 10:38:51.181 TV: SetActive(0,w/o OSD) 0 ->  0 -- begin
2011-04-04 10:38:51.181 TV: SetActive(0,w/o OSD) 0 ->  0 -- end
2011-04-04 10:38:51.181 Player(0): StopPlaying - begin
2011-04-04 10:38:51.181 Player(0): Exited decoder loop.
2011-04-04 10:38:51.196 VidOutVDPAU: DiscardFrames(1)
2011-04-04 10:38:51.196 VideoBuffers::DiscardFrames(1): AAAAAAALALLALAaAA
2011-04-04 10:38:51.197 VideoBuffers::DiscardFrames(): AAAAAAAAAAAAAAAAA -- done()
2011-04-04 10:38:51.197 VideoBuffers::DiscardFrames(1): AAAAAAAAAAAAAAAAA -- done
2011-04-04 10:38:51.197 VidOutVDPAU: DiscardFrames() 3: AAAAAAAAAAAAAAAAA -- done()
2011-04-04 10:38:51.428 VDPAU Painter: Clearing VDPAU painter cache.
2011-04-04 10:38:51.463 MythPainter: 19 images not yet de-allocated.
2011-04-04 10:38:51.659 Player(0): StopPlaying - end
2011-04-04 10:38:51.659 TV: StopStuff(): stopping ring buffer
2011-04-04 10:38:51.668 TV: StopStuff(): stopping player
2011-04-04 10:38:51.669 TV: StopStuff(): stopping recorder
2011-04-04 10:38:55.530 TV: StopStuff() -- end
2011-04-04 10:38:55.530 TV: Changing from WatchingLiveTV to None
2011-04-04 10:38:55.532 TV: HandleStateChange(0) -- end
2011-04-04 10:38:55.533 TV: Exiting main playback loop.
2011-04-04 10:38:55.538 TV: tv->LiveTV() -- begin
2011-04-04 10:38:55.550 TV: HandleStateChange(0) -- begin
2011-04-04 10:38:55.551 TV: Attempting to change from None to WatchingLiveTV
2011-04-04 10:38:55.551 MythCoreContext: Connecting to backend server: 127.0.0.1:6543 (try 1 of 1)
2011-04-04 10:38:55.556 Using protocol version 65
2011-04-04 10:38:55.563 IsTunable(2441)
2011-04-04 10:38:55.573 IsTunable(2441) ->  true
2011-04-04 10:38:55.581 TV: Spawning LiveTV Recorder -- begin
2011-04-04 10:38:55.820 TV: Spawning LiveTV Recorder -- end
2011-04-04 10:38:55.823 LiveTVChain(live-mythiptv-2011-04-04T10:38:55): ReloadAll(): Added new recording
2011-04-04 10:38:55.837 TV: playbackURL(/var/video/2441_20110404103855.mpg) cardtype(DUMMY)
2011-04-04 10:38:55.840 TV Error: LiveTV not successfully started
2011-04-04 10:38:55.841 TV: DrawUnusedRects() -- begin
2011-04-04 10:38:55.841 TV: DrawUnusedRects() -- end
2011-04-04 10:38:55.841 TV: Main UI disabled.
2011-04-04 10:38:55.842 TV: HandleStateChange(0) -- end
2011-04-04 10:38:55.842 TV: tv->LiveTV() -- end
2011-04-04 10:38:55.842 TV: Entering main playback loop.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://www.mythtv.org/pipermail/mythtv-users/attachments/20110404/7ff74ae8/attachment-0001.html 