Community
Arnold for Houdini Forum
Rendering with Arnold in Houdini and Solaris using the HtoA plug-in.
cancel
Showing results for 
Show  only  | Search instead for 
Did you mean: 

Long pause before render

10 REPLIES 10
Reply
Message 1 of 11
francoislord
167 Views, 10 Replies

Long pause before render

Hi,

I'm rendering a closeup of a patch of hair. Everything goes well and looks good except when I start the render, it takes a long time before the first bucket appears and the number of rays is 10x larger than for other buckets. I would like to know why.

Here is the husk log. You can see it takes about an hour before the first bucket, and then it flies relatively quickly.

[14:22:32] 0% Lap=0:02:08.43 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:24:32] 0% Lap=0:04:08.51 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:26:32] 0% Lap=0:06:08.60 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:28:32] 0% Lap=0:08:08.69 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:30:32] 0% Lap=0:10:08.75 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:32:32] 0% Lap=0:12:08.79 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:34:32] 0% Lap=0:14:08.88 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:36:32] 0% Lap=0:16:08.90 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:38:32] 0% Lap=0:18:08.91 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:40:32] 0% Lap=0:20:08.98 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:42:32] 0% Lap=0:22:09.04 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:44:32] 0% Lap=0:24:09.12 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:46:32] 0% Lap=0:26:09.20 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:48:32] 0% Lap=0:28:09.28 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:50:32] 0% Lap=0:30:09.29 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:52:32] 0% Lap=0:32:09.35 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:54:33] 0% Lap=0:34:09.38 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:56:33] 0% Lap=0:36:09.45 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[14:58:33] 0% Lap=0:38:09.45 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[15:00:33] 0% Lap=0:40:09.54 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[15:02:33] 0% Lap=0:42:09.55 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[15:04:33] 0% Lap=0:44:09.57 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[15:06:33] 0% Lap=0:46:09.65 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[15:08:33] 0% Lap=0:48:09.69 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[15:10:33] 0% Lap=0:50:09.79 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
[15:12:33] 0% Lap=0:52:09.88 Left=<unknown> Mem=13.31 GB Peak=13.31 GB
00:52:24 6232MB | 0% done - 2016096 rays/pixel
[15:12:53] 1% Lap=0:52:29.75 Left=55:07:14.09 Mem=13.31 GB Peak=13.31 GB
[15:13:25] 3% Lap=0:53:02.00 Left=27:24:01.91 Mem=13.31 GB Peak=13.31 GB
[15:14:11] 4% Lap=0:53:48.10 Left=18:13:57.99 Mem=13.31 GB Peak=13.31 GB
00:53:45 6233MB | 5% done - 17593 rays/pixel
[15:14:14] 6% Lap=0:53:51.21 Left=13:27:48.12 Mem=13.31 GB Peak=13.31 GB
[15:16:14] 6% Lap=0:55:51.21 Left=13:57:48.17 Mem=13.31 GB Peak=13.31 GB
[15:16:40] 7% Lap=0:56:17.01 Left=11:04:08.77 Mem=13.31 GB Peak=13.31 GB
[15:17:39] 9% Lap=0:57:15.44 Left=9:13:29.29 Mem=13.31 GB Peak=13.31 GB
00:58:02 6238MB | 10% done - 55052 rays/pixel
[15:18:31] 10% Lap=0:58:08.18 Left=7:53:23.77 Mem=13.31 GB Peak=13.31 GB
[15:18:41] 12% Lap=0:58:17.62 Left=6:48:03.31 Mem=13.31 GB Peak=13.31 GB
[15:19:13] 14% Lap=0:58:50.24 Left=5:59:33.71 Mem=13.31 GB Peak=13.31 GB
00:59:09 6240MB | 15% done - 14084 rays/pixel
[15:19:38] 15% Lap=0:59:14.64 Left=5:19:55.06 Mem=13.31 GB Peak=13.31 GB
[15:20:47] 17% Lap=1:00:23.85 Left=4:51:00.35 Mem=13.31 GB Peak=13.31 GB
[15:21:30] 18% Lap=1:01:07.24 Left=4:24:51.36 Mem=13.31 GB Peak=13.31 GB
01:01:53 6243MB | 20% done - 34955 rays/pixel
[15:22:23] 20% Lap=1:01:59.60 Left=4:03:12.26 Mem=13.31 GB Peak=13.31 GB
[15:23:17] 21% Lap=1:02:54.33 Left=3:44:39.75 Mem=13.31 GB Peak=13.31 GB
[15:23:27] 23% Lap=1:03:03.78 Left=3:26:00.36 Mem=13.31 GB Peak=13.31 GB
01:04:30 6245MB | 25% done - 33081 rays/pixel
[15:24:59] 25% Lap=1:04:36.00 Left=3:13:47.99 Mem=13.31 GB Peak=13.31 GB
[15:25:08] 26% Lap=1:04:45.03 Left=2:59:00.97 Mem=13.31 GB Peak=13.31 GB
[15:26:13] 28% Lap=1:05:50.09 Left=2:48:14.68 Mem=13.31 GB Peak=13.31 GB
[15:26:20] 29% Lap=1:05:56.72 Left=2:36:11.17 Mem=13.31 GB Peak=13.31 GB
01:06:00 6247MB | 30% done - 14244 rays/pixel
[15:26:29] 31% Lap=1:06:05.95 Left=2:25:25.09 Mem=13.31 GB Peak=13.31 GB
[15:28:06] 32% Lap=1:07:42.60 Left=2:18:38.66 Mem=13.31 GB Peak=13.31 GB
[15:28:33] 34% Lap=1:08:09.62 Left=2:10:07.45 Mem=13.31 GB Peak=13.31 GB
01:08:38 6250MB | 35% done - 33537 rays/pixel

