(Maya) Why does it take so long to assemble rendered tiles?

Deadline
1

I had a job for a customer where she wanted to print a large banner for a scene I created in Maya. To get her the 300dpi resolution the image would need, I needed to render a frame image that was 14,440 x 7240. I figured no problem this is just what tile rendering was designed for. I am using the latest version of Deadline and submitted my job breaking it into a 30 x 30 array of tiles for a total of 900 tiles to render. My surprise came when it took almost as long to assemble the tiles as it did to render the tiles.

As you can see from the summary dumps below the total task time to render was:
total task time: 00d 16h 44m 19s

and the total task time to assemble the tiles was:
total task time: 00d 13h 04m 43s

Now granted, the render has a very high CPU utilization across 2 machines (33% median with 99% peak) where assembling the tiles was (7% median with 8% peak) across 1 machine but I don’t understand why assembling the tiles is such a difficult task. What am I missing that this is simply a copy and paste of 900 smaller frames into one large frame? Deadline knows how the tiles are broken up as it created the fractured tiles in the first place. There is no need for pattern recognition or trying to match seams, this should be exact and known. I don’t understand why this shouldn’t take seconds or maybe perhaps minutes but hours? I would have been better off just letting one machine grind on the entire frame.

===========================================================================================
Here are the stats on the scene render:

Studio1_large - scene_render (Frame 0 - 900 Tiles) job has now completed.

Job Details
name: Studio1_large - scene_render (Frame 0 - 900 Tiles)
comment:
plugin: MayaCmd
frames: 0-899
pool: none
group: fixedwindows
output location: file:///L:/projects/PhilFX/MyMoltenMuse/Sunlight_Logo/images/scene_render

Submission Details
username: phoppes
machine: Optimus
department:
time: Feb 13/12 17:31:01

Results
frames/chunk: 1
total chunks: 900
queued: 0
rendering: 0
completed: 900
suspended: 0

Timings
submitted date/time: Feb 13/12 17:31:01
started date/time: Feb 13/12 17:31:13
completed date/time: Feb 14/12 03:03:32
elapsed running time: 00d 09h 32m 19s

total task time: 00d 16h 44m 19s
average task time: 00d 00h 01m 06s
median task time: 00d 00h 00m 58s
total task startup time: 00d 00h 16m 43s
average task startup time: 00d 00h 00m 01s
median task startup time: 00d 00h 00m 01s
total task render time: 00d 16h 24m 35s
average task render time: 00d 00h 01m 05s
median task render time: 00d 00h 00m 57s

wasted time due to errors: 00d 00h 00m 13s
wasted time due to requeues: 00d 00h 00m 00s

Miscellaneous Info
errors reported: 1
average number of tasks rendering concurrently: 2

Image Size Info
total image file size: 331102539000
average image file size: 367891710
median image file size: 367891710

Task Info
peak task RAM usage: 1.285 GB
average task RAM usage: 495.879 MB
median task RAM usage: 500.443 MB
peak task CPU utilisation: 99%
average task CPU utilisation: 33%
median task CPU utilisation: 35%

message auto generated by Deadline Slave
version: v5.1.0.46114 R
machine: Starscream
date/time: 02/14/2012 03:03

=======================================================================================================================
Here are the stats on the tile assembly:

Studio1_large(Frame 0 - Tile Assembly Job) job has now completed.

Job Details
name: Studio1_large(Frame 0 - Tile Assembly Job)
comment:
plugin: TileAssembler
frames: 0
pool: none
group: fixedwindows
output location: file:///L:/projects/PhilFX/MyMoltenMuse/Sunlight_Logo/images/scene_render

Submission Details
username: phoppes
machine: Optimus
department:
time: Feb 13/12 17:31:10

Results
frames/chunk: 1
total chunks: 1
queued: 0
rendering: 0
completed: 1
suspended: 0

Timings
submitted date/time: Feb 13/12 17:31:10
started date/time: Feb 14/12 03:04:35
completed date/time: Feb 14/12 17:46:07
elapsed running time: 00d 14h 41m 32s

total task time: 00d 13h 04m 43s
average task time: 00d 13h 04m 43s
median task time: 00d 13h 04m 43s
total task startup time: 00d 00h 00m 01s
average task startup time: 00d 00h 00m 01s
median task startup time: 00d 00h 00m 01s
total task render time: 00d 13h 04m 41s
average task render time: 00d 13h 04m 41s
median task render time: 00d 13h 04m 41s

