ffmpeg decoding cleanup

van · Post by **van** » Sun Aug 24, 2008 10:50 pm

The patch at http://handbrake.pastebin.ca/1183759 is a cut at cleaning up some ffmpeg conversion issues.

- The ignore_pts flag is gone & the decoder should use the content time stamps. This change should address this and this. There's still an issue that the ffmpeg mp4 reader ignores track edits. That means it doesn't correct video timestamps for init_delay so the A/V sync is off by up to 100ms when you run HB on its own h264-in-mp4 output.

- There's a work-around for the negative lengths while reading some avi files that jbrjake found. This hasn't really been tested because I haven't come upon a piece of content that exhibits this bug yet.

- I've got a bit better understanding of how ffmpeg sets up its timebase & recent changes to ffmpeg have made it internally more consistent. The result should be that we can reliably convert more content. But while ffmpeg seems to set timebase reliably, it doesn't much care about video frame rate (which is an informational parameter & not used it's decoding / display process). So frame rate is generally wrong on content that uses real timestamps (mp4/mov/...). Since we often can't get a frame rate from ffmpeg, I've changed our default from ntsc to ntsc film since this gives a more conservative (bigger) value for init_delay. Since we're using real timestamps for the decode this doesn't affect the HB output but it does mess up the progress indicator if the content is not 23.976 fps (it was messed up before if the content wasn't 29.97).

Post by **JohnAStebbins** » Sun Aug 24, 2008 11:50 pm

Heh, one-upped by van again. Thanks van. I visually inspected to see that it addressed the issues I was concerned about, then tested my problem files. Works like a charm.

I have a question regarding the frame rate issue. In sync.c line 620, there's code that inserts an eof into the stream if the number of frames processed exceeds the number of frames expected. The number of frames expected is based on the frame rate. An inaccurate frame rate will cause some video to be truncated. Do we still need this early stream termination code for something? An inaccurate video duration will cause the same problem which I've personally experienced.

EDIT: just realized that's output frame rate in sync.c so it's kind of unrelated. but still seems like a bad thing to be doing.

van · Post by **van** » Mon Aug 25, 2008 1:14 am

Hi John. Glad to hear it worked. I saw your earlier post about the deadlock due to the frame count in sync.c (nice catch BTW!) & it's on my list to fix. Life has just been too busy lately to get to it. That code doesn't really belong in sync. The problem it addresses is that some kinds of DVD DRM deliberately create a loop in the vob linkage & make an infinite source that will fill any disk when you try to convert it. The max frames check is to minimize the damage this can do. But this only applies to DVDs since stream content can't loop. I want to move that code to dvd.c so it won't affect converting other kinds of content.

Post by **JohnAStebbins** » Mon Aug 25, 2008 1:17 am

Ah, hadn't thought of that. Good to hear it's been thought about.

van · Post by **van** » Fri Sep 05, 2008 7:01 am

The next cut at this patch is at http://handbrake.pastebin.ca/1194522. I think it's finally handling jbrjake's 'badpacket' test case correctly. The previous code would handle vfw divx with one packed b-frame per packet but badpacket had two. The new code should handle any number of packed b-frames (up to 8 which I think is twice the max allowed). I was also completely mis-handling the negative length avi null packets which caused the A/V sync to get screwed up. That should now be fixed.

The mp4/mov A/V sync problems in the previous version should now be fixed. I figured out a more robust way to get video frame rate and that now seems to be reported correctly for all the input types I've tried.

I've run this with both ffmpeg-r14737 and the current ffmpeg head (r15216). It seems to work with both. With the current head I've also tried it using both faad for aac decoding & superdump's new aac decoder. Both seem to work but there's not a version of the latm-aac patch for superdump's decoder so I've mostly been testing with faad.

I've gotten good conversions with good A/V sync on all of the 30 or so different test cases I've tried so this may be getting close to being usable. I'd like to hear about successes and failures with it. Thanks.

eddyg · Post by **eddyg** » Sat Sep 06, 2008 9:59 pm

with any luck superdump will be adding latm support to his aac decoder - then we can ditch the latm patch. I wouldn't want to ditch it earlier than that since I depend on it daily.

Cheers ed

eddyg · Post by **eddyg** » Sat Sep 13, 2008 8:44 am

Hi Van

There may be an issue with the AV sync changes. For the first time ever I just had some extreme lip sync issues for my dvb-t stream. On the other hand an avi was perfect which was out before.

I'll do some more test encodes to establish a pattern.

Cheers Ed

van · Post by **van** » Sat Sep 13, 2008 10:25 pm

Ed - Does the patch at http://handbrake.pastebin.ca/1202124 take care of the problem?

eddyg · Post by **eddyg** » Mon Sep 15, 2008 2:54 am

Hi Van,

