0.9.3 Encodes have extra length at end (w/ Log)

[VKX]

All the movies I encode with 0.9.3 seem to have a weird error at the very end. After the credits, it's blank for a few more minutes. Trying to skip through this part using the progress bar (in quicktime or iTunes, for instance) yeilds strange results. It'll usually continue showing the frame I was at when I started skipping forward (and remain showing that frame even as the progress bar now says the blank end minutes are playing).

Here's a log from a recent encode with this issue.

Code: Select all

HandBrake Activity Log for /Users/VKX/Downloads/Sin City.m4v: 2009-01-17 17:32:47 -0600
Handbrake Version: 0.9.3 (2008112300)

[17:32:47] macgui: Rip: Pending queue count is 0
[17:32:47] macgui: Rip: No pending jobs, so sending this one to doAddToQueue
[17:32:47] macgui: Rip: Going right to performNewQueueScan
[17:32:47] macgui: scanning specifically for title: 1
[17:32:47] macgui: performNewQueueScan currentQueueEncodeIndex is: 0
[17:32:47] hb_scan: path=/Volumes/Storage/DVDs/Movies/Sin City, title_index=1
[17:32:47] scan: trying to open with libdvdread

*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***

[17:32:47] scan: DVD has 14 title(s)
[17:32:47] scan: scanning title 1
[17:32:47] scan: opening IFO for VTS 1
[17:32:47] pgc_id: 1, pgn: 1: pgc: 0xf16de20
[17:32:47] scan: vts=1, ttn=1, cells=0->28, blocks=593->592, 2960810 blocks
[17:32:47] scan: duration is 02:03:54 (7434320 ms)
[17:32:47] scan: checking audio 1
[17:32:47] scan: id=80bd, lang=English (AC3), 3cc=eng ext=0
[17:32:47] scan: checking audio 2
[17:32:47] scan: id=89bd, lang=English (DTS), 3cc=eng ext=0
[17:32:47] scan: checking audio 3
[17:32:47] scan: id=82bd, lang=English (AC3), 3cc=eng ext=0
[17:32:47] scan: checking audio 4
[17:32:47] scan: id=83bd, lang=English (AC3), 3cc=eng ext=0
[17:32:47] scan: checking audio 5
[17:32:47] scan: id=84bd, lang=English (AC3), 3cc=eng ext=0
[17:32:47] scan: checking subtitle 1
[17:32:47] scan: id=20bd, lang=English, 3cc=eng
[17:32:47] scan: checking subtitle 2
[17:32:47] scan: id=21bd, lang=Espanol, 3cc=spa
[17:32:47] scan: title 1 has 29 chapters
[17:32:47] scan: chap 1 c=0->0, b=593->64968 (64376), 179379 ms
[17:32:47] scan: chap 2 c=1->1, b=64969->108629 (43661), 111154 ms
[17:32:47] scan: chap 3 c=2->2, b=108630->311640 (203011), 490677 ms
[17:32:47] scan: chap 4 c=3->3, b=311641->402461 (90821), 216516 ms
[17:32:47] scan: chap 5 c=4->4, b=402462->447124 (44663), 118251 ms
[17:32:47] scan: chap 6 c=5->5, b=447125->593681 (146557), 357357 ms
[17:32:47] scan: chap 7 c=6->6, b=593682->724448 (130767), 346422 ms
[17:32:47] scan: chap 8 c=7->7, b=724449->832741 (108293), 242518 ms
[17:32:47] scan: chap 9 c=8->8, b=832742->1048192 (215451), 568579 ms
[17:32:47] scan: chap 10 c=9->9, b=1048193->1125037 (76845), 205348 ms
[17:32:47] scan: chap 11 c=10->10, b=1125038->1240208 (115171), 278398 ms
[17:32:47] scan: chap 12 c=11->11, b=1240209->1316783 (76575), 194337 ms
[17:32:47] scan: chap 13 c=12->12, b=1316784->1403024 (86241), 218361 ms
[17:32:47] scan: chap 14 c=13->13, b=1403025->1479812 (76788), 210386 ms
[17:32:47] scan: chap 15 c=14->14, b=1479813->1601552 (121740), 308474 ms
[17:32:47] scan: chap 16 c=15->15, b=1601553->1711589 (110037), 258558 ms
[17:32:47] scan: chap 17 c=16->16, b=1711590->1841399 (129810), 324524 ms
[17:32:47] scan: chap 18 c=17->17, b=1841400->1918318 (76919), 177410 ms
[17:32:47] scan: chap 19 c=18->18, b=1918319->2065458 (147140), 379556 ms
[17:32:47] scan: chap 20 c=19->19, b=2065459->2149091 (83633), 220473 ms
[17:32:47] scan: chap 21 c=20->20, b=2149092->2224476 (75385), 188474 ms
[17:32:47] scan: chap 22 c=21->21, b=2224477->2317224 (92748), 233443 ms
[17:32:47] scan: chap 23 c=22->22, b=2317225->2443479 (126255), 299586 ms
[17:32:47] scan: chap 24 c=23->23, b=2443480->2607274 (163795), 422623 ms
[17:32:47] scan: chap 25 c=24->24, b=2607275->2745948 (138674), 319640 ms
[17:32:47] scan: chap 26 c=25->25, b=2745949->2807341 (61393), 127170 ms
[17:32:47] scan: chap 27 c=26->26, b=2807342->2831722 (24381), 57190 ms
[17:32:47] scan: chap 28 c=27->27, b=2831723->2960917 (129195), 378499 ms
[17:32:47] scan: chap 29 c=28->28, b=108->592 (485), 1001 ms
[17:32:47] scan: aspect = 0
[17:32:47] scan: decoding previews for title 1
[17:32:48] scan: audio 0x80bd: AC-3, rate=48000Hz, bitrate=448000 English (AC3) (5.1 ch)
[17:32:48] scan: audio 0x89bd: DCA, rate=48000Hz, bitrate=768000 English (DTS) (5.1 ch)
[17:32:48] scan: audio 0x82bd: AC-3, rate=48000Hz, bitrate=96000 English (AC3) (1.0 ch)
[17:32:48] scan: audio 0x83bd: AC-3, rate=48000Hz, bitrate=96000 English (AC3) (1.0 ch)
[17:32:48] scan: audio 0x84bd: AC-3, rate=48000Hz, bitrate=384000 English (AC3) (5.1 ch)
[17:32:48] scan: 10 previews, 720x480, 23.976 fps, autocrop = 6/8/0/0, aspect 16:9, PAR 32:27
[17:32:48] scan: title (0) job->width:720, job->height:400
[17:32:48] libhb: scan thread found 1 valid title(s)
[17:32:49] macgui: ScanDone state received from fQueueEncodeLibhb
[17:32:49] macgui: processNewQueueEncode title list is: 1
[17:32:49] macgui: Preset: AppleTV
[17:32:49] macgui: processNewQueueEncode number of passes expected is: 1
[17:32:49] macgui: prepareJob audiotrack 2 is: 0
[17:32:49] macgui: prepareJob exiting
[17:32:49] 1 job(s) to process
[17:32:49] starting job
[17:32:49] job configuration:
[17:32:49]  * source
[17:32:49]    + /Volumes/Storage/DVDs/Movies/Sin City
[17:32:49]    + title 1, chapter(s) 1 to 29
[17:32:49]  * destination
[17:32:49]    + /Users/VKX/Downloads/Sin City.m4v
[17:32:49]    + container: MPEG-4 (.mp4 and .m4v)
[17:32:49]      + 64-bit formatting
[17:32:49]      + chapter markers
[17:32:49]  * video track
[17:32:49]    + decoder: mpeg2
[17:32:49]      + bitrate 9800 kbps
[17:32:49]    + frame rate: same as source (around 23.976 fps)
[17:32:49]    + dimensions: 720 * 480 -> 720 * 400, crop 6/8/4/4
[17:32:49]    + encoder: x264
[17:32:49]      + options: level=30:cabac=0:ref=3:mixed-refs=1:bframes=6:weightb=1:direct=auto:no-fast-pskip=1:me=umh:subq=7:analyse=all
[17:32:49]      + bitrate: 4000 kbps, pass: 0
[17:32:49]  * audio track 0
[17:32:49]    + decoder: English (AC3) (5.1 ch) (track 1, id 80bd)
[17:32:49]      + bitrate: 448 kbps, samplerate: 48000 Hz
[17:32:49]    + mixdown: Dolby Pro Logic II
[17:32:49]    + encoder: faac
[17:32:49]      + bitrate: 128 kbps, samplerate: 44100 Hz
[17:32:49]  * audio track 1
[17:32:49]    + decoder: English (AC3) (5.1 ch) (track 1, id 80bd)
[17:32:49]      + bitrate: 448 kbps, samplerate: 48000 Hz
[17:32:49]    + AC3 passthrough
[17:32:49]  * audio track 2
[17:32:49]    + decoder: English (AC3) (1.0 ch) (track 3, id 82bd)
[17:32:49]      + bitrate: 96 kbps, samplerate: 48000 Hz
[17:32:49]    + mixdown: Mono
[17:32:49]    + encoder: faac
[17:32:49]      + bitrate: 96 kbps, samplerate: 44100 Hz
[17:32:49]  * audio track 3
[17:32:49]    + decoder: English (AC3) (1.0 ch) (track 4, id 83bd)
[17:32:49]      + bitrate: 96 kbps, samplerate: 48000 Hz
[17:32:49]    + mixdown: Mono
[17:32:49]    + encoder: faac
[17:32:49]      + bitrate: 96 kbps, samplerate: 44100 Hz

