Stick at 100% for a loooong Time

[C6Silver]

I've been using Handbrake for a long time and have had this issue for a long time but just getting around to asking about it now. I have been ripping my DVD collection for quite some time and I use the same settings, process, and location for all (500+) I find that many times, although certainly not all, when the process gets to 100% it will remain there for potentially many hours. The file will grow slowly in size but the CPU's are not engaged as they are when the process is decoding. The disc is also not being read. Eventually it does end and the file works but, as in the case of the log below, whatever it is doing at 100% can take longer than the entire process that proceeded it. With many others, however, it ends when it gets to 100% without this long waiting period. I've done many searches about this and can find some threads but no real answers. Hopefully the log below can tell someone something about what is happening and why it doesn't happen every time.

Thanks.

---------------

Code: Select all

HandBrake 0.9.9.5530 - 64bit Version
OS: Microsoft Windows NT 6.1.7601 Service Pack 1
CPU: Intel(R) Core(TM)2 Quad CPU    Q6600  @ 2.40GHz
Ram: 4095 MB, Screen: 1920x1200
Temp Dir: C:\Users\Firefox\AppData\Local\Temp\
Install Dir: C:\Program Files\Handbrake
Data Dir: C:\Users\Firefox\AppData\Roaming\HandBrake\HandBrake\0.9.9.5530

-------------------------------------------
CLI Query:  -i "E:\\" -t 1 --angle 1 -c 1-19 -o "\\MEDIASERVER\video\Movies\movie.m4v"  -f m4v  -4  --decomb -w 720 --loose-anamorphic  --modulus 2 -e x264 -q 20 --vfr -a 1,1 -E faac,copy:ac3 -6 dpl2,auto -R Auto,Auto -B 160,0 -D 0,0 --gain 0,0 --audio-fallback ffac3 --markers="C:\Users\Firefox\AppData\Local\Temp\movie-1-chapters.csv" --x264-profile=high  --h264-level="4.1"  --verbose=1
User Query: False

[13:24:36] hb_init: starting libhb thread
HandBrake 0.9.9 (2013052900) - MinGW x86_64 - http://handbrake.fr
4 CPUs detected
Opening E:\...
[13:24:36] hb_scan: path=E:\, title_index=1
libbluray/bdnav/index_parse.c:162: indx_parse(): error opening E:\/BDMV/index.bdmv
libbluray/bdnav/index_parse.c:162: indx_parse(): error opening E:\/BDMV/BACKUP/index.bdmv
libbluray/bluray.c:1725: nav_get_title_list(E:\) failed (000000000031E4D0)
[13:24:36] bd: not a bd - trying as a stream/file instead
libdvdnav: Using dvdnav version 4.1.3
libdvdread: Using libdvdcss version 1.2.11 for DVD access
NAME OPEN FAILED
libdvdnav: Unable to find home directorylibdvdnav: DVD disk reports itself with Region mask 0x00fe0000. Regions: 1
libdvdread: Using libdvdcss version 1.2.11 for DVD access
[13:24:36] scan: DVD has 10 title(s)
[13:24:36] scan: scanning title 1
[13:24:36] scan: opening IFO for VTS 4
[13:24:36] scan: duration is 01:20:08 (4808020 ms)
[13:24:36] pgc_id: 1, pgn: 1: pgc: 000000000032A980
[13:24:36] scan: vts=4, ttn=1, cells=0->18, blocks=2766->1918813, 1916048 blocks
[13:24:36] scan: checking audio 1
[13:24:36] scan: id=0x80bd, lang=English (AC3), 3cc=eng ext=0
[13:24:36] scan: checking audio 2
[13:24:36] scan: id=0x81bd, lang=Espanol (AC3), 3cc=spa ext=0
[13:24:36] scan: checking subtitle 1
[13:24:36] scan: id=0x21bd, lang=English, 3cc=eng ext=0
[13:24:36] scan: checking subtitle 2
[13:24:36] scan: id=0x23bd, lang=Francais, 3cc=fra ext=0
[13:24:36] scan: checking subtitle 3
[13:24:36] scan: id=0x25bd, lang=Espanol, 3cc=spa ext=0
[13:24:36] scan: title 1 has 19 chapters
[13:24:36] scan: chap 1 c=0->0, b=2766->99293 (96528), 246502 ms
[13:24:36] scan: chap 2 c=1->1, b=99294->241355 (142062), 341400 ms
[13:24:36] scan: chap 3 c=2->2, b=241356->359093 (117738), 275458 ms
[13:24:36] scan: chap 4 c=3->3, b=359094->473197 (114104), 302398 ms
[13:24:36] scan: chap 5 c=4->4, b=473198->559050 (85853), 209559 ms
[13:24:36] scan: chap 6 c=5->5, b=559051->650513 (91463), 227280 ms
[13:24:36] scan: chap 7 c=6->6, b=650514->780578 (130065), 299375 ms
[13:24:36] scan: chap 8 c=7->7, b=780579->876013 (95435), 240585 ms
[13:24:36] scan: chap 9 c=8->8, b=876014->981985 (105972), 280330 ms
[13:24:36] scan: chap 10 c=9->9, b=981986->1067051 (85066), 227280 ms
[13:24:36] scan: chap 11 c=10->10, b=1067052->1150078 (83027), 221453 ms
[13:24:36] scan: chap 12 c=11->11, b=1150079->1286864 (136786), 349399 ms
[13:24:36] scan: chap 13 c=12->12, b=1286865->1368810 (81946), 210393 ms
[13:24:36] scan: chap 14 c=13->13, b=1368811->1465037 (96227), 247459 ms
[13:24:36] scan: chap 15 c=14->14, b=1465038->1510139 (45102), 116333 ms
[13:24:36] scan: chap 16 c=15->15, b=1510140->1614849 (104710), 262466 ms
[13:24:36] scan: chap 17 c=16->16, b=1614850->1731699 (116850), 282456 ms
[13:24:36] scan: chap 18 c=17->17, b=1731700->1850935 (119236), 280496 ms
[13:24:36] scan: chap 19 c=18->18, b=1850936->1918813 (67878), 187390 ms
[13:24:36] scan: aspect = 1.77778
[13:24:36] scan: decoding previews for title 1
libdvdnav: DVD disk reports itself with Region mask 0x00fe0000. Regions: 1
libdvdnav: Suspected RCE Region Protection!!!
Scanning title 1 of 1, preview 1, 0.00 %[13:24:37] scan: title angle(s) 1
libdvdread: Attempting to retrieve all CSS keys
libdvdread: This can take a _long_ time, please be patient
libdvdread: Get key for /VIDEO_TS/VTS_01_1.VOB at 0x000001b1
libdvdread: Elapsed time 0
libdvdread: Get key for /VIDEO_TS/VTS_02_1.VOB at 0x000834b6
libdvdread: Elapsed time 0
libdvdread: Get key for /VIDEO_TS/VTS_03_1.VOB at 0x00087a46
libdvdread: Elapsed time 0
libdvdread: Get key for /VIDEO_TS/VTS_04_0.VOB at 0x0009399f
libdvdread: Elapsed time 0
libdvdread: Get key for /VIDEO_TS/VTS_04_1.VOB at 0x00094d0f
libdvdread: Elapsed time 0
libdvdread: Get key for /VIDEO_TS/VTS_05_1.VOB at 0x002694a4
libdvdread: Elapsed time 0
libdvdread: Found 5 VTS's
libdvdread: Elapsed time 0
Scanning title 1 of 1, preview 1, 10.00 %[13:24:37] scan: audio 0x81bd: AC-3, rate=48000Hz, bitrate=448000 Espanol (AC3) (5.1 ch)
[13:24:37] scan: audio 0x80bd: AC-3, rate=48000Hz, bitrate=448000 English (AC3) (5.1 ch)
Scanning title 1 of 1, preview 2, 20.00 %
Scanning title 1 of 1, preview 3, 30.00 %
Scanning title 1 of 1, preview 5, 50.00 %
Scanning title 1 of 1, preview 6, 60.00 %
Scanning title 1 of 1, preview 8, 80.00 %
Scanning title 1 of 1, preview 9, 90.00 %[13:24:38] scan: 10 previews, 720x480, 23.976 fps, autocrop = 0/0/0/0, aspect 16:9, PAR 32:27
[13:24:38] libhb: scan thread found 1 valid title(s)
+ title 1:
  + vts 4, ttn 1, cells 0->18 (1916048 blocks)
  + duration: 01:20:08
  + size: 720x480, pixel aspect: 32/27, display aspect: 1.78, 23.976 fps
  + autocrop: 0/0/0/0
  + chapters:
    + 1: cells 0->0, 96528 blocks, duration 00:04:07
    + 2: cells 1->1, 142062 blocks, duration 00:05:41
    + 3: cells 2->2, 117738 blocks, duration 00:04:35
    + 4: cells 3->3, 114104 blocks, duration 00:05:02
    + 5: cells 4->4, 85853 blocks, duration 00:03:30
    + 6: cells 5->5, 91463 blocks, duration 00:03:47
    + 7: cells 6->6, 130065 blocks, duration 00:04:59
    + 8: cells 7->7, 95435 blocks, duration 00:04:01
    + 9: cells 8->8, 105972 blocks, duration 00:04:40
    + 10: cells 9->9, 85066 blocks, duration 00:03:47
    + 11: cells 10->10, 83027 blocks, duration 00:03:41
    + 12: cells 11->11, 136786 blocks, duration 00:05:49
    + 13: cells 12->12, 81946 blocks, duration 00:03:30
    + 14: cells 13->13, 96227 blocks, duration 00:04:07
    + 15: cells 14->14, 45102 blocks, duration 00:01:56
    + 16: cells 15->15, 104710 blocks, duration 00:04:22
    + 17: cells 16->16, 116850 blocks, duration 00:04:42
    + 18: cells 17->17, 119236 blocks, duration 00:04:40
    + 19: cells 18->18, 67878 blocks, duration 00:03:07
  + audio tracks:
    + 1, English (AC3) (5.1 ch) (iso639-2: eng), 48000Hz, 448000bps
    + 2, Espanol (AC3) (5.1 ch) (iso639-2: spa), 48000Hz, 448000bps
  + subtitle tracks:
    + 1, English (iso639-2: eng) (Bitmap)(VOBSUB)
    + 2, Francais (iso639-2: fra) (Bitmap)(VOBSUB)
    + 3, Espanol (iso639-2: spa) (Bitmap)(VOBSUB)
    + 4, Closed Captions (iso639-2: eng) (Text)(CC)