wasted time due to errors: 00d 00h 00m 00s
wasted time due to requeues: 00d 00h 00m 00s

Miscellaneous Info
errors reported: 0
average number of tasks rendering concurrently: 1

Image Size Info
total image file size: 834746990
average image file size: 834746990
median image file size: 834746990

Task Info
peak task RAM usage: 1.569 GB
average task RAM usage: 1.555 GB
median task RAM usage: 1.555 GB
peak task CPU utilisation: 8%
average task CPU utilisation: 7%
median task CPU utilisation: 7%

message auto generated by Deadline Slave
version: v5.1.0.46114 R
machine: Optimus
date/time: 02/14/2012 17:46

2

16+ hours is crazy! I wouldn’t have expected to see this either. There could be a few reasons to explain it, but still, we’ve never heard of an assembly taking 16+ hours before.

  1. The tile assembler isn’t multithreaded, so that would likely explain the low cpu utilization.

  2. Unlikely, but it could be IO related, since there are 900 tiles. Out of curiosity, why did you go with 30x30? Based on the render times (about 1 minute per task), that might have been overkill. I wonder what the results would have been if you went with 15x15 or 10x10 instead.

  3. Do you know if the tiles were a cropped, or if they were the full resolution with just a region in it being rendered? If it’s the latter, that could definitely explain the problem. The tile assembler performs much better when each tile is cropped, but unfortunately not all renderers support this. I’m sure there is room for optimization here, we’ve just never looked into it because until now, there were never any major complaints.

Finally, could you post the render log from the tile assembly job? That might shed some light on this too.

Thanks!

  • Ryan
3

We don’t go over 10x10 to keep assembly quick. Still takes 1-2mins, but we had massive slow down on our old network which admitadly was pretty darn slow, but it seemed to be something to do with multiple tile assembly jobs running together, for render elements for example. it just killed our server and the jobs took a long time to assemble. On our old server we limited our tile assembly jobs to 2 machines.

Russel, I wonder whether there would be greater performance from the Tile Assembler if first all tiles were copied to the local machine and then assembled from there? We found improvements with this when we had our old crap network.

Also, are you rendering render elements to the same folder? If you had say 10 render elements and 30x30 tiles you’ll have 9000 files in one folder, which on Windows for example will really sulk and slow down with.

4

I listed a cropped version of the log below. I wacked out portions that were simply repeats of a similar line but just for a different tile so the listing is not so long.

To you comments back:

  1. Yea, I realized it is not multi-threaded but that is probably not the issue.
  2. I agree I/O should not be the issue. I am a small shop. Just me, but I rendered this on a 3.3Ghz i7 980 Extreme (12 threads) and a 2 x Xeon 2.4Ghz Hex core server (24 threads). I’ve never done a tile render with deadline before so I really did not have a good feel for how to break it up. 10x10 or 15x15 probably would have been better in 20/20 hindsight.
  3. AH, here I think you hit the proverbial nail on the head. No the images were not cropped. The intermediate tiles were all at the full resolution of 14440 x 7240 with a small rendered region in each. I did not realize that I could/should have them cropped. When I look at your panel there is no where it mentions cropping the images. Is this something I need to do with a MEL script before hand?

=======================================================
Log Message

0: Task timeout is disabled.
0: Loaded job: Studio1_large(Frame 0 - Tile Assembly Job) (999_001_001_0c3ccc1d)
0: INFO: StartJob: initializing script plugin TileAssembler
0: INFO: Any stdout that matches the regular expression “ERROR:.*” will be handled as appropriate
0: INFO: Any stdout that matches the regular expression “Processing [0-9]+ by [0-9]+, a total of ([0-9]+) tiles” will be handled as appropriate
0: INFO: Any stdout that matches the regular expression “Adding tile [0-9]+,[0-9]” will be handled as appropriate
0: INFO: Any stdout that matches the regular expression “Writing output to” will be handled as appropriate
0: INFO: About: Tile Assembler Plugin for Deadline
0: Plugin rendering frame(s): 0
0: INFO: Stdout Handling Enabled: True
0: INFO: Popup Handling Enabled: False
0: INFO: Using Process Tree: True
0: INFO: Hiding DOS Window: True
0: INFO: Creating New Console: False
0: INFO: Render Executable: “C:\Program Files\Thinkbox\Deadline\bin\TileAssembler64.exe”
0: INFO: Assembling uncropped tiles
0: INFO: Ignoring overlap
0: INFO: Cleaning up tiles after assembly is finished
0: INFO: Render Argument: --verbose 5 --not-cropped --ignore-overlap --cleanup-tiles “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x1_30x30_Studio1.0.tif”
0: INFO: Startup Directory: “C:\Program Files\Thinkbox\Deadline\bin”
0: INFO: Process Priority: BelowNormal
0: INFO: Process is now running
0: STDOUT: TileAssembler 1.2 rev 46114
0: STDOUT: Copyright (c) 2005-2011 Thinkbox Software Inc
0: STDOUT: Portions Copyright (C) Copyright 1999-2007 ImageMagick Studio LLC, a non-profit organization dedicated to making software imaging solutions freely available.
0: STDOUT: Portions Copyright (C) 2002, Industrial Light & Magic, a division of Lucas Digital Ltd. LLC All rights reserved.
0: STDOUT: Processing 30 by 30, a total of 900 tiles…
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x1_30x30_Studio1.0.tif” exists.
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x2_30x30_Studio1.0.tif” exists.
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x3_30x30_Studio1.0.tif” exists.
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x4_30x30_Studio1.0.tif” exists.
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x5_30x30_Studio1.0.tif” exists.
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x6_30x30_Studio1.0.tif” exists.
.
.
.
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_30x25_30x30_Studio1.0.tif” exists.
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_30x26_30x30_Studio1.0.tif” exists.
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_30x27_30x30_Studio1.0.tif” exists.
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_30x28_30x30_Studio1.0.tif” exists.
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_30x29_30x30_Studio1.0.tif” exists.
0: STDOUT: Validating that component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_30x30_30x30_Studio1.0.tif” exists.
0: STDOUT: Assembling a .tif image file
0: STDOUT: The fully assembled image is 14440 by 7240
0: STDOUT: Assembled image type = TrueColorMatteType
0: STDOUT: Assembled image format = TIFF
0: STDOUT: Assembled image width = 14440
0: STDOUT: Assembled image height = 7240
0: STDOUT: Assembled image depth = 16
0: STDOUT: Assembled image quality = 0
0: STDOUT: Assembled image orientation = TopLeftOrientation
0: STDOUT: Assembled image compression = RLECompression
0: STDOUT: Assembled image interlace type = NoInterlace
0: STDOUT: Assembled image resolution units = UndefinedResolution
0: STDOUT: Performing non-cropped assembly
0: STDOUT: Adding tile 1,1
0: STDOUT: Adding tile 1,2
0: STDOUT: Adding tile 1,3
0: STDOUT: Adding tile 1,4
0: STDOUT: Adding tile 1,5
0: STDOUT: Adding tile 1,6
0: STDOUT: Adding tile 1,7
0: STDOUT: Adding tile 1,8
0: STDOUT: Adding tile 1,9
.
.
.
.
0: STDOUT: Adding tile 30,24
0: STDOUT: Adding tile 30,25
0: STDOUT: Adding tile 30,26
0: STDOUT: Adding tile 30,27
0: STDOUT: Adding tile 30,28
0: STDOUT: Adding tile 30,29
0: STDOUT: Adding tile 30,30
0: STDOUT: Writing output to “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render\Studio1.0.tif”
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x1_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x2_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x3_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x4_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x5_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x6_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x7_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x8_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_1x9_30x30_Studio1.0.tif”.
.
.
.
.
.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_30x26_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_30x27_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_30x28_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_30x29_30x30_Studio1.0.tif”.
0: STDOUT: Deleting component tile “L:\projects\PhilFX\MyMoltenMuse\Sunlight_Logo\images\scene_render_tile_30x30_30x30_Studio1.0.tif”.
0: INFO: Process exit code: 0

=======================================================
Log Details

Log Date/Time = Feb 14/12 17:46:06
Frames = 0-0

Slave Machine = Optimus
Slave Version = v5.1.0.46114 R

Plugin Name = TileAssembler

5

That probably means that less tiles would have helped here. Regardless, we should really look at trying to optimize non-cropped assemblies.

The cropping of region renders depends on the renderer you’re using. Some Maya renderers crop, some don’t, and it’s not something you should have to worry about manually addressing beforehand.

Cheers,

  • Ryan
6

Thanks for the reply. I used Mental Ray to render this project.