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: | 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 )
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
comment:2 Changed 12 years ago by
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
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
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
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:7 Changed 12 years ago by
Milestone: | 0.25 → unknown |
---|---|
Priority: | critical → minor |
Severity: | high → medium |
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
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
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
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
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
Description: | modified (diff) |
---|
Loaded commit 2011 11 13. Fails.
And for tracking, the below commit works: