VFR rip of Ratatouille fails. QT says "incorrect duration"

[Eug]

This has been replicated by me several times now, and by btm. Ratatouille's 1st chapter will get ripped to an unreadable file by HandBrake... but only if VFR is active. Turn off VFR and it's totally fine. As btm has suggested, this could be due to Ratatouille's copy protection I suppose, but then again it could be a bug in HandBrake. I don't know.

Mac OS X 10.5.4
Intel iMac Core 2 Duo 2.33 GHz
HandBrake 0.9.2
Quicktime 7.5
iTunes 7.7.1

QT's error message:



iTunes won't let me import the file at all.

Activity log:

Code: Select all

[21:54:09] thread b00c5000 started ("work")
[21:54:09] 1 job(s) to process
[21:54:09] starting job
[21:54:09]  + device /dev/disk1
[21:54:09]  + title 1, chapter(s) 1 to 1
[21:54:09]  + 720x480 -> 720x352, crop 58/62/0/0
[21:54:09]  + filters
[21:54:09]    + Detelecine (pullup) (default settings)
[21:54:09]  + video frame rate: variable (detected 23.976 fps)
[21:54:09]  + video bitrate 2500 kbps, pass 0
[21:54:09]  + PixelRatio: 2, width:720, height: 352
[21:54:09]  + encoder x264
[21:54:09]    + x264 options: level=30:cabac=0:ref=1:analyse=all:me=umh:subq=6:no-fast-pskip=1:trellis=1
[21:54:09]  + audio 160 kbps, 48000 Hz
[21:54:09]  + encoder faac
[21:54:09]    + 80bd, English (AC3) (5.1 ch)
[21:54:09]      + Requested mixdown: Dolby Pro Logic II (HB_AMIXDOWN_DOLBYPLII)
[21:54:09]      + Actual mixdown: Dolby Pro Logic II (HB_AMIXDOWN_DOLBYPLII)
[21:54:09]    + 80bd, English (AC3) (5.1 ch)
[21:54:09]      + Requested mixdown: AC-3 Pass-through (HB_AMIXDOWN_AC3)
[21:54:09]      + Actual mixdown: AC-3 Pass-through (HB_AMIXDOWN_AC3)
[21:54:09] thread b04e6000 started ("reader")
[21:54:09]  + output: /Users/eug/Desktop/RATATOUILLE-Test.m4v
[21:54:09] thread b0579000 started ("muxer")
[21:54:09] thread b05fb000 started ("MPEG-2 decoder (libmpeg2)")
[21:54:09] thread b0781000 started ("Renderer")
[21:54:09] encx264: keyint-min: 24, keyint-max: 240
[21:54:09] encx264: encoding with stored aspect 139/120
[21:54:09] encx264: opening libx264 (pass 0)
x264 [info]: using SAR=139/120
x264 [info]: using cpu capabilities: MMX MMXEXT SSE SSE2 SSE3 SSSE3 Cache64 
[21:54:09] thread b0803000 started ("H.264/AVC encoder (libx264)")
No accelerated IMDCT transform found
[21:54:09] thread b0885000 started ("AC3 decoder")
[21:54:09] thread b0989000 started ("AAC encoder (libfaac)")
No accelerated IMDCT transform found
[21:54:09] thread b0a84000 started ("AC3 decoder")
[21:54:09] sync: expecting 1899 video frames
[21:54:13] dvd: Beginning of Cell (0) at block 1296
[21:54:13] dvd: End of Cell (0) at block 1296
[21:54:13] dvd: Beginning of Cell (1) at block 1312
[21:54:13] dvd: End of Cell (1) at block 1312
[21:54:13] dvd: Beginning of Cell (2) at block 1328
[21:54:13] sync: first pts is 25257
[21:54:13] dvd: null prev_vobu in cell 2 at block 1587
[21:54:13] macgui: Using preset: Eug iPhone
[21:54:13] dvd: Beginning of Cell (3) at block 2624
[21:54:13] dvd: End of Cell (3) at block 2624
[21:54:13] dvd: Beginning of Cell (4) at block 2640
[21:54:13] dvd: End of Cell (4) at block 2640
[21:54:13] dvd: Beginning of Cell (5) at block 2656
[21:54:13] dvd: End of Cell (5) at block 2656
[21:54:13] dvd: Beginning of Cell (6) at block 2672
[21:54:13] About to add iPod atom
[21:54:13] Disabled extra audio track 2
[21:55:00] dvd: End of Cell (6) at block 25043
[21:55:01] dvd: Beginning of Cell (7) at block 25289
[21:55:17] dvd: End of Cell (7) at block 33395
[21:55:18] dvd: Beginning of Cell (8) at block 33762
[21:55:18] dvd: Chapter Break Cell Found
[21:55:18] reader: end of chapter 1 (media 1) reached at media chapter 2
[21:55:18] reader: done
[21:55:18] thread b04e6000 exited ("reader")
[21:55:22] sync: got 1909 frames, 1899 expected
[21:55:23] Reader has exited early, inserting silence.
[21:55:23] Reader has exited early, inserting silence.
[21:55:23] sync: adding a silent AC-3 frame for track 80bd
[21:55:23] Reader has exited early, inserting silence.
[21:55:24] thread b0a84000 exited ("AC3 decoder")
[21:55:24] thread b05fb000 exited ("MPEG-2 decoder (libmpeg2)")
[21:55:24] thread b0885000 exited ("AC3 decoder")
[21:55:24] thread b05fb000 joined ("MPEG-2 decoder (libmpeg2)")
[21:55:24] thread b0781000 exited ("Renderer")
[21:55:24] thread b0781000 joined ("Renderer")
[21:55:24] render: lost time: 13513 (4 frames)
[21:55:24] render: gained time: 13513 (16 frames) (0 not accounted for)
[21:55:24] render: average dropped frame duration: 3378
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 2 buffer(s)
[21:55:24] thread b0803000 exited ("H.264/AVC encoder (libx264)")
[21:55:24] thread b0803000 joined ("H.264/AVC encoder (libx264)")
x264 [info]: slice I:27    Avg QP:10.22  size: 26667  PSNR Mean Y:55.96 U:54.40 V:53.92 Avg:54.45 Global:53.22
x264 [info]: slice P:1876  Avg QP:11.84  size: 13220  PSNR Mean Y:50.66 U:50.78 V:51.01 Avg:50.71 Global:49.51
x264 [info]: mb I  I16..4: 83.5%  0.0% 16.5%
x264 [info]: mb P  I16..4:  4.1%  0.0%  2.9%  P16..4: 52.0% 11.5%  4.6%  0.6%  0.4%    skip:24.0%
x264 [info]: final ratefactor: 12.84
x264 [info]: SSIM Mean Y:0.9927708
x264 [info]: PSNR Mean Y:50.740 U:50.832 V:51.055 Avg:50.761 Global:49.542 kb/s:2572.37
[21:55:24] thread b0885000 joined ("AC3 decoder")
[21:55:24] thread b0989000 exited ("AAC encoder (libfaac)")
[21:55:24] thread b0989000 joined ("AAC encoder (libfaac)")
[21:55:24] thread b0a84000 joined ("AC3 decoder")
[21:55:24] thread b04e6000 joined ("reader")
[21:55:24] mux: file size, 30666436 bytes
[21:55:24] mux: track 0, 25521999 bytes, 2689.00 kbps
[21:55:24] mux: video bitrate error, +1793815 bytes
[21:55:24] mux: track 1, 1460722 bytes, 153.90 kbps
[21:55:24] mux: track 2, 3643392 bytes, 383.87 kbps
[21:55:24] mux: overhead, 5.15 bytes per frame
[21:55:24] thread b0579000 exited ("muxer")
[21:55:24] thread b0579000 joined ("muxer")
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 2 buffer(s)
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 0 buffer(s)
[21:55:24] fifo_close: trashing 1 buffer(s)
[21:55:24] Freed 5 buffers of size 512
[21:55:24] Freed 2 buffers of size 1024
[21:55:24] Freed 2048 buffers of size 2048
[21:55:24] Freed 0 buffers of size 4096
[21:55:24] Freed 0 buffers of size 8192
[21:55:24] Freed 35 buffers of size 16384
[21:55:24] Freed 0 buffers of size 32768
[21:55:24] Freed 68 buffers of size 518400
[21:55:24] Allocated 40023552 bytes of buffers on this pass and Freed 40023552 bytes, 0 bytes leaked
[21:55:24] thread b00c5000 exited ("work")
[21:55:24] thread b00c5000 joined ("work")
[21:55:24] libhb: work result = 0

