[mythtv-commits] Ticket #10212: Transcoded recordings playback broken (stutters, audio failure) during November commits

MythTV noreply at mythtv.org
Sun Jan 8 13:46:49 UTC 2012


#10212: Transcoded recordings playback broken (stutters, audio failure) during
November commits
-------------------------------------+-----------------------------
 Reporter:  jk90090@…                |          Owner:  markk
     Type:  Bug Report - General     |         Status:  new
 Priority:  minor                    |      Milestone:  unknown
Component:  MythTV - Video Playback  |        Version:  Unspecified
 Severity:  medium                   |     Resolution:
 Keywords:  transcoded recordings    |  Ticket locked:  0
-------------------------------------+-----------------------------

Old description:

> Recently, and accidentally, I updated from mythtv-0.25_pre20111102 to
> mythtv-0.25_pre20111129, and now I'm having some serious buffering issues
> with TRANSCODED recordings.  Any recording that isn't transcoded is
> playing back perfectly (720p, 1080i both smooth as silk), and it's pretty
> much for all transcoded content, so simply newly transcoded recordings.
>
> I transcode by ticking the 'transcode' option for the recording schedule,
> either with Medium Quality or Low Quality
>
> The settings I use are:  (Advanced -> TV Settings -> Recording Profiles
> -> Transcoders -> ..)
>     Media Quality - Resize video while transcoding, 1280x720, MPEG4, 2200
> Bitrate, Max Qual 2, Min Qual 15, Max qual diff between frames 3, Scale
> bitrate for frame size, Enable High-quality encoding, Enable 4MV
> encoding; MP3 audio, 32000 sampling rate, qual 7, volume 90%
>     Low Quality - Resize video while transcoding, 960x540, MPEG4, 2200
> Bitrate, Max Qual 2, Min Qual 15, Max qual diff between frames 3, Scale
> bitrate for frame size, Enable High-quality encoding, Enable 4MV
> encoding; MP3 audio, 32000 sampling rate, qual 5, volume 90%
>
> I am using a Frontend with VPDAU high quality playback (and I have tried
> without using VPDAU with no different results), and CPU usage for the
> system is single digits generally when doing playback.  Dual Core i5 I
> think, 6 GB memory.
>
> Some log excerpts from playback:
>
> 2011-12-02 10:28:09.198258 N [5764/5764] CoreContext mythplayer.cpp:2090
> (PrebufferEnoughFrames) - Player(2): Waited 208ms for video buffers
> AAAAAffAAAAAAAAAAAAAAAAAAAAA
> 2011-12-02 10:28:09.247233 I [5764/22424] Decoder ringbuffer.cpp:1093
> (WaitForAvail) - RingBuf(myth://mythserver:6543/2041_20111201213000.nuv):
> Waited 0.2 seconds for data
>             to become available... 66599 < 83003
> 2011-12-02 10:28:09.255258 I [5764/22424] Decoder ringbuffer.cpp:1093
> (WaitForAvail) - RingBuf(myth://mythserver:6543/2041_20111201213000.nuv):
> Waited 0.2 seconds for data
>             to become available... 68647 < 83003
> 2011-12-02 10:28:09.263160 I [5764/22424] Decoder ringbuffer.cpp:1093
> (WaitForAvail) - RingBuf(myth://mythserver:6543/2041_20111201213000.nuv):
> Waited 0.2 seconds for data
>             to become available... 70695 < 83003
>
> On the backend, I am not getting any errors.
>
> I copied the nuv to an SMB share that I have mounted for Videos, went
> into videos, same bad results.  I renamed it to avi, and used mplayer for
> playback which worked flawlessly.  Next I copied the file to a frontend
> local directory, again same failure.  Basically the internal player is
> the one having the trouble, regardless of location.
>
> I pulled down the 1107 commit and after some DB trickery was able to get
> the frontend up, and entered into the Videos section, and playback of the
> NUV is back to normal.  IF I get more time, I'll try another commit in
> between 1107 and 1129 to narrow down further where the bug has been
> introduced.
>
> Help!
>
> Some debug excerpts:
>
> 2011-12-18 16:38:27.343942 D [16487/16841] RingBuffer ringbuffer.cpp:858
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1200128, 2048) -- begin
> 2011-12-18 16:38:27.343987 I [16487/16841] RingBuffer ringbuffer.cpp:879
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1200128, 2048) -> 2048, took 0 ms (1000Mbps)
> 2011-12-18 16:38:27.344000 D [16487/16841] RingBuffer ringbuffer.cpp:892
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
> requested   2K in read
> 2011-12-18 16:38:27.344007 D [16487/16841] RingBuffer ringbuffer.cpp:943
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
> ahead loop
> 2011-12-18 16:38:27.345563 I [16487/16843] Decoder
> audio/audiooutputbase.cpp:1095 (SetAudiotime) - AO: SetAudiotime
> atc=47752884 tc=47752985 f=4096 pfu=-4352 pfs=-512
> 2011-12-18 16:38:27.345799 I [16487/16843] Decoder
> audio/audiooutputbase.cpp:1331 (AddData) - AO: AddData frames=1152,
> bytes=4608, used=25729, free=3046271, timecode=47752985 needsupmix=1
> 2011-12-18 16:38:27.345818 D [16487/16843] Decoder freesurround.cpp:363
> (putFrames) - FreeSurround::putFrames 1152 #ch 2 used 1152 generated 0
> 2011-12-18 16:38:27.345832 I [16487/16843] Decoder
> audio/audiooutputbase.cpp:1095 (SetAudiotime) - AO: SetAudiotime
> atc=47752860 tc=47752985 f=0 pfu=-5504 pfs=-512
> 2011-12-18 16:38:27.345848 D [16487/16843] Decoder ringbuffer.cpp:1188
> (ReadPriv) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> ReadPriv(..12, normal) @1198721 -- begin
> 2011-12-18 16:38:27.345867 D [16487/16843] Decoder ringbuffer.cpp:1272
> (ReadPriv) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> ReadPriv(..12, normal) -- copying data
> 2011-12-18 16:38:27.345876 D [16487/16843] Decoder ringbuffer.cpp:1287
> (ReadPriv) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> ReadPriv(..12, normal) -- checksum 5687
> 2011-12-18 16:38:27.345890 D [16487/16843] Decoder ringbuffer.cpp:1188
> (ReadPriv) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> ReadPriv(..34077, normal) @1198733 -- begin
> 2011-12-18 16:38:27.352057 D [16487/16841] RingBuffer ringbuffer.cpp:858
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1202176, 2048) -- begin
> 2011-12-18 16:38:27.352068 I [16487/16487] CoreContext
> mythplayer.cpp:1824 (AVSync) - Player(1): AVSync show
> 2011-12-18 16:38:27.352118 I [16487/16841] RingBuffer ringbuffer.cpp:879
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1202176, 2048) -> 2048, took 0 ms (1000Mbps)
> 2011-12-18 16:38:27.352134 D [16487/16841] RingBuffer ringbuffer.cpp:892
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
> requested   2K in read
> 2011-12-18 16:38:27.352143 D [16487/16841] RingBuffer ringbuffer.cpp:943
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
> ahead loop
> 2011-12-18 16:38:27.355434 I [16487/16842] AudioOutputBase
> audio/audiooutputbase.cpp:1046 (GetAudiotime) - AO: GetAudiotime
> audt=47752726 atc=47752860 mb=25728 sb=0 tb=25728 sr=48000 obpf=4 bpf=24
> sf=1 -1722167296 -89
> 2011-12-18 16:38:27.355463 I [16487/16842] AudioOutputBase
> audio/audiooutputalsa.cpp:526 (WriteAudio) - WriteAudio: Preparing 9600
> bytes (2400 frames)
> 2011-12-18 16:38:27.355512 I [16487/16842] AudioOutputBase
> audio/audiooutputbase.cpp:1046 (GetAudiotime) - AO: GetAudiotime
> audt=47752726 atc=47752860 mb=16128 sb=19200 tb=35328 sr=48000 obpf=4
> bpf=24 sf=1 -762167296 -39
> 2011-12-18 16:38:27.355527 I [16487/16842] AudioOutputBase
> audio/audiooutputalsa.cpp:526 (WriteAudio) - WriteAudio: Preparing 9600
> bytes (2400 frames)
> 2011-12-18 16:38:27.355543 I [16487/16842] AudioOutputBase
> audio/audiooutputbase.cpp:1621 (OutputAudioLoop) - AO: audio waiting for
> buffer to fill: have 6528 want 9600
> 2011-12-18 16:38:27.359473 D [16487/16841] RingBuffer ringbuffer.cpp:858
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1204224, 2048) -- begin
> 2011-12-18 16:38:27.359509 I [16487/16841] RingBuffer ringbuffer.cpp:879
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1204224, 2048) -> 2048, took 0 ms (1000Mbps)
> 2011-12-18 16:38:27.359523 D [16487/16841] RingBuffer ringbuffer.cpp:892
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
> requested   2K in read
> 2011-12-18 16:38:27.359532 D [16487/16841] RingBuffer ringbuffer.cpp:943
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
> ahead loop
> 2011-12-18 16:38:27.367627 I [16487/16842] AudioOutputBase
> audio/audiooutputbase.cpp:1621 (OutputAudioLoop) - AO: audio waiting for
> buffer to fill: have 6528 want 9600
> 2011-12-18 16:38:27.367649 D [16487/16841] RingBuffer ringbuffer.cpp:858
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1206272, 2048) -- begin
> 2011-12-18 16:38:27.367689 I [16487/16841] RingBuffer ringbuffer.cpp:879
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1206272, 2048) -> 2048, took 0 ms (1000Mbps)
> 2011-12-18 16:38:27.367714 D [16487/16841] RingBuffer ringbuffer.cpp:892
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
> requested   2K in read
> 2011-12-18 16:38:27.367723 D [16487/16841] RingBuffer ringbuffer.cpp:943
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
> ahead loop
> 2011-12-18 16:38:27.368724 I [16487/16487] CoreContext
> audio/audiooutputbase.cpp:1046 (GetAudiotime) - AO: GetAudiotime
> audt=47752726 atc=47752860 mb=6528 sb=26080 tb=32608 sr=48000 obpf=4
> bpf=24 sf=1 -1034167296 -53
> 2011-12-18 16:38:27.368760 I [16487/16487] CoreContext
> mythplayer.cpp:1908 (AVSync) - Player(1): A/V timecodes audio 47752726
> video 47752773 frameinterval 33367 avdel 47 avg -20082 tcoffset 60 avp 0
> avpen 0 avdc 0
> 2011-12-18 16:38:27.368817 I [16487/16487] CoreContext
> mythplayer.cpp:2018 (SetBuffering) - Player(1): Waiting for video
> buffers...
> 2011-12-18 16:38:27.375767 D [16487/16841] RingBuffer ringbuffer.cpp:858
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1208320, 2048) -- begin
> 2011-12-18 16:38:27.375803 I [16487/16841] RingBuffer ringbuffer.cpp:879
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1208320, 2048) -> 2048, took 0 ms (1000Mbps)
> 2011-12-18 16:38:27.375816 D [16487/16841] RingBuffer ringbuffer.cpp:892
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
> requested   2K in read
> 2011-12-18 16:38:27.375824 D [16487/16841] RingBuffer ringbuffer.cpp:943
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
> ahead loop
> 2011-12-18 16:38:27.379866 I [16487/16842] AudioOutputBase
> audio/audiooutputbase.cpp:1621 (OutputAudioLoop) - AO: audio waiting for
> buffer to fill: have 6528 want 9600
> 2011-12-18 16:38:27.383923 D [16487/16841] RingBuffer ringbuffer.cpp:858
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1210368, 2048) -- begin
> 2011-12-18 16:38:27.383966 I [16487/16841] RingBuffer ringbuffer.cpp:879
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1210368, 2048) -> 2048, took 0 ms (1000Mbps)
> 2011-12-18 16:38:27.383981 D [16487/16841] RingBuffer ringbuffer.cpp:892
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
> requested   2K in read
> 2011-12-18 16:38:27.383990 D [16487/16841] RingBuffer ringbuffer.cpp:943
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
> ahead loop
> 2011-12-18 16:38:27.392077 I [16487/16842] AudioOutputBase
> audio/audiooutputbase.cpp:1621 (OutputAudioLoop) - AO: audio waiting for
> buffer to fill: have 6528 want 9600
> 2011-12-18 16:38:27.392825 D [16487/16841] RingBuffer ringbuffer.cpp:858
> (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
> safe_read(... at 1212416, 2048) -- begin

New description:

 Recently, and accidentally, I updated from mythtv-0.25_pre20111102 to
 mythtv-0.25_pre20111129, and now I'm having some serious buffering issues
 with TRANSCODED recordings.  Any recording that isn't transcoded is
 playing back perfectly (720p, 1080i both smooth as silk), and it's pretty
 much for all transcoded content, so simply newly transcoded recordings.

 I transcode by ticking the 'transcode' option for the recording schedule,
 either with Medium Quality or Low Quality

 The settings I use are:  (Advanced -> TV Settings -> Recording Profiles ->
 Transcoders -> ..)
 * Media Quality - Resize video while transcoding, 1280x720, MPEG4, 2200
 Bitrate, Max Qual 2, Min Qual 15, Max qual diff between frames 3, Scale
 bitrate for frame size, Enable High-quality encoding, Enable 4MV encoding;
 MP3 audio, 32000 sampling rate, qual 7, volume 90%
 * Low Quality - Resize video while transcoding, 960x540, MPEG4, 2200
 Bitrate, Max Qual 2, Min Qual 15, Max qual diff between frames 3, Scale
 bitrate for frame size, Enable High-quality encoding, Enable 4MV encoding;
 MP3 audio, 32000 sampling rate, qual 5, volume 90%

 I am using a Frontend with VPDAU high quality playback (and I have tried
 without using VPDAU with no different results), and CPU usage for the
 system is single digits generally when doing playback.  Dual Core i5 I
 think, 6 GB memory.

 Some log excerpts from playback:
 {{{
 2011-12-02 10:28:09.198258 N [5764/5764] CoreContext mythplayer.cpp:2090
 (PrebufferEnoughFrames) - Player(2): Waited 208ms for video buffers
 AAAAAffAAAAAAAAAAAAAAAAAAAAA
 2011-12-02 10:28:09.247233 I [5764/22424] Decoder ringbuffer.cpp:1093
 (WaitForAvail) - RingBuf(myth://mythserver:6543/2041_20111201213000.nuv):
 Waited 0.2 seconds for data
             to become available... 66599 < 83003
 2011-12-02 10:28:09.255258 I [5764/22424] Decoder ringbuffer.cpp:1093
 (WaitForAvail) - RingBuf(myth://mythserver:6543/2041_20111201213000.nuv):
 Waited 0.2 seconds for data
             to become available... 68647 < 83003
 2011-12-02 10:28:09.263160 I [5764/22424] Decoder ringbuffer.cpp:1093
 (WaitForAvail) - RingBuf(myth://mythserver:6543/2041_20111201213000.nuv):
 Waited 0.2 seconds for data
             to become available... 70695 < 83003
 }}}
 On the backend, I am not getting any errors.

 I copied the nuv to an SMB share that I have mounted for Videos, went into
 videos, same bad results.  I renamed it to avi, and used mplayer for
 playback which worked flawlessly.  Next I copied the file to a frontend
 local directory, again same failure.  Basically the internal player is the
 one having the trouble, regardless of location.

 I pulled down the 1107 commit and after some DB trickery was able to get
 the frontend up, and entered into the Videos section, and playback of the
 NUV is back to normal.  IF I get more time, I'll try another commit in
 between 1107 and 1129 to narrow down further where the bug has been
 introduced.

 Help!

 Some debug excerpts:
 {{{
 2011-12-18 16:38:27.343942 D [16487/16841] RingBuffer ringbuffer.cpp:858
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1200128, 2048) -- begin
 2011-12-18 16:38:27.343987 I [16487/16841] RingBuffer ringbuffer.cpp:879
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1200128, 2048) -> 2048, took 0 ms (1000Mbps)
 2011-12-18 16:38:27.344000 D [16487/16841] RingBuffer ringbuffer.cpp:892
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
 requested   2K in read
 2011-12-18 16:38:27.344007 D [16487/16841] RingBuffer ringbuffer.cpp:943
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
 ahead loop
 2011-12-18 16:38:27.345563 I [16487/16843] Decoder
 audio/audiooutputbase.cpp:1095 (SetAudiotime) - AO: SetAudiotime
 atc=47752884 tc=47752985 f=4096 pfu=-4352 pfs=-512
 2011-12-18 16:38:27.345799 I [16487/16843] Decoder
 audio/audiooutputbase.cpp:1331 (AddData) - AO: AddData frames=1152,
 bytes=4608, used=25729, free=3046271, timecode=47752985 needsupmix=1
 2011-12-18 16:38:27.345818 D [16487/16843] Decoder freesurround.cpp:363
 (putFrames) - FreeSurround::putFrames 1152 #ch 2 used 1152 generated 0
 2011-12-18 16:38:27.345832 I [16487/16843] Decoder
 audio/audiooutputbase.cpp:1095 (SetAudiotime) - AO: SetAudiotime
 atc=47752860 tc=47752985 f=0 pfu=-5504 pfs=-512
 2011-12-18 16:38:27.345848 D [16487/16843] Decoder ringbuffer.cpp:1188
 (ReadPriv) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 ReadPriv(..12, normal) @1198721 -- begin
 2011-12-18 16:38:27.345867 D [16487/16843] Decoder ringbuffer.cpp:1272
 (ReadPriv) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 ReadPriv(..12, normal) -- copying data
 2011-12-18 16:38:27.345876 D [16487/16843] Decoder ringbuffer.cpp:1287
 (ReadPriv) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 ReadPriv(..12, normal) -- checksum 5687
 2011-12-18 16:38:27.345890 D [16487/16843] Decoder ringbuffer.cpp:1188
 (ReadPriv) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 ReadPriv(..34077, normal) @1198733 -- begin
 2011-12-18 16:38:27.352057 D [16487/16841] RingBuffer ringbuffer.cpp:858
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1202176, 2048) -- begin
 2011-12-18 16:38:27.352068 I [16487/16487] CoreContext mythplayer.cpp:1824
 (AVSync) - Player(1): AVSync show
 2011-12-18 16:38:27.352118 I [16487/16841] RingBuffer ringbuffer.cpp:879
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1202176, 2048) -> 2048, took 0 ms (1000Mbps)
 2011-12-18 16:38:27.352134 D [16487/16841] RingBuffer ringbuffer.cpp:892
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
 requested   2K in read
 2011-12-18 16:38:27.352143 D [16487/16841] RingBuffer ringbuffer.cpp:943
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
 ahead loop
 2011-12-18 16:38:27.355434 I [16487/16842] AudioOutputBase
 audio/audiooutputbase.cpp:1046 (GetAudiotime) - AO: GetAudiotime
 audt=47752726 atc=47752860 mb=25728 sb=0 tb=25728 sr=48000 obpf=4 bpf=24
 sf=1 -1722167296 -89
 2011-12-18 16:38:27.355463 I [16487/16842] AudioOutputBase
 audio/audiooutputalsa.cpp:526 (WriteAudio) - WriteAudio: Preparing 9600
 bytes (2400 frames)
 2011-12-18 16:38:27.355512 I [16487/16842] AudioOutputBase
 audio/audiooutputbase.cpp:1046 (GetAudiotime) - AO: GetAudiotime
 audt=47752726 atc=47752860 mb=16128 sb=19200 tb=35328 sr=48000 obpf=4
 bpf=24 sf=1 -762167296 -39
 2011-12-18 16:38:27.355527 I [16487/16842] AudioOutputBase
 audio/audiooutputalsa.cpp:526 (WriteAudio) - WriteAudio: Preparing 9600
 bytes (2400 frames)
 2011-12-18 16:38:27.355543 I [16487/16842] AudioOutputBase
 audio/audiooutputbase.cpp:1621 (OutputAudioLoop) - AO: audio waiting for
 buffer to fill: have 6528 want 9600
 2011-12-18 16:38:27.359473 D [16487/16841] RingBuffer ringbuffer.cpp:858
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1204224, 2048) -- begin
 2011-12-18 16:38:27.359509 I [16487/16841] RingBuffer ringbuffer.cpp:879
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1204224, 2048) -> 2048, took 0 ms (1000Mbps)
 2011-12-18 16:38:27.359523 D [16487/16841] RingBuffer ringbuffer.cpp:892
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
 requested   2K in read
 2011-12-18 16:38:27.359532 D [16487/16841] RingBuffer ringbuffer.cpp:943
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
 ahead loop
 2011-12-18 16:38:27.367627 I [16487/16842] AudioOutputBase
 audio/audiooutputbase.cpp:1621 (OutputAudioLoop) - AO: audio waiting for
 buffer to fill: have 6528 want 9600
 2011-12-18 16:38:27.367649 D [16487/16841] RingBuffer ringbuffer.cpp:858
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1206272, 2048) -- begin
 2011-12-18 16:38:27.367689 I [16487/16841] RingBuffer ringbuffer.cpp:879
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1206272, 2048) -> 2048, took 0 ms (1000Mbps)
 2011-12-18 16:38:27.367714 D [16487/16841] RingBuffer ringbuffer.cpp:892
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
 requested   2K in read
 2011-12-18 16:38:27.367723 D [16487/16841] RingBuffer ringbuffer.cpp:943
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
 ahead loop
 2011-12-18 16:38:27.368724 I [16487/16487] CoreContext
 audio/audiooutputbase.cpp:1046 (GetAudiotime) - AO: GetAudiotime
 audt=47752726 atc=47752860 mb=6528 sb=26080 tb=32608 sr=48000 obpf=4
 bpf=24 sf=1 -1034167296 -53
 2011-12-18 16:38:27.368760 I [16487/16487] CoreContext mythplayer.cpp:1908
 (AVSync) - Player(1): A/V timecodes audio 47752726 video 47752773
 frameinterval 33367 avdel 47 avg -20082 tcoffset 60 avp 0 avpen 0 avdc 0
 2011-12-18 16:38:27.368817 I [16487/16487] CoreContext mythplayer.cpp:2018
 (SetBuffering) - Player(1): Waiting for video buffers...
 2011-12-18 16:38:27.375767 D [16487/16841] RingBuffer ringbuffer.cpp:858
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1208320, 2048) -- begin
 2011-12-18 16:38:27.375803 I [16487/16841] RingBuffer ringbuffer.cpp:879
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1208320, 2048) -> 2048, took 0 ms (1000Mbps)
 2011-12-18 16:38:27.375816 D [16487/16841] RingBuffer ringbuffer.cpp:892
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
 requested   2K in read
 2011-12-18 16:38:27.375824 D [16487/16841] RingBuffer ringbuffer.cpp:943
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
 ahead loop
 2011-12-18 16:38:27.379866 I [16487/16842] AudioOutputBase
 audio/audiooutputbase.cpp:1621 (OutputAudioLoop) - AO: audio waiting for
 buffer to fill: have 6528 want 9600
 2011-12-18 16:38:27.383923 D [16487/16841] RingBuffer ringbuffer.cpp:858
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1210368, 2048) -- begin
 2011-12-18 16:38:27.383966 I [16487/16841] RingBuffer ringbuffer.cpp:879
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1210368, 2048) -> 2048, took 0 ms (1000Mbps)
 2011-12-18 16:38:27.383981 D [16487/16841] RingBuffer ringbuffer.cpp:892
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): rbwpos +=   2K
 requested   2K in read
 2011-12-18 16:38:27.383990 D [16487/16841] RingBuffer ringbuffer.cpp:943
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv): @ end of read
 ahead loop
 2011-12-18 16:38:27.392077 I [16487/16842] AudioOutputBase
 audio/audiooutputbase.cpp:1621 (OutputAudioLoop) - AO: audio waiting for
 buffer to fill: have 6528 want 9600
 2011-12-18 16:38:27.392825 D [16487/16841] RingBuffer ringbuffer.cpp:858
 (run) - RingBuf(/mythtv/video/2041_20111208213000.nuv):
 safe_read(... at 1212416, 2048) -- begin
 }}}

--

Comment (by mdean):

 http://www.mythtv.org/wiki/Debugging

-- 
Ticket URL: <http://code.mythtv.org/trac/ticket/10212#comment:12>
MythTV <http://code.mythtv.org/trac>
MythTV Media Center


More information about the mythtv-commits mailing list