Houdini 17 Simulation Hangs on load

Nick_Weeden · November 22, 2018, 10:39am

Hi,

I’m trying to do a sim in Houdini 17 but when I send it to Deadline it hangs for ages, the slave starts hython.exe and it appears to be doing something but it hangs at 0% for ever. As you can see from below it gets into the script and start I assume loading the file and then just gets stuck forever. Any thoughts on what might be causing this?

2018-11-22 09:59:55: 0: Got task!

2018-11-22 09:59:55: 0: Plugin will be reloaded because a new job has been loaded.

2018-11-22 09:59:55: 0: Loading Job’s Plugin timeout is Disabled

2018-11-22 09:59:57: 0: Loaded plugin Houdini

2018-11-22 09:59:57: 0: Executing plugin command of type ‘Sync Files for Job’

2018-11-22 09:59:57: 0: Synchronization time for job files: 140.624 ms

2018-11-22 09:59:58: 0: Synchronizing Plugin Houdini from \**\deadline10\plugins\Houdini took: 0 seconds

2018-11-22 09:59:58: 0: Done executing plugin command of type ‘Sync Files for Job’

2018-11-22 09:59:58: 0: Executing plugin command of type ‘Initialize Plugin’

2018-11-22 09:59:59: 0: CheckPathMapping: Swapped "**

2018-11-22 09:59:59: 0: INFO: Executing plugin script ‘C:\Users\Render\AppData\Local\Thinkbox\Deadline10\slave**\plugins\5bf67d7b716feb1fe445ab7a\Houdini.py’

2018-11-22 09:59:59: 0: INFO: About: Houdini Plugin for Deadline

2018-11-22 09:59:59: 0: INFO: Render Job As User disabled, running as current user ‘render’

2018-11-22 09:59:59: 0: INFO: The job’s environment will be merged with the current environment before rendering

2018-11-22 09:59:59: 0: Done executing plugin command of type ‘Initialize Plugin’

2018-11-22 10:00:00: 0: Start Job timeout is disabled.

2018-11-22 10:00:00: 0: Task timeout is disabled.

2018-11-22 10:00:00: 0: Loaded job: flare_v002 sim - /out/smoke_vdb (5bf67d7b716feb1fe445ab7a)

2018-11-22 10:00:00: 0: Skipping S: because it is already mapped

2018-11-22 10:00:00: 0: Skipping W: because it is already mapped

2018-11-22 10:00:00: 0: Executing plugin command of type ‘Start Job’

2018-11-22 10:00:00: 0: INFO: Executing global asset transfer preload script ‘C:\Users\Render\AppData\Local\Thinkbox\Deadline10\slave*\plugins\5bf67d7b716feb1fe445ab7a\GlobalAssetTransferPreLoad.py’

2018-11-22 10:00:00: 0: INFO: Looking for AWS Portal File Transfer…

2018-11-22 10:00:00: 0: INFO: Looking for File Transfer controller in C:/Program Files/Thinkbox/S3BackedCache/bin/task.py…

2018-11-22 10:00:00: 0: INFO: Could not find AWS Portal File Transfer.

2018-11-22 10:00:00: 0: INFO: AWS Portal File Transfer is not installed on the system.

2018-11-22 10:00:00: 0: Done executing plugin command of type ‘Start Job’

2018-11-22 10:00:00: 0: Plugin rendering frame(s): 1200-3100

2018-11-22 10:00:00: 0: Executing plugin command of type ‘Render Task’

2018-11-22 10:00:00: 0: INFO: Set HOUDINI_PATHMAP to {*}

2018-11-22 10:00:00: 0: INFO: Redshift Path Mapping…

2018-11-22 10:00:00: 0: INFO: source: "*"

2018-11-22 10:00:00: 0: INFO: source: "*"

2018-11-22 10:00:00: 0: INFO: source: "*"

2018-11-22 10:00:00: 0: INFO: [REDSHIFT_PATHOVERRIDE_FILE] now set to: "C:\Users\Render\AppData\Local\Thinkbox\Deadline10\slave\render-05-242\jobsData\5bf67d7b716feb1fe445ab7a\RSMapping_tempxGrl30\RSMapping.txt"