Settings:

level=30:cabac=0:ref=1:analyse=all:me=umh:subq=6:no-fast-pskip=1:trellis=1

[van]

That bug was fixed in r1478. Try the latest snapshot or compile HandBrake from the current source.

[Eug]

That bug was fixed in r1478. Try the latest snapshot or compile HandBrake from the current source.

I see. Indeed it was. svn1477 corrects the problem.

Looking forward to 0.9.3.

[dynaflash]

That bug was fixed in r1478. Try the latest snapshot or compile HandBrake from the current source.

I see. Indeed it was. svn1477 corrects the problem.

Um, if it was fixed in 1478 ... then how does 1477 solve the problem ? Not criticizing ... just curious.

[Eug]

Oops missed that.

You're right, it doesn't make sense that it would work. But nonetheless the VFR encodes work in 1477. Weird. I just tried it again, with the same preset and VFR checked.

And I tried 0.9.2 about 5 times using different anamorphic and picture settings. Regardless of the other settings, turning on VFR broke the encode in 0.9.2.

However, there is one significant difference between the successful Ratatouille encodes with 0.9.2 (no VFR) and 1477 (VFR). The former is 1:16 (1:16:03) and the latter is 1:17 (1:16:90).

[Eug]

And to be anal, I tried it yet again.