Thanks!

F

 

10 REPLIES 10
Message 2 of 11
thiago.ize
in reply to: francoislord

Increase your Arnold log verbosity to the highest setting and you'll get a bunch of messages telling you what is going on. Most likely it's subdividing meshes, doing displacements, loading textures, and so on. The high number of rays for the first bucket (0% mark) is a bug in how ray counts are being reported, so don't pay too much attention to that.

Message 3 of 11
francoislord
in reply to: thiago.ize

Setting the verbosity to 5 on the arnold_rendersettings node in Solaris does not change anything in the amount of messages I get. Even adding an Int attribute arnold:global:log:verbosity to the rendersettings prim and setting it to 9 does not affect the render verbosity. Anything else I need to do?
Message 4 of 11


@francoislord wrote:
Setting the verbosity to 5 on the arnold_rendersettings node in Solaris does not change anything in the amount of messages I get. Even adding an Int attribute arnold:global:log:verbosity to the rendersettings prim and setting it to 9 does not affect the render verbosity. Anything else I need to do?

All you get is what you showed in your first post? I get a lot more, the full Arnold log plus the husk log too, if I enable that. What version of HtoA are you using?

5 is the maximum value for the verbosity 



// Stephen Blair
// Arnold Renderer Support
Message 5 of 11

Yeah with the vervosity set to 5, I get this

00:00:34 6015MB | [texturesys] generating /My Drive/Coloride/Phase_2/houdini_projects/automation/hdri/blocky_photo_studio_4k_raw.exr.tx file from /My Drive/Coloride/Phase_2/houdini_projects/automation/hdri/blocky_photo_studio_4k.exr
00:00:36 6062MB | [skydome_light] /lights/uniform_dome: 1000x1000 importance map done in 0:17.09, average energy 0.958178
[22:34:30] 0% Lap=0:02:05.01 Left=<unknown> Mem=14.39 GB Peak=14.39 GB
[22:36:30] 0% Lap=0:04:05.08 Left=<unknown> Mem=14.39 GB Peak=14.39 GB
[22:38:30] 0% Lap=0:06:05.08 Left=<unknown> Mem=14.39 GB Peak=14.39 GB

This is with the command `husk -R Arnold --frame 1 --verbose 7t file.usd`

Message 6 of 11
thiago.ize
in reply to: francoislord

Generating tx files (autotx) should be a one-time cost. Re-rendering the same scene should not show those messages again. Is the time to the 0% message now also much faster? If not, there should be a bunch more other messages along the way saying what is going on.

Message 7 of 11
francoislord
in reply to: thiago.ize

Creating the .tx or not does not affect the long pause at the start. I'm running HtoA-6.2.1.1 with houdini-19.5.569 because that is what my cloud render farm provider supports. 

I just verified that the verbose level is properly set to 5 inside the usd file and it is. I really don't get more verbose messages in the cloud and locally on my machine.

