Batch process cutting sometimes freezes at 99%

stevehiner

New member
I've seen this several times. When it happens I'll be processing a set of (typically) MPEG2 files and one of the files will stop in the Batch Manager at 99%. I end up having to kill the process. When I start it up again the file it stuck on will be in the completed list and the file on disk will appear to be complete and does include the BeyondTV metadata. The log file shows that it completed. It seems like maybe the VRD process is finishing but there is a breakdown in VRD telling the batch manager that it's done.

Here's the tail end of the log from when it just happened:

Code:
2014-12-09 12:34:16 VideoReDo TVSuite started. Licensed to: ST-RCHNJZ-EXE8C2, Version: 5.1.0.717 - Dec  3 2014, AVP On (00cf004d-24}   Windows 7 Ultimate
2014-12-09 12:34:16 Starting up with silent and batch: 1  0
2014-12-09 12:34:26 Destruct CVideoReDoDlgAutoProxy
2014-12-09 12:34:40 Image   support lib: 8.0.1 (r40318), ippVC SSE4.1/4.2 (p8)+
2014-12-09 12:34:40 Decoder support lib: 8.0.1 (r40318), ippVC SSE4.1/4.2 (p8)+
2014-12-09 12:34:41 VideoReDo TVSuite started. Licensed to: ST-RCHNJZ-EXE8C2, Version: 5.1.0.717 - Dec  3 2014, AVP On (00cf004d-24}   Windows 7 Ultimate
2014-12-09 12:34:41 Starting up with silent and batch: 1  0
2014-12-09 12:34:41  
           ***** Loading: F:\The Librarians-(And the Crown of King Arthur; And the Sword in the Stone)-2014-12-07-0.mpg

2014-12-09 12:34:41 Starting stream open for: F:\The Librarians-(And the Crown of King Arthur; And the Sword in the Stone)-2014-12-07-0.mpg
2014-12-09 12:34:41 After aStream open.
2014-12-09 12:34:41 Is DVRMS: 0.
2014-12-09 12:34:41 Seek to begin.
2014-12-09 12:34:41 Packet classes created.
2014-12-09 12:34:41 Opening file: F:\The Librarians-(And the Crown of King Arthur; And the Sword in the Stone)-2014-12-07-0.mpg, filetype is: MPEG2  PIDs: xE0 / xC0 
2014-12-09 12:34:41 Startup - Number of PTS checks: 8
2014-12-09 12:34:41 Using display driver: Silent Mode
2014-12-09 12:34:42 Setting output options from profile: No Recode Required
MPEG-2 Program Stream
2014-12-09 12:34:42 Batch, saving project to: *
2014-12-09 12:34:46 Adding module to graph: Output muxer
2014-12-09 12:34:46 Setting graph input port: 0 to module: Output muxer port: 0 Accepts EOF
2014-12-09 12:34:46 Adding module to graph: Audio divider:output
2014-12-09 12:34:46 Setting graph input port: 1 to module: Audio divider:output port: 0 Accepts EOF
2014-12-09 12:34:46 Adding module to graph: Audio decoder:0
2014-12-09 12:34:46 Connecting output of Audio divider:output (0) to input of Audio decoder:0 (0)
2014-12-09 12:34:46 Connecting output of Audio decoder:0 (0) to input of Output muxer (2)
2014-12-09 12:34:46 Graph, passes required: 1
2014-12-09 12:34:46 Graph, Output encoding bitrate: 4.0000 Mbps
2014-12-09 12:34:46 Graph, Encoding dimension:      720 x 480
2014-12-09 12:34:46 Graph, Cropping rect:           (0 x 0 ) - (720 x 480)
2014-12-09 12:34:46 Graph, Maximum GOP:             0
2014-12-09 12:34:46 StreamProcess: Staring output muxer thread.
2014-12-09 12:34:46 Starting graph filter thread: Audio divider:output
2014-12-09 12:34:46 Starting graph filter thread: Audio decoder:0
2014-12-09 12:34:46 Source video information:
 File:                                     Name : F:\The Librarians-(And the Crown of King Arthur; And the Sword in the Stone)-2014-12-07-0.mpg
                                           Size : 4.339 GB
                                       Duration : 02:07:56.17
                                       Mux type : PS - MPEG2
 Video:                                Encoding : MPEG2
                                  VideoStreamID : xE0
                                     Frame rate : 29.97 fps
                                  Encoding size : 720 x 480
                                   Aspect ratio : 4:3
                                Header bit rate : 4.000 Mbps
                                     VBV buffer : 224 KBytes
                                        Profile : Main@Main
                                    Progressive : Prog or Int
                                         Chroma : 4:2:0
                                       Bit rate : 4.126 Mbps
                                     Captioning : DVD 608
                                    Field order : Top field first
 Audio Stream: 1 (Primary)                Codec : MPEG
                                      MPEGLayer : Layer 2
                                       Channels : 2.0
                                  PES Stream Id : xC0
                                       Bit rate : 224 Kbps
                                  Sampling rate : 48000
                                    Sample size : 16 bits