Reading chapter markers from file C:\Users\Firefox\AppData\Local\Temp\movie-1-chapters.csv
[13:24:38] 1 job(s) to process
[13:24:38] starting job
[13:24:38] yadif thread started for segment 0
[13:24:38] yadif thread started for segment 1
[13:24:38] yadif thread started for segment 2
[13:24:38] yadif thread started for segment 3
[13:24:38] decomb filter thread started for segment 0
[13:24:38] decomb filter thread started for segment 1
[13:24:38] decomb filter thread started for segment 2
[13:24:38] decomb filter thread started for segment 3
[13:24:38] decomb check thread started for segment 0
[13:24:38] decomb check thread started for segment 1
[13:24:38] decomb check thread started for segment 2
[13:24:38] decomb check thread started for segment 3
[13:24:38] mask filter thread started for segment 0
[13:24:38] mask filter thread started for segment 1
[13:24:38] mask filter thread started for segment 2
[13:24:38] mask filter thread started for segment 3
[13:24:38] mask erode thread started for segment 0
[13:24:38] mask erode thread started for segment 1
[13:24:38] mask erode thread started for segment 2
[13:24:38] mask erode thread started for segment 3
[13:24:38] mask dilate thread started for segment 0
[13:24:38] mask dilate thread started for segment 1
[13:24:38] mask dilate thread started for segment 2
[13:24:38] mask dilate thread started for segment 3
[13:24:38] sync: expecting 115277 video frames
[13:24:38] job configuration:
[13:24:38]  * source
[13:24:38]    + E:\
[13:24:38]    + title 1, chapter(s) 1 to 19
[13:24:38]  * destination
[13:24:38]    + \\MEDIASERVER\video\Movies\movie.m4v
[13:24:38]    + container: MPEG-4 (.mp4 and .m4v)
[13:24:38]      + 64-bit formatting
[13:24:38]      + chapter markers
[13:24:38]  * video track
[13:24:38]    + decoder: mpeg2
[13:24:38]      + bitrate 7500 kbps
[13:24:38]    + frame rate: same as source (around 23.976 fps)
[13:24:38]    + filters
[13:24:38]      + Decomb (default settings)
[13:24:38]      + Framerate Shaper (0:27000000:1126125)
[13:24:38]        + frame rate: same as source (around 23.976 fps)
[13:24:38]      + Crop and Scale (720:480:0:0:0:0)
[13:24:38]        + source: 720 * 480, crop (0/0/0/0): 720 * 480, scale: 720 * 480
[13:24:38]    + loose anamorphic
[13:24:38]      + storage dimensions: 720 * 480, mod 2
[13:24:38]      + pixel aspect ratio: 32 / 27
[13:24:38]      + display dimensions: 853 * 480
[13:24:38]    + encoder: H.264 (x264)
[13:24:38]      + h264 profile: high
[13:24:38]      + h264 level: 4.1
[13:24:38]      + quality: 20.00 (RF)
[13:24:38]  * audio track 1
[13:24:38]    + decoder: English (AC3) (5.1 ch) (track 1, id 0x80bd)
[13:24:38]      + bitrate: 448 kbps, samplerate: 48000 Hz
[13:24:38]    + mixdown: Dolby Pro Logic II
[13:24:38]    + encoder: AAC (faac)
[13:24:38]      + bitrate: 160 kbps, samplerate: 48000 Hz
[13:24:38]  * audio track 2
[13:24:38]    + decoder: English (AC3) (5.1 ch) (track 1, id 0x80bd)
[13:24:38]      + bitrate: 448 kbps, samplerate: 48000 Hz
[13:24:38]    + AC3 Passthru
libdvdnav: Using dvdnav version 4.1.3
libdvdread: Using libdvdcss version 1.2.11 for DVD access
NAME OPEN FAILED
libdvdnav: Unable to find home directorylibdvdnav: DVD disk reports itself with Region mask 0x00fe0000. Regions: 1
libdvdread: Using libdvdcss version 1.2.11 for DVD access
libdvdnav: DVD disk reports itself with Region mask 0x00fe0000. Regions: 1
libdvdnav: Suspected RCE Region Protection!!!
[13:24:39] encx264: min-keyint: 24, keyint: 240
[13:24:39] encx264: encoding with stored aspect 32/27
[13:24:39] encx264: Encoding at constant RF 20.000000
x264 [warning]: --psnr used with psy on: results will be invalid!
x264 [warning]: --tune psnr should be used if attempting to benchmark psnr!
x264 [info]: using SAR=32/27
x264 [info]: using cpu capabilities: MMX2 SSE2Fast SSSE3 Cache64 SlowShuffle
x264 [info]: profile High, level 4.1
libdvdread: Attempting to retrieve all CSS keys
libdvdread: This can take a _long_ time, please be patient
libdvdread: Get key for /VIDEO_TS/VTS_01_1.VOB at 0x000001b1
libdvdread: Elapsed time 0
libdvdread: Get key for /VIDEO_TS/VTS_02_1.VOB at 0x000834b6
libdvdread: Elapsed time 0
libdvdread: Get key for /VIDEO_TS/VTS_03_1.VOB at 0x00087a46
libdvdread: Elapsed time 0
libdvdread: Get key for /VIDEO_TS/VTS_04_0.VOB at 0x0009399f
libdvdread: Elapsed time 0
libdvdread: Get key for /VIDEO_TS/VTS_04_1.VOB at 0x00094d0f
libdvdread: Elapsed time 0
libdvdread: Get key for /VIDEO_TS/VTS_05_1.VOB at 0x002694a4
libdvdread: Elapsed time 0
libdvdread: Found 5 VTS's
libdvdread: Elapsed time 0
[13:24:39] reader: first SCR 146 id 0xe0 DTS 1092
[13:24:39] mpeg2: "Chapter 1" (1) at frame 0 time 10510
[13:24:39] sync: first pts is 10510
[13:26:59] mpeg2: "Chapter 2" (2) at frame 5923 time 22243221
[13:30:31] mpeg2: "Chapter 3" (3) at frame 14115 time 52993941
[13:33:15] mpeg2: "Chapter 4" (4) at frame 20725 time 77806228
[13:36:01] mpeg2: "Chapter 5" (5) at frame 27991 time 105080976
[13:38:11] mpeg2: "Chapter 6" (6) at frame 33029 time 123992368
[13:40:20] mpeg2: "Chapter 7" (7) at frame 38494 time 144507363
[13:43:50] mpeg2: "Chapter 8" (8) at frame 45670 time 171444273
[13:46:36] mpeg2: "Chapter 9" (9) at frame 51446 time 193125933
[13:49:37] mpeg2: "Chapter 10" (10) at frame 58174 time 218381163
[13:51:49] mpeg2: "Chapter 11" (11) at frame 63638 time 238891653
[13:54:08] mpeg2: "Chapter 12" (12) at frame 68947 time 258819561
[13:57:48] sync: audio 0x80bd time went backwards 32 ms, dropped 1 frames (start 290255040, next 290257920)
[13:57:48] sync: audio 0x80bd time went backwards 32 ms, dropped 1 frames (start 290255040, next 290257920)
[13:57:48] mpeg2: "Chapter 13" (13) at frame 77322 time 290257968
[14:00:00] mpeg2: "Chapter 14" (14) at frame 82382 time 309249063
[14:02:48] mpeg2: "Chapter 15" (15) at frame 88321 time 331541833
[14:03:53] mpeg2: "Chapter 16" (16) at frame 91111 time 342014796
[14:06:22] mpeg2: "Chapter 17" (17) at frame 97403 time 365633391
[14:09:01] mpeg2: "Chapter 18" (18) at frame 104174 time 391050783
[14:11:51] mpeg2: "Chapter 19" (19) at frame 110905 time 416316523
libdvdnav: Language 'en' not found, using 'ÿÿ' instead
libdvdnav: Menu Languages available: ÿÿ 
[14:12:50] reader: done. 2 scr changes
[14:13:01] work: average encoding speed for job is 39.910435 fps
[14:13:02] sync: got 115404 frames, 115277 expected
[14:13:02] decomb: deinterlaced 0 | blended 0 | unfiltered 115403 | total 115403
[14:13:02] render: lost time: 0 (0 frames)
[14:13:02] render: gained time: 0 (0 frames) (0 not accounted for)
[14:13:02] mpeg2 done: 115404 frames
x264 [info]: frame I:995   Avg QP:17.36  size: 31255  PSNR Mean Y:48.70 U:49.99 V:51.59 Avg:49.20 Global:48.52
x264 [info]: frame P:57007 Avg QP:20.34  size: 11373  PSNR Mean Y:45.35 U:47.40 V:48.99 Avg:46.03 Global:45.61
x264 [info]: frame B:57401 Avg QP:22.87  size:  2982  PSNR Mean Y:43.81 U:46.74 V:48.22 Avg:44.64 Global:44.09
x264 [info]: consecutive B-frames: 21.7% 28.6% 22.6% 27.2%
x264 [info]: mb I  I16..4:  4.8% 91.7%  3.5%
x264 [info]: mb P  I16..4:  1.0% 12.5%  0.2%  P16..4: 46.7% 19.0% 12.2%  0.0%  0.0%    skip: 8.4%
x264 [info]: mb B  I16..4:  0.1%  0.7%  0.0%  B16..8: 46.6%  4.2%  0.8%  direct: 3.6%  skip:43.9%  L0:38.8% L1:51.1% BI:10.1%
x264 [info]: 8x8 transform intra:90.9% inter:83.7%
x264 [info]: coded y,uvDC,uvAC intra: 82.3% 80.6% 34.6% inter: 32.4% 42.6% 3.2%
x264 [info]: i16 v,h,dc,p: 26% 18% 11% 44%
x264 [info]: i8 v,h,dc,ddl,ddr,vr,hd,vl,hu: 14% 14% 45%  4%  4%  5%  4%  5%  5%
x264 [info]: i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 23% 15% 15%  6% 10% 11%  8%  8%  6%
x264 [info]: i8c dc,h,v,p: 55% 21% 19%  6%
x264 [info]: Weighted P-Frames: Y:6.2% UV:1.9%
x264 [info]: ref P L0: 53.6% 14.3% 22.1%  9.5%  0.4%
x264 [info]: ref B L0: 80.7% 17.5%  1.8%
x264 [info]: ref B L1: 94.9%  5.1%
x264 [info]: SSIM Mean Y:0.9779653 (16.569db)
x264 [info]: PSNR Mean Y:44.609 U:47.093 V:48.630 Avg:45.362 Global:44.798 kb/s:1413.72
[15:52:06] mux: track 0, 115403 frames, 850549720 bytes, 1413.61 kbps, fifo 2048
[15:52:06] mux: track 1, 225631 frames, 96243864 bytes, 159.96 kbps, fifo 4096
[15:52:06] mux: track 2, 150420 frames, 269552640 bytes, 448.00 kbps, fifo 4096
[15:52:06] libhb: work result = 0
Encode done!
HandBrake has exited.