*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:776 ***
*** for pgc->program_map_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:777 ***
*** for pgc->cell_playback_offset == 0 ***


*** libdvdread: CHECK_VALUE failed in ifo_read.c:778 ***
*** for pgc->cell_position_offset == 0 ***

[17:32:49] encx264: keyint-min: 24, keyint-max: 240
x264 [info]: using cpu capabilities: MMX2 SSE2Fast SSSE3 Cache64
x264 [info]: profile Main, level 3.0
No accelerated IMDCT transform found
No accelerated IMDCT transform found
No accelerated IMDCT transform found
No accelerated IMDCT transform found
[17:32:50] sync: expecting 178269 video frames
[17:32:50] reader: first SCR 146
[17:32:50] a52_syncinfo failed
[17:32:50] a52_syncinfo ok
[17:32:50] a52_syncinfo failed
[17:32:50] a52_syncinfo ok
[17:32:50] mpeg2: "Chapter  1" (1) at frame 0 time 3003
[17:32:50] sync: first pts is 3003
[17:32:50] sync: video time didn't advance - dropped 10 frames (delta 408 ms, current 52549, next 53300, dur 751)
[17:37:32] mpeg2: "Chapter  2" (2) at frame 4303 time 16114848
[17:40:02] mpeg2: "Chapter  3" (3) at frame 6976 time 26149373
[17:53:56] mpeg2: "Chapter  4" (4) at frame 18756 time 70368548
[18:00:07] mpeg2: "Chapter  5" (5) at frame 23945 time 89846006
[18:03:01] mpeg2: "Chapter  6" (6) at frame 26782 time 100496145
[18:13:07] mpeg2: "Chapter  7" (7) at frame 35348 time 132650768
[18:23:16] mpeg2: "Chapter  8" (8) at frame 43664 time 163866953
[18:31:43] mpeg2: "Chapter  9" (9) at frame 49484 time 185713778
[18:47:28] mpeg2: "Chapter 10" (10) at frame 63126 time 236922435
[18:53:10] mpeg2: "Chapter 11" (11) at frame 68055 time 255423918
[19:02:10] mpeg2: "Chapter 12" (12) at frame 74746 time 280541010
[19:08:20] mpeg2: "Chapter 13" (13) at frame 79413 time 298059011
[19:15:27] mpeg2: "Chapter 14" (14) at frame 84657 time 317740673
[19:22:26] mpeg2: "Chapter 15" (15) at frame 89711 time 336712125
[19:33:10] mpeg2: "Chapter 16" (16) at frame 97105 time 364467353
[19:41:45] mpeg2: "Chapter 17" (17) at frame 103304 time 387736098
[19:51:52] mpeg2: "Chapter 18" (18) at frame 111087 time 416952285
[19:58:48] mpeg2: "Chapter 19" (19) at frame 115339 time 432913230
[20:11:21] mpeg2: "Chapter 20" (20) at frame 124447 time 467099382
[20:11:21] sync: adding 194 ms of silence to audio 0  start 467095861, next 467078400
[20:11:21] sync: adding 194 ms of silence to audio 1  start 467095861, next 467078400
[20:11:21] sync: adding 142 ms of silence to audio 2  start 467094139, next 467081280
[20:11:21] sync: adding 142 ms of silence to audio 3  start 467094139, next 467081280
[20:16:59] mpeg2: "Chapter 21" (21) at frame 129751 time 487022980
[20:22:19] mpeg2: "Chapter 22" (22) at frame 134283 time 504034975
[20:29:14] mpeg2: "Chapter 23" (23) at frame 139888 time 525073993
[20:39:10] mpeg2: "Chapter 24" (24) at frame 147086 time 552093485
[20:51:25] mpeg2: "Chapter 25" (25) at frame 157219 time 590130985
[21:03:42] mpeg2: "Chapter 26" (26) at frame 164900 time 618962788
[21:08:17] mpeg2: "Chapter 27" (27) at frame 167957 time 630438752
[21:10:06] mpeg2: "Chapter 28" (28) at frame 169328 time 635584393
[21:19:10] dvd: end of cell 28 at block 108
[21:19:11] mpeg2: "Chapter 29" (29) at frame 178417 time 669701474
[21:19:12] reader: done. 3 scr changes
[21:19:12] sync: video time didn't advance - dropped 1 frames (delta 32 ms, current 669752525, next 669752599, dur 74)
[21:19:12] sync: got 178435 frames, 178269 expected
[21:19:12] work: average encoding speed for job is 13.136496 fps
[21:19:16] mpeg2 done: 178447 frames
[21:19:16] render: lost time: 0 (0 frames)
[21:19:16] render: gained time: 0 (0 frames) (0 not accounted for)
x264 [info]: slice I:1907  Avg QP:12.77  size: 52313  PSNR Mean Y:50.22 U:55.61 V:56.41 Avg:51.39 Global:49.86
x264 [info]: slice P:83579 Avg QP:14.25  size: 28637  PSNR Mean Y:47.00 U:52.70 V:53.89 Avg:48.22 Global:46.86
x264 [info]: slice B:92953 Avg QP:15.10  size: 12324  PSNR Mean Y:47.18 U:53.37 V:54.54 Avg:48.45 Global:46.73
x264 [info]: consecutive B-frames: 13.4% 46.3% 17.9% 11.3%  7.0%  2.8%  1.4%
x264 [info]: mb I  I16..4: 22.2%  0.0% 77.8%
x264 [info]: mb P  I16..4:  3.6%  0.0% 16.4%  P16..4: 31.9% 21.6% 13.0%  2.8%  2.4%    skip: 8.3%
x264 [info]: mb B  I16..4:  0.4%  0.0%  2.3%  B16..8: 34.0%  5.7%  6.2%  direct:17.5%  skip:33.9%  L0:30.8% L1:40.4% BI:28.8%
x264 [info]: final ratefactor: 11.65
x264 [info]: direct mvs  spatial:99.2%  temporal:0.8%
x264 [info]: ref P L0  76.1% 14.3%  9.7%
x264 [info]: ref B L0  85.6% 14.4%
x264 [info]: SSIM Mean Y:0.9926723
x264 [info]: PSNR Mean Y:47.130 U:53.080 V:54.253 Avg:48.373 Global:46.814 kb/s:3911.46
[21:19:16] libhb: work result = 0

