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

Thu Apr 7 15:45:56 UTC 2011

On 04/04/2011 12:13 PM, Josh Norell wrote:
> 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.
>
>
> _______________________________________________
> mythtv-users mailing list
> mythtv-users at mythtv.org
> http://www.mythtv.org/mailman/listinfo/mythtv-users
>    

Anyone have any ideas on this?
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://www.mythtv.org/pipermail/mythtv-users/attachments/20110407/42267f2f/attachment-0001.html