0.9.2 - VFR no worky:

Code: Select all

[00:14:02] thread b04d5000 started ("work")
[00:14:02] 2 job(s) to process
[00:14:02] starting job
[00:14:02]  + device /dev/disk1
[00:14:02]  + title 1, chapter(s) 1 to 1
[00:14:02]  + 720x480 -> 720x304, crop 58/62/0/0
[00:14:02]  + filters
[00:14:02]    + Detelecine (pullup) (default settings)
[00:14:02]  + video frame rate: variable (detected 23.976 fps)
[00:14:02]  + video bitrate 2500 kbps, pass -1
[00:14:02]  + PixelRatio: 0, width:720, height: 304
[00:14:02]  + encoder x264
[00:14:02]  + audio 160 kbps, 48000 Hz
[00:14:02]  + encoder faac
[00:14:02] thread b0568000 started ("reader")
[00:14:02]  + output: /Users/eug/Desktop/RATATOUILLE.m4v
[00:14:02] thread b05fb000 started ("muxer")
[00:14:02] thread b067d000 started ("MPEG-2 decoder (libmpeg2)")
[00:14:02] thread b0803000 started ("Renderer")
[00:14:02] encx264: keyint-min: 24, keyint-max: 240
[00:14:02] encx264: opening libx264 (pass -1)
x264 [info]: using cpu capabilities: MMX MMXEXT SSE SSE2 SSE3 SSSE3 Cache64 
[00:14:02] thread b0885000 started ("H.264/AVC encoder (libx264)")
[00:14:02] sync: expecting 1899 video frames
[00:14:04] dvd: Beginning of Cell (0) at block 1296
[00:14:04] dvd: End of Cell (0) at block 1296
[00:14:04] dvd: Beginning of Cell (1) at block 1312
[00:14:04] dvd: End of Cell (1) at block 1312
[00:14:04] dvd: Beginning of Cell (2) at block 1328
[00:14:05] dvd: null prev_vobu in cell 2 at block 1587
[00:14:05] dvd: Beginning of Cell (3) at block 2624
[00:14:05] dvd: End of Cell (3) at block 2624
[00:14:05] dvd: Beginning of Cell (4) at block 2640
[00:14:05] dvd: End of Cell (4) at block 2640
[00:14:05] dvd: Beginning of Cell (5) at block 2656
[00:14:05] dvd: End of Cell (5) at block 2656
[00:14:05] dvd: Beginning of Cell (6) at block 2672
[00:14:05] macgui: Using preset: Eug iPhone
[00:14:20] dvd: End of Cell (6) at block 25043
[00:14:20] dvd: Beginning of Cell (7) at block 25289
[00:14:25] dvd: End of Cell (7) at block 33395
[00:14:26] dvd: Beginning of Cell (8) at block 33762
[00:14:26] dvd: Chapter Break Cell Found
[00:14:26] reader: end of chapter 1 (media 1) reached at media chapter 2
[00:14:26] reader: done
[00:14:26] thread b0568000 exited ("reader")
[00:14:26] sync: got 0 frames, 1899 expected
[00:14:26] thread b0885000 exited ("H.264/AVC encoder (libx264)")
[00:14:26] thread b067d000 exited ("MPEG-2 decoder (libmpeg2)")
[00:14:26] thread b0803000 exited ("Renderer")
[00:14:26] thread b067d000 joined ("MPEG-2 decoder (libmpeg2)")
[00:14:26] thread b0803000 joined ("Renderer")
[00:14:26] render: lost time: 0 (0 frames)
[00:14:26] render: gained time: 0 (0 frames) (0 not accounted for)
[00:14:26] fifo_close: trashing 0 buffer(s)
[00:14:26] fifo_close: trashing 0 buffer(s)
[00:14:26] thread b0885000 joined ("H.264/AVC encoder (libx264)")
x264 [info]: final ratefactor: 11.19
[00:14:26] thread b0568000 joined ("reader")
[00:14:26] thread b05fb000 exited ("muxer")
[00:14:26] thread b05fb000 joined ("muxer")
[00:14:26] fifo_close: trashing 0 buffer(s)
[00:14:26] fifo_close: trashing 0 buffer(s)
[00:14:26] fifo_close: trashing 0 buffer(s)
[00:14:26] fifo_close: trashing 0 buffer(s)
[00:14:26] fifo_close: trashing 0 buffer(s)
[00:14:26] Freed 1 buffers of size 512
[00:14:26] Freed 0 buffers of size 1024
[00:14:26] Freed 2 buffers of size 2048
[00:14:26] Freed 0 buffers of size 4096
[00:14:26] Freed 0 buffers of size 8192
[00:14:26] Freed 0 buffers of size 16384
[00:14:26] Freed 0 buffers of size 32768
[00:14:26] Freed 1 buffers of size 518400
[00:14:26] Allocated 523008 bytes of buffers on this pass and Freed 523008 bytes, 0 bytes leaked
[00:14:26] starting job
[00:14:26]  + device /dev/disk1
[00:14:26]  + title 1, chapter(s) 1 to 1
[00:14:26]  + 720x480 -> 720x304, crop 58/62/0/0
[00:14:26]  + filters
[00:14:26]    + Detelecine (pullup) (default settings)
[00:14:26]  + video frame rate: variable (detected 23.976 fps)
[00:14:26]  + video bitrate 2500 kbps, pass 0
[00:14:26]  + PixelRatio: 0, width:720, height: 304
[00:14:26]  + encoder x264
[00:14:26]    + x264 options: level=30:cabac=0:ref=1:analyse=all:me=umh:subq=6:no-fast-pskip=1:trellis=1
[00:14:26]  + audio 160 kbps, 48000 Hz
[00:14:26]  + encoder faac
[00:14:26]    + 80bd, English (AC3) (5.1 ch)
[00:14:26]      + Requested mixdown: Dolby Pro Logic II (HB_AMIXDOWN_DOLBYPLII)
[00:14:26]      + Actual mixdown: Dolby Pro Logic II (HB_AMIXDOWN_DOLBYPLII)
[00:14:26]    + 80bd, English (AC3) (5.1 ch)
[00:14:26]      + Requested mixdown: AC-3 Pass-through (HB_AMIXDOWN_AC3)
[00:14:26]      + Actual mixdown: AC-3 Pass-through (HB_AMIXDOWN_AC3)
[00:14:26] thread b0568000 started ("reader")
[00:14:26]  + output: /Users/eug/Desktop/RATATOUILLE.m4v
[00:14:26] thread b05fb000 started ("muxer")
[00:14:26] thread b067d000 started ("MPEG-2 decoder (libmpeg2)")
[00:14:26] thread b0803000 started ("Renderer")
[00:14:26] encx264: keyint-min: 24, keyint-max: 240
[00:14:26] encx264: opening libx264 (pass 0)
x264 [info]: using cpu capabilities: MMX MMXEXT SSE SSE2 SSE3 SSSE3 Cache64 
[00:14:26] thread b0885000 started ("H.264/AVC encoder (libx264)")
No accelerated IMDCT transform found
[00:14:26] thread b0907000 started ("AC3 decoder")
[00:14:26] thread b0989000 started ("AAC encoder (libfaac)")
No accelerated IMDCT transform found
[00:14:26] thread b0a84000 started ("AC3 decoder")
[00:14:26] sync: expecting 1899 video frames
[00:14:27] dvd: Beginning of Cell (0) at block 1296
[00:14:27] dvd: End of Cell (0) at block 1296
[00:14:27] dvd: Beginning of Cell (1) at block 1312
[00:14:27] dvd: End of Cell (1) at block 1312
[00:14:27] sync: first pts is 25257
[00:14:27] dvd: Beginning of Cell (2) at block 1328
[00:14:27] macgui: Using preset: Eug iPhone
[00:14:27] dvd: null prev_vobu in cell 2 at block 1587
[00:14:28] dvd: Beginning of Cell (3) at block 2624
[00:14:28] dvd: End of Cell (3) at block 2624
[00:14:28] dvd: Beginning of Cell (4) at block 2640
[00:14:28] dvd: End of Cell (4) at block 2640
[00:14:28] dvd: Beginning of Cell (5) at block 2656
[00:14:28] dvd: End of Cell (5) at block 2656
[00:14:28] dvd: Beginning of Cell (6) at block 2672
[00:14:28] About to add iPod atom
[00:14:28] Disabled extra audio track 2
[00:15:12] dvd: End of Cell (6) at block 25043
[00:15:12] dvd: Beginning of Cell (7) at block 25289
[00:15:29] dvd: End of Cell (7) at block 33395
[00:15:30] dvd: Beginning of Cell (8) at block 33762
[00:15:30] dvd: Chapter Break Cell Found
[00:15:30] reader: end of chapter 1 (media 1) reached at media chapter 2
[00:15:30] reader: done
[00:15:30] thread b0568000 exited ("reader")
[00:15:34] sync: got 1909 frames, 1899 expected
[00:15:35] Reader has exited early, inserting silence.
[00:15:35] Reader has exited early, inserting silence.
[00:15:35] sync: adding a silent AC-3 frame for track 80bd
[00:15:35] Reader has exited early, inserting silence.
[00:15:35] thread b0803000 exited ("Renderer")
[00:15:35] thread b0989000 exited ("AAC encoder (libfaac)")
[00:15:35] thread b0885000 exited ("H.264/AVC encoder (libx264)")
[00:15:35] thread b067d000 exited ("MPEG-2 decoder (libmpeg2)")
[00:15:35] thread b0a84000 exited ("AC3 decoder")
[00:15:35] thread b0907000 exited ("AC3 decoder")
[00:15:35] thread b067d000 joined ("MPEG-2 decoder (libmpeg2)")
[00:15:35] mux: file size, 30759083 bytes
[00:15:35] mux: track 0, 25614665 bytes, 2698.76 kbps
[00:15:35] mux: video bitrate error, +1886481 bytes
[00:15:35] mux: track 1, 1460722 bytes, 153.90 kbps
[00:15:35] mux: track 2, 3643392 bytes, 383.87 kbps
[00:15:35] mux: overhead, 5.15 bytes per frame
[00:15:35] thread b05fb000 exited ("muxer")
[00:15:35] thread b0803000 joined ("Renderer")
[00:15:35] render: lost time: 13513 (4 frames)
[00:15:35] render: gained time: 13513 (16 frames) (0 not accounted for)
[00:15:35] render: average dropped frame duration: 3378
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 2 buffer(s)
[00:15:35] thread b0885000 joined ("H.264/AVC encoder (libx264)")
x264 [info]: slice I:28    Avg QP:10.04  size: 23158  PSNR Mean Y:54.10 U:53.71 V:53.31 Avg:53.80 Global:53.22
x264 [info]: slice P:1875  Avg QP:11.07  size: 13315  PSNR Mean Y:51.01 U:50.59 V:50.83 Avg:50.87 Global:50.16
x264 [info]: mb I  I16..4: 82.7%  0.0% 17.3%
x264 [info]: mb P  I16..4:  3.9%  0.0%  2.8%  P16..4: 55.0% 12.6%  5.3%  0.7%  0.5%    skip:19.1%
x264 [info]: final ratefactor: 11.86
x264 [info]: SSIM Mean Y:0.9934167
x264 [info]: PSNR Mean Y:51.052 U:50.635 V:50.863 Avg:50.916 Global:50.189 kb/s:2581.72
[00:15:35] thread b0907000 joined ("AC3 decoder")
[00:15:35] thread b0989000 joined ("AAC encoder (libfaac)")
[00:15:35] thread b0a84000 joined ("AC3 decoder")
[00:15:35] thread b0568000 joined ("reader")
[00:15:35] thread b05fb000 joined ("muxer")
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 2 buffer(s)
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 0 buffer(s)
[00:15:35] fifo_close: trashing 1 buffer(s)
[00:15:35] Freed 6 buffers of size 512
[00:15:35] Freed 3 buffers of size 1024
[00:15:35] Freed 2048 buffers of size 2048
[00:15:35] Freed 0 buffers of size 4096
[00:15:35] Freed 0 buffers of size 8192
[00:15:35] Freed 35 buffers of size 16384
[00:15:35] Freed 0 buffers of size 32768
[00:15:35] Freed 68 buffers of size 518400
[00:15:35] Allocated 40025088 bytes of buffers on this pass and Freed 40025088 bytes, 0 bytes leaked
[00:15:35] thread b04d5000 exited ("work")
[00:15:35] thread b04d5000 joined ("work")
[00:15:35] libhb: work result = 0

