Opened 12 years ago

Last modified 12 years ago

#10212 closed Bug Report - General

Transcoded recordings playback broken (stutters, audio failure) during November commits — at Version 12

Reported by: jk90090@… Owned by: markk
Priority: minor Milestone: 0.25
Component: MythTV - Video Playback Version: Master Head
Severity: medium Keywords: transcoded recordings
Cc: Ticket locked: no

Description (last modified by sphery)

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(...@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(...@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(...@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(...@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(...@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(...@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(...@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(...@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(...@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(...@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(...@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(...@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(...@1212416, 2048) -- begin

Change History (12)

comment:1 Changed 12 years ago by jk90090@…

Loaded commit 2011 11 13. Fails.

scripts/mythtv-buildebuild.py -s 4f3b78c3ef2a704c5c74013fa1c6cb870cce4631 --date=20111113 emerge -pv =media-tv/mythtv-0.25_pre20111113

And for tracking, the below commit works:

scripts/mythtv-buildebuild.py -s a2e143f7c77349afcf5cf147a1e4765a2a54db21 --date=20111107 emerge -v =media-tv/mythtv-0.25_pre20111107

comment:2 Changed 12 years ago by jk90090@…

Commit 20111110 works fine.

scripts/mythtv-buildebuild.py -s 94bf2f1eed9b274f33d20028fdec582a2d1f4867 --date=20111110 emerge -v =media-tv/mythtv-0.25_pre20111110

comment:3 Changed 12 years ago by jk90090@…

Ok, narrowed it down to a 1 day window now.

Commit date 20111111 fails to playback properly

scripts/mythtv-buildebuild.py --date=20111111 -s 47d52964f9946e90d9d8edc4392107b338270491 emerge -v =media-tv/mythtv-0.25_pre20111111

comment:4 Changed 12 years ago by jk90090@…

Not entirely sure if the hash actually makes any difference, but I also tried commit hash 836a072d75a21756dc93d014cfd66586f8f67b97 for date 20111111, which also results in failure.

comment:5 Changed 12 years ago by jk90090@…

Additional testting data. My backend, which is still currently running the 20111217 build, plays back the transcoded recordings fine. It is a Quad-core Intel i7 S 860, running a Radeon card (01:00.0 VGA compatible controller: ATI Technologies Inc RV710 [Radeon HD 4550]), audio through Intel chip (00:1b.0 Audio device: Intel Corporation Ibex Peak High Definition Audio (rev 06))

Frontend: Intel Dual Core Duo 6400, Nvidia card (01:00.0 VGA compatible controller: nVidia Corporation G94 9600 GT? (rev a1)), Intel audio (00:1b.0 Audio device: Intel Corporation 82801H (ICH8 Family) HD Audio Controller (rev 02))

comment:6 Changed 12 years ago by jk90090@…

Mark, having any luck?

comment:7 Changed 12 years ago by robertm

Milestone: 0.25unknown
Priority: criticalminor
Severity: highmedium

Please don't bump/ping tickets. Also, please read the ticket howto, do not set severity, milestone, or priority.

comment:8 Changed 12 years ago by amlopezalonso@…

Just having commercials removed (no other transcoding made) makes this issue to happen. The stuttering slots appear scattered along the transcoded recording with no obvious (for me at least) pattern.

comment:9 Changed 12 years ago by jk90090@…

For what it's worth, here's what FFMPEG shows on an transcoded recording:

ffmpeg version 0.7.3, Copyright (c) 2000-2011 the FFmpeg developers

built on Aug 30 2011 16:18:43 with gcc 4.4.4 configuration: --prefix=/usr --libdir=/usr/lib --shlibdir=/usr/lib --mandir=/usr/share/man --enable-shared --cc=i686-pc-linux-gnu-gcc --disable-static --enable-gpl --enable-version3 --enable-postproc --enable-avfilter --disable-stripping --disable-debug --disable-doc --disable-network --disable-vaapi --disable-vdpau --enable-libmp3lame --enable-libvo-aacenc --enable-libvo-amrwbenc --enable-libtheora --enable-libvorbis --enable-libx264 --enable-libxvid --enable-libdc1394 --disable-indev=v4l --disable-indev=oss --disable-indev=jack --enable-x11grab --disable-outdev=oss --enable-libfreetype --enable-pthreads --enable-libopencore-amrwb --enable-libopencore-amrnb --disable-altivec --disable-avx --cpu=i686 --enable-hardcoded-tables libavutil 50. 43. 0 / 50. 43. 0 libavcodec 52.122. 0 / 52.122. 0 libavformat 52.110. 0 / 52.110. 0 libavdevice 52. 5. 0 / 52. 5. 0 libavfilter 1. 80. 0 / 1. 80. 0 libswscale 0. 14. 1 / 0. 14. 1 libpostproc 51. 2. 0 / 51. 2. 0

[nuv @ 0x9ccfe00] Estimating duration from bitrate, this may be inaccurate

Seems stream 0 codec frame rate differs from container frame rate: 1000.00 (1000/1) -> 29.97 (30000/1001) Input #0, nuv, from '2041_20111208213000.avi':

Duration: 13:47:53.70, start: 47746.500000, bitrate: 127 kb/s

Stream #0.0: Video: mpeg4, yuv420p, 960x544, PAR 34:45 DAR 4:3, 29.97 tbr, 1k tbn, 1k tbc Stream #0.1: Audio: mp3, 48000 Hz, stereo, s16, 128 kb/s

At least one output file must be specified

comment:10 Changed 12 years ago by jk90090@…

More data points: It would appear the Mythbuntu 11.10 repository 0.25 builds are suffering the same issue. I loaded it today on the Frontend and experience the same playback issues.

comment:11 Changed 12 years ago by amlopezalonso@…

Yes, that's the one I'm running.

@robertm:

Could you please suggest an option to pass to FE/other in order to generate a proper backtrace?

Thanks, Antonio

comment:12 Changed 12 years ago by sphery

Description: modified (diff)
Note: See TracTickets for help on using tickets.