2018-11-22 10:00:00: 0: INFO: Starting Houdini Job

2018-11-22 10:00:00: 0: INFO: Stdout Redirection Enabled: True

2018-11-22 10:00:00: 0: INFO: Stdout Handling Enabled: True

2018-11-22 10:00:00: 0: INFO: Popup Handling Enabled: True

2018-11-22 10:00:00: 0: INFO: QT Popup Handling Enabled: False

2018-11-22 10:00:00: 0: INFO: WindowsForms10.Window.8.app.* Popup Handling Enabled: False

2018-11-22 10:00:00: 0: INFO: Using Process Tree: True

2018-11-22 10:00:00: 0: INFO: Hiding DOS Window: True

2018-11-22 10:00:00: 0: INFO: Creating New Console: False

2018-11-22 10:00:00: 0: INFO: Running as user: render

2018-11-22 10:00:00: 0: INFO: Executable: "C:\Program Files\Side Effects Software\Houdini 17.0.352\bin\Hython.exe"

2018-11-22 10:00:00: 0: INFO: Argument: "C:\Users\Render\AppData\Local\Thinkbox\Deadline10\slave\render-05-242\plugins\5bf67d7b716feb1fe445ab7a\hrender_dl.py" -f 1200 3100 1 -g -d /out/smoke_vdb "C:/Users/Render/AppData/Local/Thinkbox/Deadline10/slave/render-05-242/jobsData/5bf67d7b716feb1fe445ab7a/flare_v002.hip"

2018-11-22 10:00:00: 0: INFO: Full Command: "C:\Program Files\Side Effects Software\Houdini 17.0.352\bin\Hython.exe" "C:\Users\Render\AppData\Local\Thinkbox\Deadline10\slave\render-05-242\plugins\5bf67d7b716feb1fe445ab7a\hrender_dl.py" -f 1200 3100 1 -g -d /out/smoke_vdb "C:/Users/Render/AppData/Local/Thinkbox/Deadline10/slave/render-05-242/jobsData/5bf67d7b716feb1fe445ab7a/flare_v002.hip"

2018-11-22 10:00:00: 0: INFO: Startup Directory: "C:\Program Files\Side Effects Software\Houdini 17.0.352\bin"

2018-11-22 10:00:00: 0: INFO: Process Priority: BelowNormal

2018-11-22 10:00:00: 0: INFO: Process Affinity: default

2018-11-22 10:00:00: 0: INFO: Process is now running

2018-11-22 10:00:34: 0: STDOUT: [2018/Nov/22:10:00:05] VFH [Info] Loading Phoenix cache loader plugins from "S:/Codebase/Houdini/Vray/vfh_home/libs"…

2018-11-22 10:00:34: 0: STDOUT: [2018/Nov/22:10:00:06] VFH [Info] Build 913ba00 from Oct 24 2018, 04:29:38

2018-11-22 10:00:36: 0: STDOUT: Detected Houdini version: (17, 0, 352)

2018-11-22 10:00:36: 0: STDOUT: [‘C:\Users\Render\AppData\Local\Thinkbox\Deadline10\slave\render-05-242\plugins\5bf67d7b716feb1fe445ab7a\hrender_dl.py’, ‘-f’, ‘1200’, ‘3100’, ‘1’, ‘-g’, ‘-d’, ‘/out/smoke_vdb’, ‘C:/Users/Render/AppData/Local/Thinkbox/Deadline10/slave/render-05-242/jobsData/5bf67d7b716feb1fe445ab7a/flare_v002.hip’]

2018-11-22 10:00:36: 0: STDOUT: Start: 1200

2018-11-22 10:00:36: 0: STDOUT: End: 3100

2018-11-22 10:00:36: 0: STDOUT: Increment: 1

2018-11-22 10:00:36: 0: STDOUT: Ignore Inputs: True