svn1477 - VFR works:

Code: Select all

[00:25:06] thread b04e6000 started ("work")
[00:25:06] 2 job(s) to process
[00:25:06] starting job
[00:25:06]  + device /dev/disk1
[00:25:06]  + title 1, chapter(s) 1 to 1
[00:25:06]  + 720x480 -> 720x304, crop 58/62/0/0
[00:25:06]  + filters
[00:25:06]    + Detelecine (pullup) (default settings)
[00:25:06]  + video frame rate: 23.976 fps -> variable fps
[00:25:06]  + video bitrate 2500 kbps, pass -1
[00:25:06]  + PixelRatio: 0, width:720, height: 304
[00:25:06]  + encoder x264
[00:25:06] thread b0579000 started ("reader")
[00:25:06]  + output: /Users/eug/Desktop/RATATOUILLE.mp4
[00:25:06] thread b05fb000 started ("muxer")
[00:25:06] thread b0781000 started ("MPEG-2 decoder (libmpeg2)")
[00:25:06] thread b0803000 started ("Renderer")
[00:25:06] encx264: keyint-min: 24, keyint-max: 240
[00:25:06] encx264: opening libx264 (pass -1)
x264 [info]: using cpu capabilities: MMX MMX2 SSE SSE2 SSE3 SSSE3 Cache64
[00:25:06] thread b0885000 started ("H.264/AVC encoder (libx264)")
[00:25:06] sync: expecting 1899 video frames
[00:25:09] dvd: end of cell 0 at block 1296
[00:25:09] reader: first SCR 146 scr_offset 25257
[00:25:09] dvd: end of cell 1 at block 1312
[00:25:09] dvd: null prev_vobu in cell 2 at block 1587
[00:25:09] macgui: Using preset: Eug iPhone
[00:25:09] dvd: end of cell 3 at block 2624
[00:25:09] dvd: end of cell 4 at block 2640
[00:25:09] dvd: end of cell 5 at block 2656
[00:25:31] reader: end of chapter 1 (media 1) reached at media chapter 2
[00:25:31] reader: done. 6 scr changes
[00:25:31] thread b0579000 exited ("reader")
[00:25:31] sync: got 0 frames, 1899 expected
[00:25:31] thread b0803000 exited ("Renderer")
[00:25:31] thread b0885000 exited ("H.264/AVC encoder (libx264)")
[00:25:31] thread b0781000 exited ("MPEG-2 decoder (libmpeg2)")
[00:25:31] thread b0781000 joined ("MPEG-2 decoder (libmpeg2)")
[00:25:31] mpeg2 done: 0 frames
[00:25:31] thread b0803000 joined ("Renderer")
[00:25:31] render: lost time: 0 (0 frames)
[00:25:31] render: gained time: 0 (0 frames) (0 not accounted for)
[00:25:31] fifo_close: trashing 0 buffer(s)
[00:25:31] fifo_close: trashing 0 buffer(s)
[00:25:31] thread b0885000 joined ("H.264/AVC encoder (libx264)")
x264 [info]: final ratefactor: 19.25
[00:25:31] thread b0579000 joined ("reader")
[00:25:31] thread b05fb000 exited ("muxer")
[00:25:31] thread b05fb000 joined ("muxer")
[00:25:31] fifo_close: trashing 0 buffer(s)
[00:25:31] fifo_close: trashing 0 buffer(s)
[00:25:31] fifo_close: trashing 0 buffer(s)
[00:25:31] fifo_close: trashing 0 buffer(s)
[00:25:31] fifo_close: trashing 0 buffer(s)
[00:25:31] Freed 1 buffers of size 512
[00:25:31] Freed 0 buffers of size 1024
[00:25:31] Freed 2 buffers of size 2048
[00:25:31] Freed 0 buffers of size 4096
[00:25:31] Freed 0 buffers of size 8192
[00:25:31] Freed 0 buffers of size 16384
[00:25:31] Freed 0 buffers of size 32768
[00:25:31] Freed 5 buffers of size 518400
[00:25:31] Allocated 2596608 bytes of buffers on this pass and Freed 2596608 bytes, 0 bytes leaked
[00:25:31] starting job
[00:25:31]  + device /dev/disk1
[00:25:31]  + title 1, chapter(s) 1 to 1
[00:25:31]  + 720x480 -> 720x304, crop 58/62/0/0
[00:25:31]  + filters
[00:25:31]    + Detelecine (pullup) (default settings)
[00:25:31]  + video frame rate: 23.976 fps -> variable fps
[00:25:31]  + video bitrate 2500 kbps, pass 0
[00:25:31]  + PixelRatio: 0, width:720, height: 304
[00:25:31]  + encoder x264
[00:25:31]    + x264 options: level=30:cabac=0:ref=1:analyse=all:me=umh:subq=6:no-fast-pskip=1
[00:25:31]  + audio track 0
[00:25:31]    + input track 0
[00:25:31]    + audio 160 kbps, 48000 Hz
[00:25:31]    + encoder faac
[00:25:31]      + 80bd, English (AC3) (5.1 ch)
[00:25:31]        + Requested mixdown: Dolby Pro Logic II (HB_AMIXDOWN_DOLBYPLII)
[00:25:31]        + Actual mixdown: Dolby Pro Logic II (HB_AMIXDOWN_DOLBYPLII)
[00:25:31]  + audio track 1
[00:25:31]    + input track 0
[00:25:31]    + AC3 passthrough
[00:25:31]      + 80bd, English (AC3) (5.1 ch)
[00:25:31] thread b0579000 started ("reader")
[00:25:31]  + output: /Users/eug/Desktop/RATATOUILLE.mp4
[00:25:31] thread b05fb000 started ("muxer")
[00:25:31] thread b0781000 started ("MPEG-2 decoder (libmpeg2)")
[00:25:31] thread b0803000 started ("Renderer")
[00:25:31] encx264: keyint-min: 24, keyint-max: 240
[00:25:31] encx264: opening libx264 (pass 0)
x264 [info]: using cpu capabilities: MMX MMX2 SSE SSE2 SSE3 SSSE3 Cache64
[00:25:31] thread b0885000 started ("H.264/AVC encoder (libx264)")
No accelerated IMDCT transform found
[00:25:31] thread b0907000 started ("AC3 decoder")
[00:25:31] thread b0989000 started ("AAC encoder (libfaac)")
No accelerated IMDCT transform found
[00:25:31] thread b0a84000 started ("AC3 decoder")
[00:25:31] sync: expecting 1899 video frames
[00:25:33] dvd: end of cell 0 at block 1296
[00:25:33] reader: first SCR 146 scr_offset 25257
[00:25:33] dvd: end of cell 1 at block 1312
[00:25:33] mpeg2: "Chapter  1" (1) at frame 0 time 0
[00:25:33] sync: video time didn't advance - dropped 11 frames (delta 342 ms, current 33033, next 2195)
[00:25:33] dvd: null prev_vobu in cell 2 at block 1587
[00:25:33] sync: video time didn't advance - dropped 11 frames (delta 342 ms, current 35228, next 4390)
[00:25:33] macgui: Using preset: Eug iPhone
[00:25:33] dvd: end of cell 3 at block 2624
[00:25:33] dvd: end of cell 4 at block 2640
[00:25:33] dvd: end of cell 5 at block 2656
[00:25:33] sync: adding 932 ms of silence to audio 0  start 83953, next 0
[00:25:33] sync: adding 932 ms of silence to audio 1  start 83953, next 0
[00:25:33] About to add iPod atom
[00:25:33] Disabled extra audio track 2
[00:25:33] sync: video time didn't advance - dropped 11 frames (delta 342 ms, current 117515, next 86677)
[00:25:34] sync: video time didn't advance - dropped 11 frames (delta 342 ms, current 119710, next 88872)
[00:25:34] sync: video time didn't advance - dropped 11 frames (delta 421 ms, current 121905, next 83953)
[00:26:30] reader: end of chapter 1 (media 1) reached at media chapter 2
[00:26:30] reader: done. 6 scr changes
[00:26:30] thread b0579000 exited ("reader")
[00:26:35] sync: reader has exited, adding silence to audio 0
[00:26:35] sync: reader has exited, adding silence to audio 1
[00:26:35] sync: got 1854 frames, 1899 expected
[00:26:35] sync: added 128 ms of silence to audio 0
[00:26:35] sync: added 128 ms of silence to audio 1
[00:26:35] thread b0781000 exited ("MPEG-2 decoder (libmpeg2)")
[00:26:35] thread b0781000 joined ("MPEG-2 decoder (libmpeg2)")
[00:26:35] mpeg2 done: 1910 frames
[00:26:35] thread b0a84000 exited ("AC3 decoder")
[00:26:35] thread b0907000 exited ("AC3 decoder")
[00:26:35] thread b0803000 exited ("Renderer")
[00:26:35] thread b0885000 exited ("H.264/AVC encoder (libx264)")
[00:26:35] thread b0803000 joined ("Renderer")
[00:26:35] render: lost time: 9009 (3 frames)
[00:26:35] render: gained time: 9009 (12 frames) (0 not accounted for)
[00:26:35] render: average dropped frame duration: 3003
[00:26:35] fifo_close: trashing 0 buffer(s)
[00:26:35] fifo_close: trashing 2 buffer(s)
[00:26:35] thread b0885000 joined ("H.264/AVC encoder (libx264)")
x264 [info]: slice I:28    Avg QP:10.39  size: 18546  PSNR Mean Y:58.57 U:58.27 V:55.86 Avg:56.25 Global:53.23
x264 [info]: slice P:1821  Avg QP:11.37  size: 11318  PSNR Mean Y:51.69 U:51.70 V:52.03 Avg:51.72 Global:49.72
x264 [info]: mb I  I16..4: 83.3%  0.0% 16.7%
x264 [info]: mb P  I16..4:  5.5%  0.0%  3.3%  P16..4: 53.7% 11.4%  5.0%  0.7%  0.5%    skip:20.0%
x264 [info]: final ratefactor: 8.87
x264 [info]: SSIM Mean Y:0.9937451
x264 [info]: PSNR Mean Y:51.790 U:51.797 V:52.090 Avg:51.791 Global:49.760 kb/s:2191.94
[00:26:35] thread b0989000 exited ("AAC encoder (libfaac)")
[00:26:35] thread b0907000 joined ("AC3 decoder")
[00:26:35] thread b0989000 joined ("AAC encoder (libfaac)")
[00:26:35] thread b0a84000 joined ("AC3 decoder")
[00:26:35] thread b0579000 joined ("reader")
[00:26:35] mux: file size, 26351547 bytes
[00:26:35] mux: track 0, 21130457 bytes, 2197.03 kbps
[00:26:35] mux: video bitrate error, -2913931 bytes
[00:26:35] mux: track 1, 1488636 bytes, 154.78 kbps
[00:26:35] mux: track 2, 3692544 bytes, 383.93 kbps
[00:26:35] mux: overhead, 5.08 bytes per frame
[00:26:35] thread b05fb000 exited ("muxer")
[00:26:35] thread b05fb000 joined ("muxer")
[00:26:35] fifo_close: trashing 0 buffer(s)
[00:26:35] fifo_close: trashing 1 buffer(s)
[00:26:35] fifo_close: trashing 0 buffer(s)
[00:26:35] fifo_close: trashing 0 buffer(s)
[00:26:35] fifo_close: trashing 0 buffer(s)
[00:26:35] fifo_close: trashing 0 buffer(s)
[00:26:35] fifo_close: trashing 0 buffer(s)
[00:26:35] fifo_close: trashing 0 buffer(s)
[00:26:35] fifo_close: trashing 1 buffer(s)
[00:26:35] fifo_close: trashing 0 buffer(s)
[00:26:35] fifo_close: trashing 0 buffer(s)
[00:26:35] fifo_close: trashing 0 buffer(s)
[00:26:35] fifo_close: trashing 1 buffer(s)
[00:26:35] Freed 6 buffers of size 512
[00:26:35] Freed 0 buffers of size 1024
[00:26:35] Freed 2048 buffers of size 2048
[00:26:35] Freed 0 buffers of size 4096
[00:26:35] Freed 0 buffers of size 8192
[00:26:35] Freed 235 buffers of size 16384
[00:26:35] Freed 0 buffers of size 32768
[00:26:35] Freed 48 buffers of size 518400
[00:26:35] Allocated 32930816 bytes of buffers on this pass and Freed 32930816 bytes, 0 bytes leaked
[00:26:35] thread b04e6000 exited ("work")
[00:26:35] thread b04e6000 joined ("work")
[00:26:35] libhb: work result = 0

The successful svn1477 encode (with VFR active) is again 1:17 (1:16:94 this time).

P.S. I may as well also mention that svn1477 introduces an artifact that doesn't exist in the successful (non-VFR) 0.9.2 encode.