The main thing you need to keep in mind is that Deadline does not render the job, Houdini does. With all rendering applications, Deadline simply tells the application what to do, and then sits around and watches for output (STDOUT from the process, or a returns value when running a command line). So it is a bit unfair to blame Deadline for most of the things you wrote, as it tells Houdini to load the scene and render whatever frames you requested. It then has Output Handlers that perform RegEx on the STDOUT to figure out if a frame progress was reported, watch out for known and unknown Error messages in the STDOUT, and react to them.
By default, the Frames Per Task should be 1. The Task progress will only increase if the renderer is actually outputting progress information to STDOUT.
For a non-Houdini example, when V-Ray renders in Maya, you see something like this:
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:07] V-Ray: Additional progressive sampling filter buffers memory usage: 176.81 MB
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 56.9s): 1 % completed
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: Noise threshold goal lowered to 0.142857
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 18.6s): 4 % completed
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: Noise threshold goal lowered to 0.090909
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: Noise threshold goal lowered to 0.052632
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 17.3s): 5 % completed
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: Noise threshold goal lowered to 0.028571
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 15.1s): 6 % completed
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: Noise threshold goal lowered to 0.014925
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 11.1s): 8 % completed
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: Noise threshold goal set: 0.010000
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 5.6s): 16 % completed
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 1.5s): 44 % completed
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 1.1s): 53 % completed
2019-12-03 16:00:08: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 0.8s): 62 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 0.7s): 67 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 0.6s): 70 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 0.5s): 74 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 0.4s): 80 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 0.3s): 84 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 0.2s): 86 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:08] V-Ray: (Estimated time remaining: 0h 0m 0.2s): 88 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:09] V-Ray: (Estimated time remaining: 0h 0m 0.1s): 91 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:09] V-Ray: (Estimated time remaining: 0h 0m 0.1s): 93 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:09] V-Ray: (Estimated time remaining: 0h 0m 0.1s): 95 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:09] V-Ray: (Estimated time remaining: 0h 0m 0.1s): 96 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:09] V-Ray: (Estimated time remaining: 0h 0m 0.0s): 97 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:09] V-Ray: (Estimated time remaining: 0h 0m 0.0s): 98 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:09] V-Ray: (Estimated time remaining: 0h 0m 0.0s): 99 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:09] V-Ray: (Estimated time remaining: 0h 0m 0.0s): 100 % completed
2019-12-03 16:00:09: 0: STDOUT: [2019/Dec/3|16:00:09] V-Ray: Progressive rendering finished: specified noise level reached
In the MayaBatch.py integration script, there are several STDOUT Handlers that are looking for the % display to update the progress, catch errors etc.
self.AddStdoutHandlerCallback( "V-Ray error: .*" ).HandleCallback += self.HandleFatalError
self.AddStdoutHandlerCallback( "V-Ray: Building light cache*" ).HandleCallback += self.HandleVrayMessage
self.AddStdoutHandlerCallback( "V-Ray: Prepass ([0-9]+) of ([0-9]+)*" ).HandleCallback += self.HandleVrayMessage
self.AddStdoutHandlerCallback( "V-Ray: Rendering image*" ).HandleCallback += self.HandleVrayMessage
self.AddStdoutHandlerCallback( "V-Ray: +([0-9]+)%" ).HandleCallback += self.HandleVrayProgress
self.AddStdoutHandlerCallback( "V-Ray: +([0-9]+) %" ).HandleCallback += self.HandleVrayProgress
self.AddStdoutHandlerCallback( "([0-9]+) % completed" ).HandleCallback += self.HandleVrayProgress
self.AddStdoutHandlerCallback( "V-Ray: Total frame time" ).HandleCallback += self.HandleVrayFrameComplete
self.AddStdoutHandlerCallback( "V-Ray: Updating frame at time ([0-9]+)" ).HandleCallback += self.HandleVrayExportProgress
self.AddStdoutHandlerCallback( "V-Ray: Render complete" ).HandleCallback += self.HandleVrayExportComplete
self.AddStdoutHandlerCallback( ".*V-Ray warning.* The file path for .* cannot be created.*" ).HandleCallback += self.HandleFatalError
We have similar ones registered for Redshift there:
if self.Renderer == "redshift":
self.AddStdoutHandlerCallback( r"Frame rendering aborted." ).HandleCallback += self.HandleFatalError
self.AddStdoutHandlerCallback( r"Rendering was internally aborted" ).HandleCallback += self.HandleFatalError
self.AddStdoutHandlerCallback( r'Cannot find procedure "rsPreference"' ).HandleCallback += self.HandleFatalError
self.AddStdoutHandlerCallback( "Rendering frame \\d+ \\((\\d+)/(\\d+)\\)" ).HandleCallback += self.HandleRedshiftNewFrameProgress
self.AddStdoutHandlerCallback( "Block (\\d+)/(\\d+) .+ rendered" ).HandleCallback += self.HandleRedshiftBlockRendered
When Redshift renders in Maya, it outputs something like this:
2019-11-13 18:30:40: 0: STDOUT: Rendering blocks... (resolution: 960x540, block size: 128, unified minmax: [4,16])
2019-11-13 18:30:40: 0: STDOUT: Allocating VRAM for device 0 (Tesla M60)
2019-11-13 18:30:40: 0: STDOUT: Redshift can use up to 6399 MB
2019-11-13 18:30:40: 0: STDOUT: Fixed: 0 MB
2019-11-13 18:30:40: 0: STDOUT: Geo: 402 MB, Tex: 39 MB, Rays: 1840 MB, NRPR: 1142240
2019-11-13 18:30:40: 0: STDOUT: Done! ( 6ms). CUDA reported free mem: 728 MB
2019-11-13 18:30:40: 0: STDOUT: Block 1/40 (3,1) rendered by GPU 0 in 551ms
2019-11-13 18:30:40: 0: STDOUT: Block 2/40 (4,1) rendered by GPU 0 in 286ms
2019-11-13 18:30:41: 0: STDOUT: Block 3/40 (4,2) rendered by GPU 0 in 401ms
2019-11-13 18:30:41: 0: STDOUT: Block 4/40 (3,2) rendered by GPU 0 in 380ms
2019-11-13 18:30:42: 0: STDOUT: Block 5/40 (2,3) rendered by GPU 0 in 306ms
2019-11-13 18:30:42: 0: STDOUT: Block 6/40 (2,2) rendered by GPU 0 in 299ms
2019-11-13 18:30:42: 0: STDOUT: Block 7/40 (2,1) rendered by GPU 0 in 264ms
2019-11-13 18:30:42: 0: STDOUT: Block 8/40 (2,0) rendered by GPU 0 in 250ms
2019-11-13 18:30:43: 0: STDOUT: Block 9/40 (3,0) rendered by GPU 0 in 263ms
2019-11-13 18:30:43: 0: STDOUT: Block 10/40 (4,0) rendered by GPU 0 in 169ms
2019-11-13 18:30:43: 0: STDOUT: Block 11/40 (5,0) rendered by GPU 0 in 156ms
2019-11-13 18:30:43: 0: STDOUT: Block 12/40 (5,1) rendered by GPU 0 in 236ms
2019-11-13 18:30:44: 0: STDOUT: Block 13/40 (5,2) rendered by GPU 0 in 354ms
2019-11-13 18:30:44: 0: STDOUT: Block 14/40 (5,3) rendered by GPU 0 in 398ms
2019-11-13 18:30:44: 0: STDOUT: Block 15/40 (4,3) rendered by GPU 0 in 396ms
2019-11-13 18:30:45: 0: STDOUT: Block 16/40 (3,3) rendered by GPU 0 in 459ms
2019-11-13 18:30:45: 0: STDOUT: Block 17/40 (1,4) rendered by GPU 0 in 83ms
2019-11-13 18:30:45: 0: STDOUT: Block 18/40 (1,3) rendered by GPU 0 in 241ms
2019-11-13 18:30:45: 0: STDOUT: Block 19/40 (1,2) rendered by GPU 0 in 378ms
2019-11-13 18:30:46: 0: STDOUT: Block 20/40 (1,1) rendered by GPU 0 in 284ms
2019-11-13 18:30:46: 0: STDOUT: Block 21/40 (1,0) rendered by GPU 0 in 263ms
2019-11-13 18:30:46: 0: STDOUT: Block 22/40 (6,0) rendered by GPU 0 in 222ms
2019-11-13 18:30:47: 0: STDOUT: Block 23/40 (6,1) rendered by GPU 0 in 244ms
2019-11-13 18:30:47: 0: STDOUT: Block 24/40 (6,2) rendered by GPU 0 in 374ms
2019-11-13 18:30:47: 0: STDOUT: Block 25/40 (6,3) rendered by GPU 0 in 322ms
2019-11-13 18:30:47: 0: STDOUT: Block 26/40 (6,4) rendered by GPU 0 in 102ms
2019-11-13 18:30:47: 0: STDOUT: Block 27/40 (5,4) rendered by GPU 0 in 118ms
2019-11-13 18:30:48: 0: STDOUT: Block 28/40 (4,4) rendered by GPU 0 in 135ms
2019-11-13 18:30:48: 0: STDOUT: Block 29/40 (3,4) rendered by GPU 0 in 171ms
2019-11-13 18:30:48: 0: STDOUT: Block 30/40 (2,4) rendered by GPU 0 in 102ms
2019-11-13 18:30:48: 0: STDOUT: Block 31/40 (0,4) rendered by GPU 0 in 110ms
2019-11-13 18:30:48: 0: STDOUT: Block 32/40 (0,3) rendered by GPU 0 in 322ms
2019-11-13 18:30:49: 0: STDOUT: Block 33/40 (0,2) rendered by GPU 0 in 350ms
2019-11-13 18:30:49: 0: STDOUT: Block 34/40 (0,1) rendered by GPU 0 in 264ms
2019-11-13 18:30:49: 0: STDOUT: Block 35/40 (0,0) rendered by GPU 0 in 200ms
2019-11-13 18:30:49: 0: STDOUT: Block 36/40 (7,0) rendered by GPU 0 in 132ms
2019-11-13 18:30:49: 0: STDOUT: Block 37/40 (7,1) rendered by GPU 0 in 138ms
2019-11-13 18:30:50: 0: STDOUT: Block 38/40 (7,2) rendered by GPU 0 in 210ms
2019-11-13 18:30:50: 0: STDOUT: Block 39/40 (7,3) rendered by GPU 0 in 183ms
2019-11-13 18:30:50: 0: STDOUT: Block 40/40 (7,4) rendered by GPU 0 in 67ms
2019-11-13 18:30:50: 0: STDOUT: Processing blocks...
2019-11-13 18:30:50: 0: STDOUT: Time to render 40 blocks: 10.3s
In the case of Houdini, it is possible that Redshift does not write anything usable to the log to handle as progress. Here are the Houdini STDOUT Handlers found in Repo/plugins/Houdini/Houdini.py:
self.AddStdoutHandlerCallback( "(Couldn't find renderer.*)" ).HandleCallback += self.HandleStdoutRenderer
self.AddStdoutHandlerCallback( "(Error: Unknown option:.*)" ).HandleCallback += self.HandleStdoutUnknown
self.AddStdoutHandlerCallback( "(Error: .*)" ).HandleCallback += self.HandleStdoutError
self.AddStdoutHandlerCallback(r"(ERROR\s*\|.*)").HandleCallback += self.HandleStdoutError #Arnold errors
self.AddStdoutHandlerCallback(r"\[Error\].*").HandleCallback += self.HandleStdoutError
self.AddStdoutHandlerCallback( ".*(Redshift cannot operate with less than 128MB of free VRAM).*" ).HandleCallback += self.HandleStdoutError
self.AddStdoutHandlerCallback( ".*(No licenses could be found to run this application).*" ).HandleCallback += self.HandleStdoutLicense
self.AddStdoutHandlerCallback( ".*ALF_PROGRESS ([0-9]+)%.*" ).HandleCallback += self.HandleStdoutFrameProgress
self.AddStdoutHandlerCallback( ".*Render Time:.*" ).HandleCallback += self.HandleStdoutFrameComplete
self.AddStdoutHandlerCallback( ".*Finished Rendering.*" ).HandleCallback += self.HandleStdoutDoneRender
self.AddStdoutHandlerCallback( ".*ROP type: (.*)" ).HandleCallback += self.SetRopType
self.AddStdoutHandlerCallback( ".*?(\d+)% done.*" ).HandleCallback += self.HandleStdoutFrameProgress
self.AddStdoutHandlerCallback( "\[render progress\] ---[ ]+(\d+) percent" ).HandleCallback += self.HandleStdoutFrameProgress
self.AddStdoutHandlerCallback( "(License error: No license found)").HandleCallback += self.HandleStdoutLicense
The two handlers for FrameProgress are
self.AddStdoutHandlerCallback( ".*?(\d+)% done.*" ).HandleCallback += self.HandleStdoutFrameProgress
self.AddStdoutHandlerCallback( "\[render progress\] ---[ ]+(\d+) percent" ).HandleCallback += self.HandleStdoutFrameProgress
Your log does not show anything like that, so the Tasks would not show any progress.
However, if you have 100 frames and 1 Frame Per Task, you will get a Job Progress advancing from 0 to 100% as each Task finishes.
It only makes sense to combine multiple frames in a single Task if there is an overhead in relaunching the application between Tasks. For example, AfterEffects notoriously performs better if your Frames Per Task value is high (10 or so). But for applications that keep the scene in memory and just switch between frames, it is probably ok to keep the value at 1.
I cannot comment on why the caches were being re-cooked - I wonder if the file cache paths were invalid in the context of the render node, and forced Houdini to recompute?
), so the Task was cancelled due to that. There are no license errors reported anymore.