2018-11-22 10:00:36: 0: STDOUT: No output specified. Output will be handled by the driver

2018-11-22 10:00:36: 0: STDOUT: Driver: /out/smoke_vdb

2018-11-22 10:00:36: 0: STDOUT: Input File: C:/Users/Render/AppData/Local/Thinkbox/Deadline10/slave/render-05-242/jobsData/5bf67d7b716feb1fe445ab7a/flare_v002.hip

Nick_Weeden · November 22, 2018, 11:06am

It’s very weird. The simulation starts at frame 1300. If I make it start at frame 0 it works. It seems like it’s not respecting the frame range and starting the simulation from 0?

Nick_Weeden · November 22, 2018, 11:25am

Sorry, a couple more weird issues. It’s not evaluating the ‘Output File’ strings properly on the output node.

It can’t do relative references (eg referencing the file cache node in the sim import geo node)
It’s not evaluating the string in the ‘Output File’, possibly the same issue as above. Although it respects $F4 to put in a frame with 4 zero padding, it won’t evaluate `$F4+1300` to the frame number plus 1300.

eamsler · November 26, 2018, 5:47pm

Well, it’s a simulation so it can’t just skip ahead. Imagine a pool or snooker table: You can’t ask “where are the balls going to be 15 seconds after the cue is hit?” you actually have to see everything leading up to that point. That’s essentially what Houdini’s doing to get to frame 1,300: It’s watching where the balls are going before it starts outputting valid frames.

If you’re often trying to skip work that’s already been done, there are ways to cache the sim to disk but the overhead on the file server may be too much to bother. Usually, it’s better to just bake the sim out to disk on a single machine and render that (also outlined in the link above). You might be doing exactly that, but hopefully that workflow helps someone else.

The relative references are failing due to submitting the HIP file. You’ll see it’s being copied locally based on the “Full Command”:

2018-11-22 10:00:00: 0: INFO: Full Command: "C:\Program Files\Side Effects Software\Houdini 17.0.352\bin\Hython.exe" "C:\Users\Render\AppData\Local\Thinkbox\Deadline10\slave\render-05-242\plugins\5bf67d7b716feb1fe445ab7a\hrender_dl.py" -f 1200 3100 1 -g -d /out/smoke_vdb "C:/Users/Render/AppData/Local/Thinkbox/Deadline10/slave/render-05-242/jobsData/5bf67d7b716feb1fe445ab7a/flare_v002.hip"

If the output is also relative to the HIP that’s going to fail as well. I’m not at all sure if Houdini supports the +1300, but it’s very likely to confuse Deadline when you want to explore output.

Nick_Weeden · November 26, 2018, 9:00pm

Hi Edwin, the sim was set to start at 1300 so there would be no calculation before that. In Houdini it does nothing before that only when I send it to the farm does it appear to do it. I changed the start frame of the sim to 0 and that is when it started working.

Houdini understands the +1300, there’s quite a few options for how to do things like that but it doesn’t seem that they work on deadline maybe because of the ` symbol not being handled correctly?

The path wasn’t relative, it was a full UNC path. I learned the $HIP problem a long time ago.

eamsler · November 27, 2018, 8:12pm

Yeah, I apparently forgot that you actually know what you’re doing with Houdini (and I don’t). Sorry about that.

I’m pretty sure we also won’t evaluate the tick marks either. If Deadline doesn’t have to touch them it should be fine, but it would be good to try and isolate the problem from Deadline as I recommend pretty often. There’s a bit of a trick to this one though: Because the scene file was copied locally and because Deadline also copies over “hrender_dl.py” from the plugin you might have to work quickly.

I tend to run a test render, then disable the Slave from the Monitor while it’s working. Once it’s disabled, cancel its task and the temp files should be safe. The Slave won’t clean up its working directory until it picks up a new job, so you should be able to steal the “Full Command” from the generated requeue report and not need to modify it. If running it from the command line hits the same pause (I’m expecting it will) then try opening the HIP and seeing if you can render it within Houdini or if there’s some obvious error while it’s loading up.