2014-12-09 12:34:46 Graph monitoring thread started.
2014-12-09 12:34:46 Starting new Frame Accurate Output Segment: start:120386.944 (00:02:00.12),  end:557208.344 (00:09:17.07) 
2014-12-09 12:34:46 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:34:46 Sending status: 'Audio volume changed' to module: 'Output muxer - 0', Type: Video frame
2014-12-09 12:34:46 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:34:46 Sending status: 'Audio volume changed' to module: 'Audio divider:output - 0', Type: Audio frame
2014-12-09 12:34:46 Adding new graph range, Start:     120387 (00:02:00.12), End:  557208.34 (00:09:17.07)
2014-12-09 12:34:46 XXCount: 0, Real: 1 0
2014-12-09 12:34:56 XXCount: 0, Real: 1 0
2014-12-09 12:34:56 Starting new Frame Accurate Output Segment: start:779078.311 (00:12:59.01),  end:1402786.411 (00:23:22.23) 
2014-12-09 12:34:56 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:34:56 Sending status: 'Audio volume changed' to module: 'Output muxer - 0', Type: Video frame
2014-12-09 12:34:56 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:34:56 Sending status: 'Audio volume changed' to module: 'Audio divider:output - 0', Type: Audio frame
2014-12-09 12:34:56 Adding new graph range, Start:     779078 (00:12:59.01), End: 1402786.41 (00:23:22.23)
2014-12-09 12:34:56 XXCount: 0, Real: 1 0
2014-12-09 12:35:09 XXCount: 0, Real: 1 0
2014-12-09 12:35:10 Starting new Frame Accurate Output Segment: start:1614312.711 (00:26:54.09),  end:2100750.344 (00:35:00.23) 
2014-12-09 12:35:10 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:35:10 Sending status: 'Audio volume changed' to module: 'Output muxer - 0', Type: Video frame
2014-12-09 12:35:10 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:35:10 Sending status: 'Audio volume changed' to module: 'Audio divider:output - 0', Type: Audio frame
2014-12-09 12:35:10 Adding new graph range, Start:    1614313 (00:26:54.09), End: 2100750.34 (00:35:00.23)
2014-12-09 12:35:10 XXCount: 0, Real: 1 0
2014-12-09 12:35:21 XXCount: 0, Real: 1 0
2014-12-09 12:35:21 Starting new Frame Accurate Output Segment: start:2292356.744 (00:38:12.12),  end:2643559.278 (00:44:03.17) 
2014-12-09 12:35:21 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:35:21 Sending status: 'Audio volume changed' to module: 'Output muxer - 0', Type: Video frame
2014-12-09 12:35:21 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:35:21 Sending status: 'Audio volume changed' to module: 'Audio divider:output - 0', Type: Audio frame
2014-12-09 12:35:21 Adding new graph range, Start:    2292357 (00:38:12.12), End: 2643559.28 (00:44:03.17)
2014-12-09 12:35:21 XXCount: 0, Real: 1 0
2014-12-09 12:35:30 Starting new Frame Accurate Output Segment: start:2834965.478 (00:47:15.00),  end:3350298.644 (00:55:50.08) 
2014-12-09 12:35:30 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:35:30 Sending status: 'Audio volume changed' to module: 'Output muxer - 0', Type: Video frame
2014-12-09 12:35:30 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:35:30 Sending status: 'Audio volume changed' to module: 'Audio divider:output - 0', Type: Audio frame
2014-12-09 12:35:30 Adding new graph range, Start:    2834965 (00:47:15.00), End: 3350298.64 (00:55:50.08)
2014-12-09 12:35:30 XXCount: 0, Real: 1 0
2014-12-09 12:35:42 XXCount: 0, Real: 1 0
2014-12-09 12:35:42 Starting new Frame Accurate Output Segment: start:3561658.111 (00:59:21.21),  end:4432679.944 (01:13:52.19) 
2014-12-09 12:35:42 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:35:42 Sending status: 'Audio volume changed' to module: 'Output muxer - 0', Type: Video frame
2014-12-09 12:35:42 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:35:42 Sending status: 'Audio volume changed' to module: 'Audio divider:output - 0', Type: Audio frame
2014-12-09 12:35:42 Adding new graph range, Start:    3561658 (00:59:21.21), End: 4432679.94 (01:13:52.19)
2014-12-09 12:35:42 XXCount: 0, Real: 1 0
2014-12-09 12:36:03 XXCount: 0, Real: 1 0
2014-12-09 12:36:03 Starting new Frame Accurate Output Segment: start:4674603.278 (01:17:54.18),  end:5079526.144 (01:24:39.15) 
2014-12-09 12:36:03 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:36:03 Sending status: 'Audio volume changed' to module: 'Output muxer - 0', Type: Video frame
2014-12-09 12:36:03 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:36:03 Sending status: 'Audio volume changed' to module: 'Audio divider:output - 0', Type: Audio frame
2014-12-09 12:36:03 Adding new graph range, Start:    4674603 (01:17:54.18), End: 5079526.14 (01:24:39.15)
2014-12-09 12:36:03 XXCount: 0, Real: 1 0
2014-12-09 12:36:14 XXCount: 0, Real: 1 0
2014-12-09 12:36:14 Starting new Frame Accurate Output Segment: start:5290652.044 (01:28:10.21),  end:5609021.778 (01:33:29.00) 
2014-12-09 12:36:14 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:36:14 Sending status: 'Audio volume changed' to module: 'Output muxer - 0', Type: Video frame
2014-12-09 12:36:14 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:36:14 Sending status: 'Audio volume changed' to module: 'Audio divider:output - 0', Type: Audio frame
2014-12-09 12:36:15 Adding new graph range, Start:    5290652 (01:28:10.21), End: 5609021.78 (01:33:29.00)
2014-12-09 12:36:15 XXCount: 0, Real: 1 0
2014-12-09 12:36:22 Starting new Frame Accurate Output Segment: start:5790284.511 (01:36:30.09),  end:6058337.311 (01:40:58.08) 
2014-12-09 12:36:22 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:36:22 Sending status: 'Audio volume changed' to module: 'Output muxer - 0', Type: Video frame
2014-12-09 12:36:22 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:36:22 Sending status: 'Audio volume changed' to module: 'Audio divider:output - 0', Type: Audio frame
2014-12-09 12:36:22 Adding new graph range, Start:    5790285 (01:36:30.09), End: 6058337.31 (01:40:58.08)
2014-12-09 12:36:27 XXCount: 0, Real: 1 0
2014-12-09 12:36:28 Starting new Frame Accurate Output Segment: start:6269763.511 (01:44:29.23),  end:6688816.444 (01:51:28.24) 
2014-12-09 12:36:28 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:36:28 Sending status: 'Audio volume changed' to module: 'Output muxer - 0', Type: Video frame
2014-12-09 12:36:28 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:36:28 Sending status: 'Audio volume changed' to module: 'Audio divider:output - 0', Type: Audio frame
2014-12-09 12:36:28 Adding new graph range, Start:    6269764 (01:44:29.23), End: 6688816.44 (01:51:28.24)
2014-12-09 12:36:37 XXCount: 0, Real: 1 0
2014-12-09 12:36:37 Starting new Frame Accurate Output Segment: start:6940433.511 (01:55:40.13),  end:7501078.611 (02:05:01.03) 
2014-12-09 12:36:37 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:36:37 Sending status: 'Audio volume changed' to module: 'Output muxer - 0', Type: Video frame
2014-12-09 12:36:37 Preparing to send status to: 0 Audio volume changed
2014-12-09 12:36:37 Sending status: 'Audio volume changed' to module: 'Audio divider:output - 0', Type: Audio frame
2014-12-09 12:36:37 Adding new graph range, Start:    6940434 (01:55:40.13), End: 7501078.61 (02:05:01.03)
2014-12-09 12:36:49 XXCount: 0, Real: 1 0
2014-12-09 12:36:50 Chapter file: C:\Temp\The Librarians-2014-12-07-And the Crown of King Arthur; And the Sword in the Stone_Chapters.txt created
2014-12-09 12:36:50 Audio divider:output: Process thread complete.
2014-12-09 12:36:50 Graph, monitoring thread received terminate signal.
2014-12-09 12:36:50 Audio decoder:0 processing thread complete. In: 218989, Out: 218989
2014-12-09 12:36:50 Output muxer processing thread complete. Video in: 157515, Out: 157515, Buffer: 0
2014-12-09 12:36:50 Graph monitoring thread finished.
2014-12-09 12:36:50 Output muxer processing thread complete. Audio stream 0 In: 218989, Out: 218989, Buffer: 0
2014-12-09 12:36:50 Muxer add / delete audio: stream: 0, add: 0  delete 0, sync:      -3.83
2014-12-09 12:36:50 Program stream muxer, Maximum audio video lag in mux:     133.46 msec
2014-12-09 12:36:51 Output complete. 
                 Input file: F:\The Librarians-(And the Crown of King Arthur; And the Sword in the Stone)-2014-12-07-0.mpg
                Output file: C:\Temp\The Librarians-2014-12-07-And the Crown of King Arthur; And the Sword in the Stone.mpg
                       Mode: Frame Accurate
    Output format: PS
    Video length: 5255
    Video output frames: 157515
    Audio output frames: 218989
    Processing time (secs): 125
    Processed frames/sec: 1260.12
       Actual Video Bitrate: 3.81 Mbps
    -Video output packets: 1303519
    -Audio output packets: 145704
    -Padding output packets: 0
        
2014-12-09 12:48:58 Image   support lib: 8.0.1 (r40318), ippVC SSE4.1/4.2 (p8)+
2014-12-09 12:48:58 Decoder support lib: 8.0.1 (r40318), ippVC SSE4.1/4.2 (p8)+
2014-12-09 12:48:59 VideoReDo TVSuite started. Licensed to: ST-RCHNJZ-EXE8C2, Version: 5.1.0.717 - Dec  3 2014, AVP On (00cf004d-24}   Windows 7 Ultimate
2014-12-09 12:48:59 Checking reg: 120
 

Dan203

Senior Developer
Staff member
Hmmm... looking at the code the only thing that could cause this is a thread timing issue. I'll try throwing a small delay into code and see if that will help prevent the issue. I'll also add some extra logging so we can see exactly where it's hanging up.
 
Top Bottom