Message 8 of 11



All you get is what you showed in your first post? I get a lot more, the full Arnold log plus the husk log too, if I enable that. 


No I get a lot more too, but not between the importance map timing and the "0% done" from Arnold. I have no idea what is going on during that time, which can take an hour.

Message 9 of 11

What does the profiling section of the log say (the two "top session self-times by X" sections) ?

If possible, I'd also kick it with -v 6 to compare that log



// Stephen Blair
// Arnold Renderer Support
Message 10 of 11

00:43:11 6230MB | -----------------------------------------------------------------------------------
00:43:11 6230MB | top session self-times by category
[23:15:39] 100% Lap=0:43:14.11 Left=0:00:00.00 Mem=14.39 GB Peak=14.39 GB
00:43:12 6230MB | BVH::intersect (/hairModel/hair) 16:22.23 (38.01%)
00:43:12 6230MB | curves::intersect (/hairModel/hair) 10:00.68 (23.25%)
00:43:12 6230MB | surface closure (/materials/hair/materials/hair/_standard_hair1) 5:48.84 (13.50%)
00:43:12 6230MB | ray traversal+intersection 1:29.27 ( 3.45%)
00:43:12 6230MB | LightSampling 1:28.06 ( 3.41%)
00:43:12 6230MB | /lights/uniform_dome 0:49.45 ( 1.91%)
00:43:12 6230MB | /lights/keylight1_parent/keylight1 0:21.13 ( 0.82%)
00:43:12 6230MB | /lights/keylight2_parent/keylight2 0:17.47 ( 0.68%)
00:43:12 6230MB | LightInitSampler 1:13.02 ( 2.83%)
00:43:12 6230MB | /lights/uniform_dome 0:37.24 ( 1.44%)
00:43:12 6230MB | /lights/keylight1_parent/keylight1 0:19.01 ( 0.74%)
00:43:12 6230MB | /lights/keylight2_parent/keylight2 0:14.99 ( 0.58%)
00:43:12 6230MB | AiLightsPrepare (/hairModel/hair) 1:04.60 ( 2.50%)
00:43:12 6230MB | AiLightsTrace 1:03.63 ( 2.46%)
00:43:12 6230MB | -----------------------------------------------------------------------------------
00:43:12 6230MB | top session self-times by node
00:43:12 6230MB | curves:/hairModel/hair 27:43.88 (64.39%)
00:43:12 6230MB | BVH::intersect 16:22.23 (38.01%)
00:43:12 6230MB | curves::intersect 10:00.68 (23.25%)
00:43:12 6230MB | AiLightsPrepare 1:04.60 ( 2.50%)
00:43:12 6230MB | standard_hair:/materials/hair/materials/hair/_standard_hair1 8:42.99 (20.24%)
00:43:12 6230MB | surface closure 5:48.84 (13.50%)
00:43:12 6230MB | AiLightsTrace 1:03.63 ( 2.46%)
00:43:12 6230MB | ray traversal+intersection 0:39.26 ( 1.52%)
00:43:12 6230MB | skydome_light:/lights/uniform_dome 2:02.63 ( 4.75%)
00:43:12 6230MB | LightSampling 0:49.45 ( 1.91%)
00:43:12 6230MB | LightInitSampler 0:37.24 ( 1.44%)
00:43:12 6230MB | ray traversal+intersection 0:18.77 ( 0.73%)
00:43:12 6230MB | ramp_rgb:/materials/hair/materials/hair/_ramp_rgb1 1:23.67 ( 3.24%)
00:43:12 6230MB | AiShaderEvalParamFuncArray 0:38.50 ( 1.49%)
00:43:12 6230MB | quad_light:/lights/keylight1_parent/keylight1 1:00.61 ( 2.35%)
00:43:12 6230MB | LightSampling 0:21.13 ( 0.82%)
00:43:12 6230MB | LightInitSampler 0:19.01 ( 0.74%)
00:43:12 6230MB | ray traversal+intersection 0:15.60 ( 0.60%)
00:43:12 6230MB | quad_light:/lights/keylight2_parent/keylight2 0:51.51 ( 1.99%)
00:43:12 6230MB | LightSampling 0:17.47 ( 0.68%)
00:43:12 6230MB | ray traversal+intersection 0:15.44 ( 0.60%)
00:43:12 6230MB | LightInitSampler 0:14.99 ( 0.58%)
00:43:12 6230MB | -----------------------------------------------------------------------------------

 