No improvement with your patch. Interestingly it is only the News that is doing it - and only for the past two days since your patch. I'll have to try reverting my version of HB and figure out whether it is your change or a change in what is coming over the air.

FYI Here is the Activity log, I don't see anything particularly interesting here.

http://handbrake.pastebin.ca/1203027

Cheers, Ed.

van · Post by **van** » Mon Sep 15, 2008 4:40 am

On the IRC logs I noticed jbrjake & tsw found a problem with some DVDs that appeared with r1570, the per-stream timing part of the STD changes. Deskchecking the code I found I'd made a really bonehead mistake - taking the difference of two timestamps that were each referenced to different clocks - that would almost certainly result in A/V sync problems if there were a lot of SCR changes (their problem DVDs had a lot of multi-angle cells & those often cause SCR changes). I just found the problem so I don't know if it fixes what they're seeing but it's definitely broken code.

Your content has a fair number of scr changes so maybe it's the same bug. If you get a chance try the patch at http://handbrake.pastebin.ca/1203069 and see if it helps. Thanks.

jbrjake · Post by **jbrjake** » Mon Sep 15, 2008 3:07 pm

Definitely fixes the problem tsw and I were having with It's Always Sunny in Philly.

Thanks, van =)

eddyg · Post by **eddyg** » Mon Sep 15, 2008 10:53 pm

Hi Van,

sync for my DVB-T is still all wrong, so much so that about half of the encodes don't even complete.

Here is a failed encode from last night using latest svn1687 plus your patch and decomb patch, I also did one using svn1700 plus decomb, and it also failed the same way, without completing and exiting early - although it actually hangs for ever rather than exit.

Code: Select all

[20:10:05] hb_init: checking cpu count
[20:10:05] hb_init: starting libhb thread
[20:10:05] thread b0081000 started ("libhb")
HandBrake svn1697M (2008091501) - http://handbrake.fr/
4 CPUs detected
Opening /Volumes/Multimedia Disk 2/EyeTV/EyeTV Archive/Piha Rescue.eyetv/000000000e7e4677.mpg...
[20:10:05] hb_scan: path=/Volumes/Multimedia Disk 2/EyeTV/EyeTV Archive/Piha Rescue.eyetv/000000000e7e4677.mpg, title_index=1
[20:10:05] thread b0103000 started ("scan")
[20:10:05] scan: trying to open with libdvdread
[20:10:05] dvd: not a dvd - trying as a stream/file instead
[20:10:05] file is MPEG Transport Stream with 188 byte packets offset 0 bytes
[20:10:05] hb_ts_stream_find_pids - found the following PIDS
[20:10:05]     Video PIDS : 
[20:10:05]       0x118 type H.264 (0x1b)
[20:10:05]     Audio PIDS : 
[20:10:05]       0x14a type MPEG4 LATM AAC (0x11)
[20:10:05]       0x3ea type ISO 13818-6 DSM-CC U-N msgs (0xb)
[20:10:05]       0x3f2 type ISO 13818-1 PES private data (0x6)
[20:10:05]       0x447 type ISO 13818-1 PES private data (0x6)
[20:10:05] transport stream pid 0x14a (type 0x11) is MPEG4 LATM AAC audio id 0xc0
[20:10:06] transport stream pid 0x3ea (type 0xb) isn't audio
[20:10:06] transport stream pid 0x3f2 (type 0x81) is AC-3 audio id 0x81bd
[20:10:06] transport stream pid 0x447 (type 0x81) is AC-3 audio id 0x82bd
[20:10:06] scan: decoding previews for title 1
[20:10:06] scan: preview 1
[h264 @ 0x1006000]error while decoding MB 66 14, bytestream (-26)
[h264 @ 0x1006000]mmco: unref short failure
[h264 @ 0x1006000]concealing 2463 DC, 2463 AC, 2463 MV errors
Scanning title 1...
[20:10:07] stream: error near frame 5: packet error bit set
[20:10:07] scan: audio 0xc0: AAC_LATM, rate=48000Hz, bitrate=384000 English (AAC_LATM) (2.0 ch)
Scanning title 1...
Scanning title 1...
Scanning title 1...
[20:10:07] scan: preview 2
Scanning title 1...
[h264 @ 0x1016a00]mmco: unref short failure
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
[20:10:08] scan: preview 3
Scanning title 1...
[h264 @ 0x1016e00]mmco: unref short failure
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
[20:10:09] scan: preview 4
Scanning title 1...
[h264 @ 0x1017200]mmco: unref short failure
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
[20:10:11] scan: preview 5
Scanning title 1...
[h264 @ 0x1017600]mmco: unref short failure
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
[20:10:11] scan: preview 6
[h264 @ 0x1017a00]mmco: unref short failure
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
[20:10:12] scan: preview 7
Scanning title 1...
[h264 @ 0x1017e00]mmco: unref short failure
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
[20:10:14] scan: preview 8
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
[20:10:15] scan: preview 9
Scanning title 1...
[h264 @ 0x1018600]mmco: unref short failure
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
[20:10:16] scan: preview 10
Scanning title 1...
[h264 @ 0x1018a00]mmco: unref short failure
Scanning title 1...
Scanning title 1...
Scanning title 1...
Scanning title 1...
[20:10:17] scan: 10 previews, 1280x720, 50.000 fps, autocrop = 0/0/0/0, aspect 16:9, PAR 1:1
[20:10:17] scan: removing audio 0x81bd because no bitrate found
[20:10:17] scan: removing audio 0x82bd because no bitrate found
[20:10:17] scan: title (0) job->width:1280, job->height:720
[20:10:17] stream: 889 good frames, 0 errors (0%)
[20:10:17] thread b0103000 exited ("scan")
[20:10:17] thread b0103000 joined ("scan")
[20:10:17] libhb: scan thread found 1 valid title(s)
+ title 1:
  + vts 0, ttn 0, cells 0->0 (0 blocks)
  + duration: 00:39:35
  + size: 1280x720, aspect: 1.78, 50.000 fps
  + autocrop: 0/0/0/0
  + chapters:
    + 1: cells 0->0, 0 blocks, duration 00:39:35
  + audio tracks:
    + 1, English (AAC_LATM) (2.0 ch)
  + subtitle tracks:
[20:10:17] thread b0103000 started ("work")
[20:10:17] 1 job(s) to process
[20:10:17] starting job
[20:10:17] work: sanitizing track 0 mixdown Dolby Pro Logic II to Stereo
[20:10:17] job configuration:
[20:10:17]  * source
[20:10:17]    + /Volumes/Multimedia Disk 2/EyeTV/EyeTV Archive/Piha Rescue.eyetv/000000000e7e4677.mpg
[20:10:17]    + title 1, chapter(s) 1 to 1
[20:10:17]  * destination
[20:10:17]    + /Users/egroenen/Movies/EyeTV/243156599.m4v
[20:10:17]    + container: MPEG-4 (.mp4 and .m4v)
[20:10:17]      + 64-bit formatting
[20:10:17]  * video track
[20:10:17]    + decoder: h264
[20:10:17]      + bitrate 200 kbps
[20:10:17]    + frame rate: 50.000 fps -> constant 25.000 fps
[20:10:17]    + dimensions: 1280 * 720 -> 1280 * 720, crop 0/0/0/0
[20:10:17]    + encoder: x264
[20:10:17]      + options: subq=4:me=hex:cabac=0:vbv-maxrate=4900:vbv-bufsize=2700
[20:10:17]      + bitrate: 4000 kbps, pass: 0
[20:10:17]  * audio track 0
[20:10:17]    + decoder: English (AAC_LATM) (2.0 ch) (track 0, id c0)
[20:10:17]    + mixdown: Stereo
[20:10:17]    + encoder: faac
[20:10:17]      + bitrate: 160 kbps, samplerate: 48000 Hz
[20:10:17] thread b0185000 started ("reader")
[20:10:17] thread b0207000 started ("Video decoder (libavcodec)")
[20:10:17] thread b0289000 started ("Renderer")
[20:10:17] encx264: opening libx264 (pass 0)
x264 [info]: using cpu capabilities: MMX2 SSE2Fast SSSE3 Cache64
[20:10:17] thread b030b000 started ("H.264/AVC encoder (libx264)")
[20:10:17] thread b038d000 started ("MPGA decoder (libavcodec)")
[20:10:17] dvd: not a dvd - trying as a stream/file instead
[20:10:17] reader: first SCR 4441709896 scr_offset 4441772026
[20:10:17] stream: error near frame 5: packet error bit set
[h264 @ 0x1000a00]non-existing PPS referenced
[h264 @ 0x1000a00]decode_slice_header error
[h264 @ 0x1000a00]error while decoding MB 66 14, bytestream (-26)
[h264 @ 0x1000a00]mmco: unref short failure
[h264 @ 0x1000a00]concealing 2463 DC, 2463 AC, 2463 MV errors
[h264 @ 0x1000a00]non-existing PPS referenced
[h264 @ 0x1000a00]decode_slice_header error
[20:10:17] thread b040f000 started ("AAC encoder (libfaac)")
[20:10:17] thread b0491000 started ("muxer")
[20:10:17] sync: expecting 59412 video frames
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549869853, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549873693, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549877533, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549881373, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549885213, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549892893, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549896733, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549900573, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549904413, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549908253, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549912093, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549896864, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549900704, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549904544, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549908384, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549912224, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549916064, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549919904, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549923744, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549927584, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549931424, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549935264, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549939104, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549942944, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549946784, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549950624, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549954464, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549958304, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549962144, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549965984, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549969824, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549973664, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549977504, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549981344, next 0
[20:10:17] Using 64-bit MP4 formatting.
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549985184, next 0
[h264 @ 0x1000a00]error while decoding MB 73 18, bytestream (-4)
[h264 @ 0x1000a00]concealing 2136 DC, 2136 AC, 2136 MV errors
[h264 @ 0x1000a00]error while decoding MB 27 4, bytestream (-8)
[h264 @ 0x1000a00]mmco: unref short failure
[h264 @ 0x1000a00]concealing 3302 DC, 3302 AC, 3302 MV errors
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549989024, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549992864, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549996704, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4550000544, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4550004384, next 0
[20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4550008224, next 0
[h264 @ 0x1000a00]mmco: unref short failure
[20:10:18] sync: 842 minute time gap in audio 0 - dropping buf  start 4550012064, next 0
[20:10:18] sync: 842 minute time gap in audio 0 - dropping buf  start 4550015904, next 0
[20:10:18] sync: 842 minute time gap in audio 0 - dropping buf  start 4550019744, next 0
[20:10:18] sync: 842 minute time gap in audio 0 - dropping buf  start 4550023584, next 0
[20:10:18] sync: 842 minute time gap in audio 0 - dropping buf  start 4550027424, next 0
[h264 @ 0x1000a00]mmco: unref short failure
[20:10:18] sync: 842 minute time gap in audio 0 - dropping buf  start 4550031264, next 0
[20:10:19] sync: 842 minute time gap in audio 0 - dropping buf  start 4550035104, next 0
[20:10:19] sync: 842 minute time gap in audio 0 - dropping buf  start 4550038944, next 0
[20:10:19] sync: 842 minute time gap in audio 0 - dropping buf  start 4550042784, next 0
[20:10:19] sync: 842 minute time gap in audio 0 - dropping buf  start 4550046624, next 0
[20:10:19] sync: 842 minute time gap in audio 0 - dropping buf  start 4550050464, next 0
[20:10:19] sync: 842 minute time gap in audio 0 - dropping buf  start 4550054304, next 0
[20:10:21] sync: 842 minute time gap in audio 0 - dropping buf  start 4550058144, next 0
[20:10:21] sync: 842 minute time gap in audio 0 - dropping buf  start 4550061984, next 0
[20:10:21] sync: 842 minute time gap in audio 0 - dropping buf  start 4550065824, next 0
[20:10:21] sync: 842 minute time gap in audio 0 - dropping buf  start 4550069664, next 0
[20:10:21] sync: 842 minute time gap in audio 0 - dropping buf  start 4550073504, next 0
[21:10:54] sync: got too many frames (118824), exiting early

The same source but with svn1686, get encodes, but no audio, and no video for the first part:

Code: Select all

[08:50:03] hb_init: checking cpu count
[08:50:03] hb_init: starting libhb thread
[08:50:03] thread b0081000 started ("libhb")
HandBrake svn1686 (2008091601) - http://handbrake.fr/
4 CPUs detected
Opening /Volumes/Multimedia Disk 2/EyeTV/EyeTV Archive/Piha Rescue.eyetv/000000000e7e4677.mpg...
[08:50:03] hb_scan: path=/Volumes/Multimedia Disk 2/EyeTV/EyeTV Archive/Piha Rescue.eyetv/000000000e7e4677.mpg, title_index=1
[08:50:03] thread b0103000 started ("scan")
[08:50:03] scan: trying to open with libdvdread
[08:50:03] dvd: not a dvd - trying as a stream/file instead
[08:50:03] file is MPEG Transport Stream with 188 byte packets offset 0 bytes
[08:50:03] hb_ts_stream_find_pids - found the following PIDS
[08:50:03]     Video PIDS : 
[08:50:03]       0x118 type H.264 (0x1b)
[08:50:03]     Audio PIDS : 
[08:50:03]       0x14a type MPEG4 LATM AAC (0x11)
[08:50:03]       0x3ea type ISO 13818-6 DSM-CC U-N msgs (0xb)
[08:50:03]       0x3f2 type ISO 13818-1 PES private data (0x6)
[08:50:03]       0x447 type ISO 13818-1 PES private data (0x6)
[08:50:03] transport stream pid 0x14a (type 0x11) is MPEG4 LATM AAC audio id 0xc0
[08:50:04] transport stream pid 0x3ea (type 0xb) isn't audio
[08:50:04] transport stream pid 0x3f2 (type 0x81) is AC-3 audio id 0x81bd
[08:50:04] transport stream pid 0x447 (type 0x81) is AC-3 audio id 0x82bd
[08:50:04] scan: decoding previews for title 1
[08:50:04] scan: preview 1
[08:50:04] stream: error near frame 2: continuity error: got 11 expected 5
[h264 @ 0x1006000]error while decoding MB 66 14, bytestream (-26)
[h264 @ 0x1006000]mmco: unref short failure
[h264 @ 0x1006000]concealing 2463 DC, 2463 AC, 2463 MV errors
[08:50:04] scan: audio 0xc0: AAC_LATM, rate=48000Hz, bitrate=384000 English (AAC_LATM) (2.0 ch)
Scanning title 1...
[08:50:04] scan: preview 2
[h264 @ 0x1016a00]mmco: unref short failure
Scanning title 1...
[08:50:05] scan: preview 3
[h264 @ 0x1016e00]mmco: unref short failure
Scanning title 1...
[08:50:05] scan: preview 4
[h264 @ 0x1017200]mmco: unref short failure
Scanning title 1...
Scanning title 1...
[08:50:05] scan: preview 5
[h264 @ 0x1017600]mmco: unref short failure
Scanning title 1...
[08:50:06] scan: preview 6
[h264 @ 0x1017a00]mmco: unref short failure
Scanning title 1...
[08:50:06] scan: preview 7
[h264 @ 0x1017e00]mmco: unref short failure
Scanning title 1...
Scanning title 1...
[08:50:07] scan: preview 8
[h264 @ 0x1018200]non-existing PPS referenced
[h264 @ 0x1018200]decode_slice_header error
[h264 @ 0x1018200]non-existing PPS referenced
[h264 @ 0x1018200]decode_slice_header error
Scanning title 1...
[08:50:07] scan: preview 9
[h264 @ 0x1018600]mmco: unref short failure
Scanning title 1...
Scanning title 1...
[08:50:07] scan: preview 10
[h264 @ 0x1018a00]mmco: unref short failure
Scanning title 1...
[08:50:08] scan: 10 previews, 1280x720, 50.000 fps, autocrop = 0/0/0/0, aspect 16:9, PAR 1:1
[08:50:08] scan: removing audio 0x81bd because no bitrate found
[08:50:08] scan: removing audio 0x82bd because no bitrate found
[08:50:08] scan: title (0) job->width:1280, job->height:720
[08:50:08] stream: 889 good frames, 0 errors (0%)
[08:50:08] thread b0103000 exited ("scan")
[08:50:08] thread b0103000 joined ("scan")
[08:50:08] libhb: scan thread found 1 valid title(s)
+ title 1:
  + vts 0, ttn 0, cells 0->0 (0 blocks)
  + duration: 00:39:35
  + size: 1280x720, aspect: 1.78, 50.000 fps
  + autocrop: 0/0/0/0
  + chapters:
    + 1: cells 0->0, 0 blocks, duration 00:39:35
  + audio tracks:
    + 1, English (AAC_LATM) (2.0 ch)
  + subtitle tracks:
[08:50:08] thread b0103000 started ("work")
[08:50:08] 1 job(s) to process
[08:50:08] starting job
[08:50:08] work: sanitizing track 0 mixdown Dolby Pro Logic II to Stereo
[08:50:08] job configuration:
[08:50:08]  * source
[08:50:08]    + /Volumes/Multimedia Disk 2/EyeTV/EyeTV Archive/Piha Rescue.eyetv/000000000e7e4677.mpg
[08:50:08]    + title 1, chapter(s) 1 to 1
[08:50:08]  * destination
[08:50:08]    + /Users/egroenen/Movies/EyeTV/243156599.m4v
[08:50:08]    + container: MPEG-4 (.mp4 and .m4v)
[08:50:08]      + 64-bit formatting
[08:50:08]  * video track
[08:50:08]    + decoder: h264
[08:50:08]      + bitrate 200 kbps
[08:50:08]    + frame rate: 50.000 fps -> constant 25.000 fps
[08:50:08]    + dimensions: 1280 * 720 -> 1280 * 720, crop 0/0/0/0
[08:50:08]    + encoder: x264
[08:50:08]      + options: subq=4:me=hex:cabac=0:vbv-maxrate=4900:vbv-bufsize=2700
[08:50:08]      + bitrate: 4000 kbps, pass: 0
[08:50:08]  * audio track 0
[08:50:08]    + decoder: English (AAC_LATM) (2.0 ch) (track 0, id c0)
[08:50:08]    + mixdown: Stereo
[08:50:08]    + encoder: faac
[08:50:08]      + bitrate: 160 kbps, samplerate: 48000 Hz
[08:50:08] thread b0185000 started ("reader")
[08:50:08] thread b0207000 started ("Video decoder (libavcodec)")
[08:50:08] thread b0289000 started ("Renderer")
[08:50:08] encx264: opening libx264 (pass 0)
x264 [info]: using cpu capabilities: MMX2 SSE2Fast SSSE3 Cache64
[08:50:09] thread b030b000 started ("H.264/AVC encoder (libx264)")
[08:50:09] dvd: not a dvd - trying as a stream/file instead
[08:50:09] reader: first SCR 4441709896 scr_offset 4441768426
[08:50:09] stream: error near frame 2: continuity error: got 11 expected 5
[08:50:09] thread b038d000 started ("MPGA decoder (libavcodec)")
[h264 @ 0x1000a00]error while decoding MB 66 14, bytestream (-26)
[h264 @ 0x1000a00]mmco: unref short failure
[h264 @ 0x1000a00]concealing 2463 DC, 2463 AC, 2463 MV errors
[08:50:09] thread b040f000 started ("AAC encoder (libfaac)")
[08:50:09] thread b0491000 started ("muxer")
[08:50:09] sync: expecting 59412 video frames
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114860103, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114863943, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114867783, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114871623, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114875463, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114883143, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114886983, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114890823, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114894663, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114898503, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114902343, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114887114, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114890954, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114894794, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114898634, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114902474, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114906314, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114910154, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114913994, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114917834, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114921674, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114925514, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114929354, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114933194, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114937034, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114940874, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114944714, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114948554, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114952394, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114956234, next 0
[08:50:09] h264: "" (1) at frame 0 time 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114960074, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114963914, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114967754, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114971594, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114975434, next 0
[08:50:09] Using 64-bit MP4 formatting.
[h264 @ 0x1000a00]error while decoding MB 73 18, bytestream (-4)
[h264 @ 0x1000a00]concealing 2136 DC, 2136 AC, 2136 MV errors
[h264 @ 0x1000a00]error while decoding MB 27 4, bytestream (-8)
[h264 @ 0x1000a00]mmco: unref short failure
[h264 @ 0x1000a00]concealing 3302 DC, 3302 AC, 3302 MV errors
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114979274, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114983114, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114986954, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114990794, next 0
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114994634, next 0
[h264 @ 0x1000a00]mmco: unref short failure
[08:50:09] sync: 21 minute time gap in audio 0 - dropping buf  start 114998474, next 0
[h264 @ 0x1000a00]mmco: unref short failure
[08:50:10] sync: 21 minute time gap in audio 0 - dropping buf  start 115002314, next 0

repeats over and over...

[10:39:56] sync: 61 minute time gap in audio 0 - dropping buf  start 330752714, next 0
[10:39:56] sync: 61 minute time gap in audio 0 - dropping buf  start 330756554, next 0
[10:39:56] sync: 61 minute time gap in audio 0 - dropping buf  start 330760394, next 0
[10:39:56] sync: 61 minute time gap in audio 0 - dropping buf  start 330764234, next 0
[10:39:56] sync: 61 minute time gap in audio 0 - dropping buf  start 330768074, next 0
[10:39:56] hb_ts_stream_decode - eof
[10:39:56] stream: 119883 good frames, 28 errors (0%)
[10:39:56] reader: done. 5 scr changes
[10:39:56] thread b0185000 exited ("reader")
[10:39:56] h264 done: 119879 frames, 0 decoder errors
[10:39:56] sync: got 91899 frames, 59412 expected
[10:39:56] sync: 59937 frames dropped, 31958 duplicated
[10:39:57] mux: file size, 1589577818 bytes
[10:39:57] mux: track 0, 1589175824 bytes, 3458.53 kbps
[10:39:57] mux: video bitrate error, -248804176 bytes
[10:39:57] mux: track 1, 51 bytes, 0.00 kbps
[10:39:57] mux: overhead, 4.37 bytes per frame
[10:39:57] thread b0491000 exited ("muxer")
[10:39:57] thread b0491000 joined ("muxer")
[10:39:57] thread b040f000 exited ("AAC encoder (libfaac)")
[10:39:57] thread b0207000 exited ("Video decoder (libavcodec)")
[10:39:57] thread b0207000 joined ("Video decoder (libavcodec)")
[10:39:57] thread b038d000 exited ("MPGA decoder (libavcodec)")
[10:39:57] thread b0289000 exited ("Renderer")
[10:39:57] thread b0289000 joined ("Renderer")
[10:39:57] render: lost time: 0 (0 frames)
[10:39:57] render: gained time: 0 (0 frames) (0 not accounted for)
[10:39:57] fifo_close: trashing 0 buffer(s)
[10:39:57] fifo_close: trashing 0 buffer(s)
[10:39:57] thread b030b000 exited ("H.264/AVC encoder (libx264)")
[10:39:57] thread b030b000 joined ("H.264/AVC encoder (libx264)")
x264 [info]: slice I:913   Avg QP:23.02  size: 54547  PSNR Mean Y:43.45 U:48.35 V:48.68 Avg:44.50 Global:41.40
x264 [info]: slice P:90986 Avg QP:19.03  size: 16919  PSNR Mean Y:44.30 U:48.67 V:48.90 Avg:45.29 Global:43.53
x264 [info]: mb I  I16..4: 54.4%  0.0% 45.6%
x264 [info]: mb P  I16..4: 13.1%  0.0%  6.2%  P16..4: 35.1% 11.8%  2.1%  0.0%  0.0%    skip:31.8%
x264 [info]: SSIM Mean Y:0.9828548
x264 [info]: PSNR Mean Y:44.290 U:48.665 V:48.901 Avg:45.279 Global:43.502 kb/s:3458.52
[10:39:57] thread b038d000 joined ("MPGA decoder (libavcodec)")
[10:39:57] thread b040f000 joined ("AAC encoder (libfaac)")
[10:39:57] thread b0185000 joined ("reader")
[10:39:57] fifo_close: trashing 0 buffer(s)
[10:39:57] fifo_close: trashing 1 buffer(s)
[10:39:57] fifo_close: trashing 0 buffer(s)
[10:39:57] fifo_close: trashing 0 buffer(s)
[10:39:57] fifo_close: trashing 0 buffer(s)
[10:39:57] fifo_close: trashing 0 buffer(s)
[10:39:57] fifo_close: trashing 0 buffer(s)
[10:39:57] fifo_close: trashing 0 buffer(s)
[10:39:57] fifo_close: trashing 0 buffer(s)
[10:39:57] Freed 32 buffers of size 1024
[10:39:57] Freed 32 buffers of size 2048
[10:39:57] Freed 21 buffers of size 16384
[10:39:57] Freed 1 buffers of size 32768
[10:39:57] Freed 32 buffers of size 2097152
[10:39:57] Allocated 67584000 bytes of buffers on this pass and Freed 67584000 bytes, 0 bytes leaked
[10:39:57] thread b0103000 exited ("work")
[10:39:57] thread b0103000 joined ("work")
[10:39:57] libhb: work result = 0

Rip done!
[10:39:57] thread b0081000 exited ("libhb")
[10:39:57] thread b0081000 joined ("libhb")
HandBrake has exited.

I'm going to try an older svn to see where it all started going wrong - these streams work fine in EyeTV
Cheers, Ed.

van · Post by **van** » Mon Sep 15, 2008 11:43 pm

These messages:

Code: Select all

 [20:10:17] sync: 842 minute time gap in audio 0 - dropping buf  start 4549869853, next 0

are from a change you suggested a while back where, rather than generating a huge chunk of silence when we get a timestamp that's way beyond the last we got, we drop to packet. It's saying that we expected timestamp 0 and got a huge number (somewhere near 2^33). The only way this can happen is if the SCR offset adjustment is messed up.

MPEG timestamps are 33 bits but I've never seen the high bit set (I suspect that most of the processing gear uses 32 bit timestamps & resets the SCR/PCR rather than allowing a carry into the 2^32 bit). I notice that the high bit is set in both the SCR (4441709896 = 1 08bf 1d48 in hex) and the initial audio timestamp (4549869853 = 1 0f31 811d). This shouldn't be possible since the audio TS is the packet TS minus the SCR and the packet TS must be < 2^33.

Since this is the first time I've seen timestamps with the 2^32 bit set, my guess is that I either screwed up the timestamp handling (I tested the 4 boundary cases with synthetic data but could easily have missed something) or the broadcaster's codec is ignoring the high bit & we're getting in trouble because we don't.

If there's any way to get me a short chunk of the content (5 seconds worth should be enough to get the PCRs & media TS) I should be able to dump it and sort out what's happening. Thanks.

eddyg · Post by **eddyg** » Tue Sep 16, 2008 12:32 am

Hi Van,

Well I've tried a few older versions of HB (1686 and 1677) and although neither hang like the svn head, neither get it right either.

Since I know svn1677 was working fine for me on these same shows I have to assume that the broadcaster has made some changes.

I'll try to cut some of the video with EyeTV and get it to you.

Cheers, Ed.

eddyg · Post by **eddyg** » Tue Sep 16, 2008 12:36 am

Cutting a small clip with EyeTV results in output that works, which is a pain in the bum.

eddyg · Post by **eddyg** » Tue Sep 16, 2008 12:46 am

I used "dd" to copy the front of it - worked perfectly.

Here is the link to my public files in my iDisk, your looking for freeview-dvbt-broken.mpg

http://idisk.mac.com/eddyg-Public/?view=web

It is copying now, should be another 15mins or so until complete (25Mb).

Cheers, Ed.

van · Post by **van** » Tue Sep 16, 2008 9:03 am

Got the file eddy & figured out the root cause. These are the first few PCRs & Audio PTSs in the order they appeared in the stream:

Code: Select all

program_clock_reference: 13:42:32.332179
program_clock_reference: 13:42:32.334348
    audio PTS: 14:02:34.1094
    audio PTS: 14:02:34.3654
program_clock_reference: 14:02:33.226378
program_clock_reference: 14:02:33.263656
    audio PTS: 14:02:35.1334
program_clock_reference: 14:02:33.300705

Notice the 20 minute jump between the 2nd & 3rd PCR. Notice that the audio PTS is clearly using the 14:02:33 timebase but the first two audio packets appear *before* the first PCR of that timebase so they're associated with the 13:42:32 timebase and thus get offset 20 minutes into the future relative to the video. To me this looks like a bug in the broadcaster's codec (the first two PCRs are only 2ms apart & I suspect the 2nd one should really have been the first of the later timebase).

But HB should be able to handle this. I think the fix is just to sanity check the PTSs & drop buffers are are more than about +- a second away from the current PCR. I've put in code to do this & it makes your stream work but now I've got to regression test it to make sure it doesn't break anything else. I'll do that after I get some sleep.

eddyg · Post by **eddyg** » Tue Sep 16, 2008 10:21 am

Hi Van

It's great to have you here to save me on this, I wasn't sure where to start.

So the PCR is on the video PID and the audio has presented a PTS that is way outside of the PCR.

So this is a sequence error between the audio and video, maybe some over the air interference caused us to miss the PCR update and so ended missing the jump in PCR and misinterpreting the PTS on the audio?

Ditching out obviously out of sequence audio seems a fair solution, certainly better than waiting for ever!

Cheers Ed.

van · Post by **van** » Tue Sep 16, 2008 10:18 pm

The patch is at http://handbrake.fr/pastebin/pastebin.php?show=44
You also probably want the libhb/reader.c bug fix I committed today (r1704).

eddyg wrote:So this is a sequence error between the audio and video, maybe some over the air interference caused us to miss the PCR update and so ended missing the jump in PCR and misinterpreting the PTS on the audio?

That can certainly happen which is a another good reason why HandBrake should handle this. But I don't think that's what happened here - it would require that a video packet be missing before the first audio packet but there are no continuity or sync errors & no gap in the every-20-ms video PTS sequence. This happens in the first second a switch between two shows & it really looks like their muxing gear just messed up the splice. (Didn't you say the failure has been happening regularly with this broadcast? Maybe the post-production gear they use to insert the initial teaser is what's messing up. But we'll never know and, with luck, the question will be academic from now on.)

eddyg · Post by **eddyg** » Wed Sep 17, 2008 9:12 am

Most excellent Van, worked perfectly, I'm back to watching the news again.

Cheers Ed

jbrjake · Post by **jbrjake** » Sun Sep 28, 2008 2:07 pm

van wrote:You also probably want the libhb/reader.c bug fix I committed today (r1704).

I've been noticing an odd AV sync issue since r1704.

When using detelecine (vfr detelecine that is, with dropped frames), encoding with x264, and muxing to mp4, the audio significantly leads the video. (The issue doesn't occur if job->vfr == 0, if the encoder isn't x264, or if the container isn't mp4.)

Here's a very short sample that will exhibit the problem, when encoded with those settings:
http://www.mediafire.com/file/nzwyzi1jmzt/hi-fi.ts

Post by **JohnAStebbins** » Mon Sep 29, 2008 4:15 pm

Out of curiosity, I added a log message to muxmp4.c:MP4Mux() to see what the timestamps (buf->start, buf->stop) and durations of the video frames are. I see this at the beginning of the encode.

Code: Select all

[08:53:03] sync: expecting 5262 video frames
[08:53:03] mpeg2: "" (1) at frame 0 time 11602
[08:53:03] sync: first pts is 11602
[08:53:03] mp4 start 0 stop 14605 dur 14605
[08:53:03] mp4 start 0 stop 14605 dur 14605
[08:53:03] mp4 start 14605 stop 19109 dur 4504
[08:53:03] mp4 start 19109 stop 22112 dur 3003
[08:53:03] mp4 start 22112 stop 26616 dur 4504
[08:53:03] mp4 start 26616 stop 29619 dur 3003

Notice the repeated timestamp. I don't know what causes this, but if I hack the code to drop one of these, the sync is correct.

My guess is that mkv tolerates this because it doesn't care about durations and goes strictly by the timestamp. Mp4 cares about the durations, so the repeat pushes everything else out.

EDIT: the duplicate seems to be getting added in renderWork()

jbrjake · Post by **jbrjake** » Mon Sep 29, 2008 8:53 pm

Thanks John. And eddyg too, for directing me on IRC towards the timestamp arrays in render.c. And I guess van too,for making sync good enough that it caught an old bug of mine

That sync issue should be fixed as of r1787.

HandBrake

ffmpeg decoding cleanup

ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup

Re: ffmpeg decoding cleanup