[jbrjake]

Does it go away if you specify a particular constant framerate?

[VKX]

Oddly enough, this worked. Thanks!

Still wish I didn't have to manually set the framerate though. What if I pick the wrong one?

[jbrjake]

It's a bug, will be fixed in the next release.

The renderer uses a delay buffer when it's using same as source fps and it's not flushed fully.

[VKX]

Actually, I tried a few encodes this morning and that doesn't seem to be fixing the issue. I set the framerate to 23.98 on each of them, but they still came out weird. Mexico 2 for instance, ends at 1:53:44 when the actual end of the encode appears to be at 1:44:30.

[VKX]

oops. See above.

[VKX]

Can anyone help? This is really frustrating.

[jbrjake]

Bump the thread again and it gets locked, valid bug or no.

[VKX]

Sorry! That really wasn't my intention.

So I found some further information . . . when I encoded something yesterday, I didn't have that problem. I think the only major difference in the encode is that it didn't have multiple audio tracks.

Here's the log.

Code: Select all

HandBrake Activity Log for /Users/user/Desktop/Touch of Evil.m4v: 2009-01-23 00:00:10 -0600
Handbrake Version: 0.9.3 (2008112300)

[00:00:10] macgui: Rip: Pending queue count is 0
[00:00:10] macgui: Rip: No pending jobs, so sending this one to doAddToQueue
[00:00:10] macgui: Rip: Going right to performNewQueueScan
[00:00:10] macgui: scanning specifically for title: 1
[00:00:10] macgui: performNewQueueScan currentQueueEncodeIndex is: 0
[00:00:10] hb_scan: path=/Users/user/Downloads/Touch of Evil.dvdmedia, title_index=1
[00:00:10] scan: trying to open with libdvdread
[00:00:10] scan: DVD has 6 title(s)
[00:00:10] scan: scanning title 1
[00:00:10] scan: opening IFO for VTS 1
[00:00:10] pgc_id: 1, pgn: 1: pgc: 0x1790d1c0
[00:00:10] scan: vts=1, ttn=1, cells=0->18, blocks=0->2001932, 2001933 blocks
[00:00:10] scan: duration is 01:50:41 (6641100 ms)
[00:00:10] scan: checking audio 1
[00:00:10] scan: id=80bd, lang=English (AC3), 3cc=eng ext=0
[00:00:10] scan: checking subtitle 1
[00:00:10] scan: id=20bd, lang=English, 3cc=eng
[00:00:10] scan: checking subtitle 2
[00:00:10] scan: id=21bd, lang=Francais, 3cc=fra
[00:00:10] scan: checking subtitle 3
[00:00:10] scan: id=22bd, lang=Espanol, 3cc=spa
[00:00:10] scan: title 1 has 19 chapters
[00:00:10] scan: chap 1 c=0->0, b=0->16575 (16576), 47254 ms
[00:00:10] scan: chap 2 c=1->1, b=16576->168464 (151889), 437452 ms
[00:00:10] scan: chap 3 c=2->2, b=168465->322350 (153886), 476524 ms
[00:00:10] scan: chap 4 c=3->3, b=322351->441400 (119050), 424530 ms
[00:00:10] scan: chap 5 c=4->4, b=441401->518331 (76931), 262377 ms
[00:00:10] scan: chap 6 c=5->5, b=518332->605455 (87124), 269196 ms
[00:00:10] scan: chap 7 c=6->6, b=605456->673975 (68520), 224340 ms
[00:00:10] scan: chap 8 c=7->7, b=673976->902856 (228881), 697686 ms
[00:00:10] scan: chap 9 c=8->8, b=902857->1039521 (136665), 403294 ms
[00:00:10] scan: chap 10 c=9->9, b=1039522->1087513 (47992), 168323 ms
[00:00:10] scan: chap 11 c=10->10, b=1087514->1183249 (95736), 333419 ms
[00:00:10] scan: chap 12 c=11->11, b=1183250->1315275 (132026), 433326 ms
[00:00:10] scan: chap 13 c=12->12, b=1315276->1488626 (173351), 622675 ms
[00:00:10] scan: chap 14 c=13->13, b=1488627->1745829 (257203), 850654 ms
[00:00:10] scan: chap 15 c=14->14, b=1745830->1785790 (39961), 146106 ms
[00:00:10] scan: chap 16 c=15->15, b=1785791->1940907 (155117), 609445 ms
[00:00:10] scan: chap 17 c=16->16, b=1940908->1958106 (17199), 73129 ms
[00:00:10] scan: chap 18 c=17->17, b=1958107->2001927 (43821), 160360 ms
[00:00:10] scan: chap 19 c=18->18, b=2001928->2001932 (5), 1000 ms
[00:00:10] scan: aspect = 0
[00:00:10] scan: decoding previews for title 1
[00:00:10] scan: audio 0x80bd: AC-3, rate=48000Hz, bitrate=192000 English (AC3) (Dolby Surround)
[00:00:12] scan: 10 previews, 720x480, 23.976 fps, autocrop = 8/12/0/0, aspect 16:9, PAR 32:27
[00:00:12] scan: title (0) job->width:720, job->height:384
[00:00:12] libhb: scan thread found 1 valid title(s)
[00:00:13] macgui: ScanDone state received from fQueueEncodeLibhb
[00:00:13] macgui: processNewQueueEncode title list is: 1
[00:00:13] macgui: Preset: Custom
[00:00:13] macgui: processNewQueueEncode number of passes expected is: 1
[00:00:13] macgui: prepareJob exiting
[00:00:13] 1 job(s) to process
[00:00:13] starting job
[00:00:13] job configuration:
[00:00:13]  * source
[00:00:13]    + /Users/user/Downloads/Touch of Evil.dvdmedia
[00:00:13]    + title 1, chapter(s) 1 to 19
[00:00:13]  * destination
[00:00:13]    + /Users/user/Desktop/Touch of Evil.m4v
[00:00:13]    + container: MPEG-4 (.mp4 and .m4v)
[00:00:13]      + 64-bit formatting
[00:00:13]      + chapter markers
[00:00:13]  * video track
[00:00:13]    + decoder: mpeg2
[00:00:13]      + bitrate 9800 kbps
[00:00:13]    + frame rate: same as source (around 23.976 fps)
[00:00:13]    + dimensions: 720 * 480 -> 720 * 400, crop 8/12/10/10
[00:00:13]    + filter
[00:00:13]      + Deinterlaces selectively with yadif/mcdeint and lowpass5 blending (1:2:6:9:80:16:16)
[00:00:13]    + encoder: x264
[00:00:13]      + options: level=30:cabac=0:ref=3:mixed-refs=1:bframes=6:weightb=1:direct=auto:no-fast-pskip=1:me=umh:subq=7:analyse=all
[00:00:13]      + bitrate: 4000 kbps, pass: 0
[00:00:13]  * audio track 0
[00:00:13]    + decoder: English (AC3) (Dolby Surround) (track 1, id 80bd)
[00:00:13]      + bitrate: 192 kbps, samplerate: 48000 Hz
[00:00:13]    + mixdown: Dolby Surround
[00:00:13]    + encoder: faac
[00:00:13]      + bitrate: 160 kbps, samplerate: 48000 Hz
[00:00:13] yadif thread started for segment 0
[00:00:13] yadif thread started for segment 1
[00:00:13] decomb thread started for segment 0
[00:00:13] decomb thread started for segment 1
[00:00:13] encx264: keyint-min: 24, keyint-max: 240
x264 [info]: using cpu capabilities: MMX2 Cache64
x264 [info]: profile Main, level 3.0
No accelerated IMDCT transform found
[00:00:13] reader: first SCR 146
[00:00:13] mpeg2: "Chapter  1" (1) at frame 0 time 3003
[00:00:13] sync: expecting 159251 video frames
[00:00:13] a52_syncinfo failed
[00:00:13] a52_syncinfo ok
[00:00:13] 0.066733s: Film -> Video
[00:00:13] sync: first pts is 3003
[00:00:13] sync: video time didn't advance - dropped 10 frames (delta 325 ms, current 42042, next 42792, dur 750)
[00:00:14] 2.227211s: Video -> Film
[00:02:07] mpeg2: "Chapter  2" (2) at frame 1166 time 4290535
[00:20:01] 427.952545s: Film -> Video
[00:20:02] 428.152710s: Video -> Film
[00:22:29] mpeg2: "Chapter  3" (3) at frame 11658 time 43671877
[00:33:14] 742.316528s: Film -> Video
[00:33:14] 742.466736s: Video -> Film
[00:42:44] mpeg2: "Chapter  4" (4) at frame 23095 time 86599762
[00:49:26] 1135.042236s: Film -> Video
[00:49:32] 1136.727295s: Video -> Film
[00:59:53] mpeg2: "Chapter  5" (5) at frame 33302 time 124876000
[01:04:40] 1501.274658s: Film -> Video
[01:04:40] 1501.424927s: Video -> Film
[01:10:51] mpeg2: "Chapter  6" (6) at frame 39611 time 148554655
[01:23:00] mpeg2: "Chapter  7" (7) at frame 46067 time 172788865
[01:26:51] 2004.277344s: Film -> Video
[01:26:51] 2004.427368s: Video -> Film
[01:32:59] mpeg2: "Chapter  8" (8) at frame 51456 time 193014070
[01:50:26] 2537.309570s: Film -> Video
[01:50:27] 2537.459961s: Video -> Film
[02:03:32] mpeg2: "Chapter  9" (9) at frame 68197 time 255851845
[02:21:38] mpeg2: "Chapter 10" (10) at frame 77869 time 292158115
[02:28:58] mpeg2: "Chapter 11" (11) at frame 81906 time 307311253
[02:46:47] mpeg2: "Chapter 12" (12) at frame 89910 time 337356268
[02:47:16] 3756.060547s: Film -> Video
[02:47:16] 3756.210938s: Video -> Film
[03:06:57] mpeg2: "Chapter 13" (13) at frame 100311 time 376395268
[03:28:47] 4700.871094s: Film -> Video
[03:28:48] 4701.020996s: Video -> Film
[03:33:05] mpeg2: "Chapter 14" (14) at frame 115261 time 432509326
[03:47:22] 5125.795410s: Film -> Video
[03:47:22] 5125.945801s: Video -> Film
[04:04:51] 5464.967773s: Film -> Video
[04:05:25] 5475.828613s: Video -> Film
[04:13:24] mpeg2: "Chapter 15" (15) at frame 135728 time 509088829
[04:19:25] mpeg2: "Chapter 16" (16) at frame 139232 time 522241969
[04:21:50] 5859.562012s: Film -> Video
[04:21:51] 5859.711914s: Video -> Film
[04:45:28] mpeg2: "Chapter 17" (17) at frame 153849 time 577106779
[04:48:34] 6485.187012s: Film -> Video
[04:48:35] mpeg2: "Chapter 18" (18) at frame 155614 time 583717884
[04:48:36] 6485.837402s: Video -> Film
[04:54:00] dvd: end of cell 18 at block 2001928
[04:54:00] reader: done. 2 scr changes
[04:54:05] 6646.331055s: Film -> Video
[04:54:06] mpeg2: "Chapter 19" (19) at frame 159467 time 598175825
[04:54:06] 6646.397949s: Video -> Film
[04:54:08] sync: got 159457 frames, 159251 expected
[04:54:08] work: average encoding speed for job is 9.042069 fps
[04:54:11] mpeg2 done: 159468 frames
[04:54:11] render: lost time: 0 (0 frames)
[04:54:11] render: gained time: 0 (0 frames) (0 not accounted for)
x264 [info]: slice I:1179  Avg QP:11.22  size: 45039  PSNR Mean Y:50.76 U:100.00 V:100.00 Avg:52.52 Global:52.25
x264 [info]: slice P:68527 Avg QP:12.22  size: 28517  PSNR Mean Y:48.55 U:100.00 V:100.00 Avg:50.31 Global:50.07
x264 [info]: slice B:89751 Avg QP:13.82  size: 14514  PSNR Mean Y:47.28 U:100.00 V:100.00 Avg:49.04 Global:48.77
x264 [info]: consecutive B-frames: 12.3% 33.6% 16.7% 23.0% 13.5%  0.6%  0.2%
x264 [info]: mb I  I16..4: 21.0%  0.0% 79.0%
x264 [info]: mb P  I16..4:  3.5%  0.0% 12.6%  P16..4: 28.9% 32.1% 17.7%  1.8%  2.8%    skip: 0.6%
x264 [info]: mb B  I16..4:  0.4%  0.0%  1.5%  B16..8: 45.5%  7.0%  8.7%  direct:22.4%  skip:14.5%  L0:30.3% L1:42.2% BI:27.5%
x264 [info]: final ratefactor: 13.55
x264 [info]: direct mvs  spatial:100.0%  temporal:0.0%
x264 [info]: ref P L0  72.4% 16.2% 11.4%
x264 [info]: ref B L0  87.5% 12.5%
x264 [info]: SSIM Mean Y:0.9894257
x264 [info]: PSNR Mean Y:47.849 U:100.000 V:100.000 Avg:49.609 Global:49.302 kb/s:3981.40
[04:54:11] decomb: yadif deinterlaced 55 | blend deinterlaced 44 | unfiltered 159357 | total 159456
[04:54:11] libhb: work result = 0

[van]

The other big difference is that you've changed the sample rate on the main audio track. Your original log said you were resampling the main audio from 48KHz to 44.1KHz:

Code: Select all

[17:32:49]  * audio track 0
[17:32:49]    + decoder: English (AC3) (5.1 ch) (track 1, id 80bd)
[17:32:49]      + bitrate: 448 kbps, samplerate: 48000 Hz
[17:32:49]    + mixdown: Dolby Pro Logic II
[17:32:49]    + encoder: faac
[17:32:49]      + bitrate: 128 kbps, samplerate: 44100 Hz

The resampling is a bad idea since it lowers audio quality. And 44.1 KHz is an unfortunate rate since it doesn't evenly divide the 90KHz MPEG2 clock so there will truncation errors when the DVD timestamps are translated to match the sample rate of this track (this is why 44.1 audio is not legal on DVDs). Also the AC3 pass-thru audio was 48KHz which pretty much guarantees that all the output audio tracks are different lengths and the player will have to deal with two different timebases simultaneously (I'd be surprised if it did this perfectly).

You might try the encode with all 4 audio tracks but make them all 48KHz

[VKX]

FINALLY!

Alright, that seems to resolve the issue. Weird. I'll let you know if I run into this problem using 48k...