kick gives me that:

[...]
        | rendering image at 512 x 512, -4 AA samples
        |   AA samples max    <disabled>
        |   AA sample clamp   <disabled>
        |   diffuse           <disabled by depth>
        |   specular          <disabled by depth>
        |   transmission      <disabled by depth>
        |   volume indirect   <disabled by depth>
        |   total                          depth 10
        |   bssrdf            samples  1
        |   light             <using per light samples>
        |   transparency      depth 10
        | initializing 29 nodes
        |  creating root object list ...
        | node initialization done in 0:01.41 (multithreaded)
        | updating 30 nodes
        |  [color_manager_ocio] using config file C:\REZ\htoa\6.2.1.1-r1\a207\a\payload\scripts\bin\../ocio/configs/arnold/config.ocio
        |  scene bounds: (-13.1640806 -5.12934828 -12.0332003) -> (13.1861105 11.5484447 14.7234077)
        | node update done in 0:00.38 (multithreaded)
        | [aov] parsing 2 output statements ...
        | [aov] registered driver: "/Render/Products/renderproduct" (driver_exr)
        | [aov]  * "RGBA" of type RGBA filtered by "/Render/Products/Vars/RGBA/filter" (box_filter)
        | [aov] registered driver: "kick_display" (driver_kick)
        | [aov]  * "RGBA" of type RGBA filtered by "/Render/Products/Vars/RGBA/filter" (box_filter)
        | [aov] done preparing 2 AOVs for 1 output to 2 drivers (0 deep AOVs)
00:00:03  2150MB WARNING | [kick] render aborted due to earlier errors
WARNING | failed to launch bucket workers:  unknown reason
        | render done
00:00:03  2200MB         |
00:00:03  2200MB         | releasing resources
00:00:03   201MB         |
00:00:03   201MB         |  releasing resources
00:00:03   192MB         |   unloading 4 plugins
00:00:03   192MB         |    closing alembic_proc.dll ...
00:00:03   192MB         |    closing cryptomatte.dll ...
00:00:03   192MB         |    closing htoa_mandelbulb_proc.dll ...
00:00:03   192MB         |    closing usd_proc.dll ...
00:00:03   192MB         |   unloading plugins done
00:00:03   192MB         |  Arnold shutdown

No wonder I never use kick. 

Message 11 of 11

In the original post, it was almost an hour before "0% done" was logged.
I think a lot of that time was spent on [accel] (building the BVH acceleration structures)

00:52:24 6232MB | 0% done - 2016096 rays/pixel
[15:12:53] 1% Lap=0:52:29.75 Left=55:07:14.09 Mem=13.31 GB Peak=13.31 GB
[15:13:25] 3% Lap=0:53:02.00 Left=27:24:01.91 Mem=13.31 GB Peak=13.31 GB
[15:14:11] 4% Lap=0:53:48.10 Left=18:13:57.99 Mem=13.31 GB Peak=13.31 GB
00:53:45 6233MB | 5% done - 17593 rays/pixel



From my simple scene:

00:00:01   691MB         | starting 31 bucket workers of size 64x64 ...
00:00:01   712MB         |  [accel] list_aggregate bvh4 done - 0:00.00 (wall time) - 2 prims, 1 key
00:00:01   715MB         |  [subdiv] /sphere1: subdividing at least once because we don't have all quads as input
00:00:01   720MB         |  [accel] polymesh bvh4 done - 0:00.00 (wall time) - 81 prims, 1 key
00:00:01   744MB         |  [subdiv] /sphere1: regular threaded subdivision done - 3 iterations: 100 faces => 24320 quads - 0:00.00
00:00:01   749MB         |  [accel] polymesh bvh4 done - 0:00.00 (wall time) - 24320 prims, 1 key
00:00:02   757MB         |    0% done - 41 rays/pixel
00:00:02   783MB         |  [skydome_light] /lights/domelight1: 1000x1000 importance map done in 0:00.17, average energy 2.685054
00:00:02   811MB         |    5% done - 201 rays/pixel







// Stephen Blair
// Arnold Renderer Support

Can't find what you're looking for? Ask the community or share your knowledge.

Post to forums  

Autodesk Design & Make Report