[s55]

The log shows a completed encode that has exited cleanly.

[mduell]

Code: Select all

[13:24:39] reader: first SCR 146 id 0xe0 DTS 1092

[14:12:50] reader: done. 2 scr changes
[14:13:01] work: average encoding speed for job is 39.910435 fps
[14:13:02] sync: got 115404 frames, 115277 expected

[15:52:06] mux: track 0, 115403 frames, 850549720 bytes, 1413.61 kbps, fifo 2048
[15:52:06] mux: track 1, 225631 frames, 96243864 bytes, 159.96 kbps, fifo 4096
[15:52:06] mux: track 2, 150420 frames, 269552640 bytes, 448.00 kbps, fifo 4096
[15:52:06] libhb: work result = 0

It did stay at 100% for over 90 minutes after an encode of less than 50 minutes.

[s55]

Ah yeh, never noticed. Probably related to the fact it's running over a network.

[C6Silver]

The question is why. This is a local network and again I have used this same mechanism and approach for 500+ copies. This does not happen each time and there is nothing common about when it does happen. I've had it happen plenty when I am totally alone in the house with no network activity other than what I am doing. This is also a wired connection.

[Smithcraft]

Might be an issue with the server. Maybe sometimes it's sleeping(low power mode, or maybe indexing drives), and other times it's awake?

SC

[BlueCrypt]

Something similar to this happens to me when I encode some movies at a very low average frame rate (1 and below :O), but I think it is because of queued frames to process or something like that. But it didn't stay for so long (about 5 minutes, depending on situation).

[C6Silver]

When it is at 100% I go and use the drive it is copying to, so it is awake. You can press F5 to see the file grow slightly with each press. The system is definitely awake.

[maxim_d33]

just curious - if output file is placed locally, not over network,
does it change behavior?
OR when output file is point to the mounted drive ( not \\... but like f:\... ) ?

[C6Silver]

just curious - if output file is placed locally, not over network,
does it change behavior?
OR when output file is point to the mounted drive ( not \\... but like f:\... ) ?

Certainly a reasonable question. I've been thinking about trying this and given it doesn't seem others necessarily have seen or know this issue, it will likely be my next step. I will report back.