After Effects - Slow first frame in task, randomly slow with other frames

JJ_Painter · September 8, 2022, 1:23pm

The title should be pretty self explanatory. I’ve noticed it’s taking a very long time to render the first frame of a task and then there’s other random frames taking way longer than they should.

2022-09-08 09:06:25:  Scheduler Thread - Job's Limit Groups: 
2022-09-08 09:06:25:  Scheduler Thread - Error mapping G: to 192.168.1.167:8086: The network name cannot be found.
2022-09-08 09:06:26:  0: Loading Job's Plugin timeout is Disabled
2022-09-08 09:06:26:  0: WARNING: Python version for 'AfterEffects' plugin is not specified! Defaulting to Python 2.
2022-09-08 09:06:26:  0: SandboxedPlugin: Render Job As User disabled, running as current user 'light'
2022-09-08 09:06:27:  'C:\Users\light\AppData\Local\Thinkbox\Deadline10\pythonAPIs\2021-11-20T022313.0000000Z' already exists. Skipping extraction of PythonSync.
2022-09-08 09:06:28:  All job files are already synchronized
2022-09-08 09:06:28:  Plugin AfterEffects was already synchronized.
2022-09-08 09:06:28:  0: Executing plugin command of type 'Initialize Plugin'
2022-09-08 09:06:28:  0: INFO: Executing plugin script 'C:\ProgramData\Thinkbox\Deadline10\workers\Graphics-11-PC\plugins\6319e85af478fc54d849ce71\AfterEffects.py'
2022-09-08 09:06:28:  0: INFO: Plugin execution sandbox using Python version 2
2022-09-08 09:06:28:  0: INFO: Fail Without Finished Message set to: False
2022-09-08 09:06:28:  0: INFO: Fail on Existing After Effects process: False
2022-09-08 09:06:28:  0: INFO: About: After Effects Plugin for Deadline
2022-09-08 09:06:28:  0: INFO: The job's environment will be merged with the current environment before rendering
2022-09-08 09:06:28:  0: Done executing plugin command of type 'Initialize Plugin'
2022-09-08 09:06:28:  0: Start Job timeout is disabled.
2022-09-08 09:06:28:  0: Task timeout is 300 seconds (Regular Task Timeout)
2022-09-08 09:06:28:  0: Loaded job: Beta-23-Test_v1_JJ.aep - CustomFixStressTest_JJ_v3 (6319e85af478fc54d849ce71)
2022-09-08 09:06:28:  0: Error mapping G: to 192.168.1.167:8086: The network name cannot be found.
2022-09-08 09:06:28:  0: Executing plugin command of type 'Start Job'
2022-09-08 09:06:28:  0: DEBUG: S3BackedCache Client is not installed.
2022-09-08 09:06:28:  0: INFO: Executing global asset transfer preload script 'C:\ProgramData\Thinkbox\Deadline10\workers\Graphics-11-PC\plugins\6319e85af478fc54d849ce71\GlobalAssetTransferPreLoad.py'
2022-09-08 09:06:28:  0: INFO: Looking for legacy (pre-10.0.26) AWS Portal File Transfer...
2022-09-08 09:06:28:  0: INFO: Looking for legacy (pre-10.0.26) File Transfer controller in C:/Program Files/Thinkbox/S3BackedCache/bin/task.py...
2022-09-08 09:06:28:  0: INFO: Could not find legacy (pre-10.0.26) AWS Portal File Transfer.
2022-09-08 09:06:28:  0: INFO: Legacy (pre-10.0.26) AWS Portal File Transfer is not installed on the system.
2022-09-08 09:06:28:  0: Done executing plugin command of type 'Start Job'
2022-09-08 09:06:28:  0: Plugin rendering frame(s): 340-359
2022-09-08 09:06:28:  0: Executing plugin command of type 'Render Task'
2022-09-08 09:06:28:  0: INFO: Attempting to create "C:\Users\light\Documents\ae_render_only_node.txt" to force After Effects to run in Render Engine mode
2022-09-08 09:06:28:  0: INFO: Stdout Redirection Enabled: True
2022-09-08 09:06:28:  0: INFO: Stdout Handling Enabled: True
2022-09-08 09:06:28:  0: INFO: Popup Handling Enabled: True
2022-09-08 09:06:28:  0: INFO: QT Popup Handling Enabled: False
2022-09-08 09:06:28:  0: INFO: WindowsForms10.Window.8.app.* Popup Handling Enabled: False
2022-09-08 09:06:28:  0: INFO: Using Process Tree: True
2022-09-08 09:06:28:  0: INFO: Hiding DOS Window: True
2022-09-08 09:06:28:  0: INFO: Creating New Console: False
2022-09-08 09:06:28:  0: INFO: Running as user: light
2022-09-08 09:06:28:  0: INFO: Executable: "C:\Program Files\Adobe\Adobe After Effects 2022\Support Files\aerender.exe"
2022-09-08 09:06:28:  0: INFO: Rendering to network drive
2022-09-08 09:06:28:  0: INFO: Validating the path: 'G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test'
2022-09-08 09:06:28:  0: INFO: Continuing on missing footage
2022-09-08 09:06:28:  0: INFO: Ignoring missing effect reference errors
2022-09-08 09:06:28:  0: INFO: Ignoring missing layer dependency errors
2022-09-08 09:06:28:  0: INFO: Argument: -project "C:\ProgramData\Thinkbox\Deadline10\workers\Graphics-11-PC\jobsData\6319e85af478fc54d849ce71\Beta-23-Test_v1_JJ.aep" -comp "CustomFixStressTest_JJ_v1" -s 340 -e 359 -output "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_[#####].exr" -mem_usage 100 100 -continueOnMissingFootage -v ERRORS_AND_PROGRESS -close DO_NOT_SAVE_CHANGES -sound OFF
2022-09-08 09:06:28:  0: INFO: Full Command: "C:\Program Files\Adobe\Adobe After Effects 2022\Support Files\aerender.exe" -project "C:\ProgramData\Thinkbox\Deadline10\workers\Graphics-11-PC\jobsData\6319e85af478fc54d849ce71\Beta-23-Test_v1_JJ.aep" -comp "CustomFixStressTest_JJ_v1" -s 340 -e 359 -output "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_[#####].exr" -mem_usage 100 100 -continueOnMissingFootage -v ERRORS_AND_PROGRESS -close DO_NOT_SAVE_CHANGES -sound OFF
2022-09-08 09:06:28:  0: INFO: Startup Directory: "C:\Program Files\Adobe\Adobe After Effects 2022\Support Files"
2022-09-08 09:06:28:  0: INFO: Process Priority: BelowNormal
2022-09-08 09:06:28:  0: INFO: Process Affinity: default
2022-09-08 09:06:28:  0: INFO: Process is now running
2022-09-08 09:06:29:  0: INFO: Submitted from After Effects version: 22.6x64
2022-09-08 09:06:29:  0: STDOUT: aerender version 22.6x64
2022-09-08 09:06:36:  0: STDOUT: PROGRESS: Launching After Effects...
2022-09-08 09:06:36:  0: STDOUT: WARNING:After Effects warning: timeSpanStart of 1.33 seconds will cause render to have frames outside of range defined by comp displayStartTime (10) and end of comp duration (24.23). Render will succeed, but may have blank frames.
2022-09-08 09:06:36:  0: STDOUT: WARNING:After Effects warning: Output color depth exceeds project color depth.
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  9/8/2022 9:06:36 AM: Starting composition "CustomFixStressTest_JJ_v1".
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Render Settings: Best Settings
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Quality: Best
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Resolution: Full
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Size: 3840 x 2160
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Proxy Use: Use No Proxies
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Effects: Current Settings
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Disk Cache: Read Only
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Color Depth: Current Settings
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Frame Blending: On for Checked Layers
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Field Render: Off
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Pulldown: Off
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Motion Blur: On for Checked Layers
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Solos: Current Settings
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Time Span: Custom
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Start: 0:00:11:10
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  End: 0:00:11:29
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Duration: 0:00:00:20
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Frame Rate: 30.00 (comp)
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Guide Layers: All Off
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Skip Existing Files: Off
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Output Module: DwabOnThemHaters
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Output To: G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_[#####].exr
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Format: OpenEXR
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Output Info: DWAB compression
2022-09-08 09:06:36:  0: STDOUT: level: 45.0
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Start Frame: 340
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Output Audio: -
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Channels: RGB
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Depth: Floating Point
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Color: Premultiplied
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Resize: -
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Crop: -
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Final Size: 3840 x 2160
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Profile: -
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  Post-Render Action: None
2022-09-08 09:06:36:  0: STDOUT: PROGRESS:  
2022-09-08 09:07:01:  0: STDOUT: PROGRESS:  0:00:11:10 (1): 24 Seconds
2022-09-08 09:07:01:  0: STDOUT: PROGRESS:  0:00:11:11 (2): 1 Seconds
2022-09-08 09:07:02:  0: STDOUT: PROGRESS:  0:00:11:12 (3): 1 Seconds
2022-09-08 09:07:03:  0: STDOUT: PROGRESS:  0:00:11:13 (4): 0 Seconds
2022-09-08 09:07:03:  0: STDOUT: PROGRESS:  0:00:11:14 (5): 0 Seconds
2022-09-08 09:07:03:  0: STDOUT: PROGRESS:  0:00:11:15 (6): 1 Seconds
2022-09-08 09:07:04:  0: STDOUT: PROGRESS:  0:00:11:16 (7): 0 Seconds
2022-09-08 09:07:17:  0: STDOUT: PROGRESS:  0:00:11:17 (8): 13 Seconds
2022-09-08 09:07:17:  0: STDOUT: PROGRESS:  0:00:11:18 (9): 1 Seconds
2022-09-08 09:07:18:  0: STDOUT: PROGRESS:  0:00:11:19 (10): 0 Seconds
2022-09-08 09:07:20:  0: STDOUT: PROGRESS:  0:00:11:20 (11): 3 Seconds
2022-09-08 09:07:21:  0: STDOUT: PROGRESS:  0:00:11:21 (12): 0 Seconds
2022-09-08 09:07:21:  0: STDOUT: PROGRESS:  0:00:11:22 (13): 1 Seconds
2022-09-08 09:07:22:  0: STDOUT: PROGRESS:  0:00:11:23 (14): 0 Seconds
2022-09-08 09:07:22:  0: STDOUT: PROGRESS:  0:00:11:24 (15): 1 Seconds
2022-09-08 09:07:30:  0: STDOUT: PROGRESS:  0:00:11:25 (16): 8 Seconds
2022-09-08 09:07:32:  0: STDOUT: PROGRESS:  0:00:11:26 (17): 2 Seconds
2022-09-08 09:07:33:  0: STDOUT: PROGRESS:  0:00:11:27 (18): 0 Seconds
2022-09-08 09:07:33:  0: STDOUT: PROGRESS:  0:00:11:28 (19): 1 Seconds
2022-09-08 09:07:33:  0: STDOUT: PROGRESS:  0:00:11:29 (20): 0 Seconds
2022-09-08 09:07:34:  0: INFO: Process exit code: 0
2022-09-08 09:07:34:  0: INFO: Checking for file "C:\Users\light\Documents\ae_render_only_node.txt"
2022-09-08 09:07:34:  0: INFO: Attempting to delete "C:\Users\light\Documents\ae_render_only_node.txt" to allow After Effects to run in the workstation environment
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00340.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00341.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00342.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00343.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00344.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00345.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00346.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00347.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00348.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00349.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00350.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00351.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00352.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00353.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00354.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00355.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00356.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00357.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00358.exr"
2022-09-08 09:07:34:  0: INFO: Checking file size of "G:\test\DeadlineRenderTest_v1\Renders\AE\23-Test\CustomFixStressTest-23_JJ_v1-NoConcurrentTasks_00359.exr"
2022-09-08 09:07:34:  0: Done executing plugin command of type 'Render Task'
2022-09-08 09:07:36:  Scheduler Thread - Job's Limit Groups: 
2022-09-08 09:07:36:  Scheduler Thread - Error mapping G: to 192.168.1.167:8086: The network name cannot be found.
2022-09-08 09:07:37:  All job files are already synchronized

In this log it’s not taking too long but it adds up over time. Sometimes I’ve noticed its taking over 3 minutes to start the first frame on some projects

Here’s a snippet from a log of a different file showing the wildly different render times on different frames, sometimes over 2min compared to a few seconds

2022-09-07 11:56:37:  0: STDOUT: PROGRESS:  Post-Render Action: None
2022-09-07 11:56:37:  0: STDOUT: PROGRESS:  
2022-09-07 11:57:13:  0: STDOUT: PROGRESS:  01400 (1): 35 Seconds
2022-09-07 11:57:25:  0: STDOUT: PROGRESS:  01401 (2): 12 Seconds
2022-09-07 11:57:25:  0: STDOUT: PROGRESS:  01402 (3): 0 Seconds
2022-09-07 11:57:25:  0: STDOUT: PROGRESS:  01403 (4): 0 Seconds
2022-09-07 11:57:25:  0: STDOUT: PROGRESS:  01404 (5): 1 Seconds
2022-09-07 11:57:26:  0: STDOUT: PROGRESS:  01405 (6): 0 Seconds
2022-09-07 11:57:26:  0: STDOUT: PROGRESS:  01406 (7): 0 Seconds
2022-09-07 11:57:38:  0: STDOUT: PROGRESS:  01407 (8): 12 Seconds
2022-09-07 11:57:42:  0: STDOUT: PROGRESS:  01408 (9): 4 Seconds
2022-09-07 11:57:42:  0: STDOUT: PROGRESS:  01409 (10): 0 Seconds
2022-09-07 11:57:45:  0: STDOUT: PROGRESS:  01410 (11): 3 Seconds
2022-09-07 11:57:46:  0: STDOUT: PROGRESS:  01411 (12): 1 Seconds
2022-09-07 11:57:46:  0: STDOUT: PROGRESS:  01412 (13): 0 Seconds
2022-09-07 11:57:46:  0: STDOUT: PROGRESS:  01413 (14): 1 Seconds
2022-09-07 11:57:48:  0: STDOUT: PROGRESS:  01414 (15): 1 Seconds
2022-09-07 11:58:00:  0: STDOUT: PROGRESS:  01415 (16): 12 Seconds
2022-09-07 11:58:04:  0: STDOUT: PROGRESS:  01416 (17): 4 Seconds
2022-09-07 11:58:04:  0: STDOUT: PROGRESS:  01417 (18): 1 Seconds
2022-09-07 11:58:05:  0: STDOUT: PROGRESS:  01418 (19): 0 Seconds
2022-09-07 11:58:06:  0: STDOUT: PROGRESS:  01419 (20): 1 Seconds
2022-09-07 11:58:06:  0: STDOUT: PROGRESS:  01420 (21): 0 Seconds
2022-09-07 11:58:12:  0: STDOUT: PROGRESS:  01421 (22): 6 Seconds
2022-09-07 11:58:13:  0: STDOUT: PROGRESS:  01422 (23): 1 Seconds
2022-09-07 11:58:20:  0: STDOUT: PROGRESS:  01423 (24): 7 Seconds
2022-09-07 11:58:20:  0: STDOUT: PROGRESS:  01424 (25): 1 Seconds
2022-09-07 11:58:24:  0: STDOUT: PROGRESS:  01425 (26): 3 Seconds
2022-09-07 11:58:25:  0: STDOUT: PROGRESS:  01426 (27): 1 Seconds
2022-09-07 11:58:25:  0: STDOUT: PROGRESS:  01427 (28): 0 Seconds
2022-09-07 11:58:32:  0: STDOUT: PROGRESS:  01428 (29): 8 Seconds
2022-09-07 11:58:34:  0: STDOUT: PROGRESS:  01429 (30): 1 Seconds
2022-09-07 11:58:37:  0: STDOUT: PROGRESS:  01430 (31): 3 Seconds
2022-09-07 11:58:41:  0: STDOUT: PROGRESS:  01431 (32): 4 Seconds
2022-09-07 11:58:49:  0: STDOUT: PROGRESS:  01432 (33): 8 Seconds
2022-09-07 11:58:49:  0: STDOUT: PROGRESS:  01433 (34): 1 Seconds
2022-09-07 11:58:52:  0: STDOUT: PROGRESS:  01434 (35): 2 Seconds
2022-09-07 11:58:54:  0: STDOUT: PROGRESS:  01435 (36): 2 Seconds
2022-09-07 11:59:01:  0: STDOUT: PROGRESS:  01436 (37): 7 Seconds
2022-09-07 11:59:03:  0: STDOUT: PROGRESS:  01437 (38): 2 Seconds
2022-09-07 11:59:04:  0: STDOUT: PROGRESS:  01438 (39): 1 Seconds
2022-09-07 11:59:04:  0: STDOUT: PROGRESS:  01439 (40): 1 Seconds
2022-09-07 11:59:15:  0: STDOUT: PROGRESS:  01440 (41): 10 Seconds
2022-09-07 11:59:19:  0: STDOUT: PROGRESS:  01441 (42): 4 Seconds
2022-09-07 11:59:19:  0: STDOUT: PROGRESS:  01442 (43): 0 Seconds
2022-09-07 11:59:19:  0: STDOUT: PROGRESS:  01443 (44): 0 Seconds
2022-09-07 11:59:20:  0: STDOUT: PROGRESS:  01444 (45): 1 Seconds
2022-09-07 11:59:20:  0: STDOUT: PROGRESS:  01445 (46): 0 Seconds
2022-09-07 11:59:20:  0: STDOUT: PROGRESS:  01446 (47): 0 Seconds
2022-09-07 11:59:21:  0: STDOUT: PROGRESS:  01447 (48): 1 Seconds
2022-09-07 11:59:21:  0: STDOUT: PROGRESS:  01448 (49): 0 Seconds
2022-09-07 11:59:21:  0: STDOUT: PROGRESS:  01449 (50): 1 Seconds
2022-09-07 11:59:22:  0: STDOUT: PROGRESS:  01450 (51): 0 Seconds
2022-09-07 11:59:22:  0: STDOUT: PROGRESS:  01451 (52): 1 Seconds
2022-09-07 11:59:23:  0: STDOUT: PROGRESS:  01452 (53): 0 Seconds
2022-09-07 11:59:24:  0: STDOUT: PROGRESS:  01453 (54): 1 Seconds
2022-09-07 11:59:25:  0: STDOUT: PROGRESS:  01454 (55): 1 Seconds
2022-09-07 11:59:56:  0: STDOUT: PROGRESS:  01455 (56): 31 Seconds
2022-09-07 11:59:57:  0: STDOUT: PROGRESS:  01456 (57): 1 Seconds
2022-09-07 11:59:57:  0: STDOUT: PROGRESS:  01457 (58): 0 Seconds
2022-09-07 11:59:57:  0: STDOUT: PROGRESS:  01458 (59): 1 Seconds
2022-09-07 11:59:58:  0: STDOUT: PROGRESS:  01459 (60): 0 Seconds
2022-09-07 12:00:05:  0: STDOUT: PROGRESS:  01460 (61): 7 Seconds
2022-09-07 12:00:05:  0: STDOUT: PROGRESS:  01461 (62): 1 Seconds
2022-09-07 12:00:06:  0: STDOUT: PROGRESS:  01462 (63): 0 Seconds
2022-09-07 12:00:06:  0: STDOUT: PROGRESS:  01463 (64): 1 Seconds
2022-09-07 12:00:11:  0: STDOUT: PROGRESS:  01464 (65): 5 Seconds
2022-09-07 12:00:31:  0: STDOUT: PROGRESS:  01465 (66): 19 Seconds
2022-09-07 12:00:39:  0: STDOUT: PROGRESS:  01466 (67): 8 Seconds
2022-09-07 12:00:57:  0: STDOUT: PROGRESS:  01467 (68): 18 Seconds
2022-09-07 12:00:59:  0: STDOUT: PROGRESS:  01468 (69): 2 Seconds
2022-09-07 12:01:01:  0: STDOUT: PROGRESS:  01469 (70): 2 Seconds
2022-09-07 12:01:02:  0: STDOUT: PROGRESS:  01470 (71): 1 Seconds
2022-09-07 12:01:03:  0: STDOUT: PROGRESS:  01471 (72): 1 Seconds
2022-09-07 12:01:04:  0: STDOUT: PROGRESS:  01472 (73): 1 Seconds
2022-09-07 12:01:08:  0: STDOUT: PROGRESS:  01473 (74): 4 Seconds
2022-09-07 12:01:10:  0: STDOUT: PROGRESS:  01474 (75): 2 Seconds
2022-09-07 12:01:13:  0: STDOUT: PROGRESS:  01475 (76): 3 Seconds
2022-09-07 12:01:23:  0: STDOUT: PROGRESS:  01476 (77): 10 Seconds
2022-09-07 12:01:29:  0: STDOUT: PROGRESS:  01477 (78): 6 Seconds
2022-09-07 12:01:38:  0: STDOUT: PROGRESS:  01478 (79): 9 Seconds
2022-09-07 12:01:38:  0: STDOUT: PROGRESS:  01479 (80): 0 Seconds
2022-09-07 12:01:59:  0: STDOUT: PROGRESS:  01480 (81): 22 Seconds
2022-09-07 12:02:00:  0: STDOUT: PROGRESS:  01481 (82): 0 Seconds
2022-09-07 12:02:01:  0: STDOUT: PROGRESS:  01482 (83): 1 Seconds
2022-09-07 12:02:01:  0: STDOUT: PROGRESS:  01483 (84): 1 Seconds
2022-09-07 12:02:03:  0: STDOUT: PROGRESS:  01484 (85): 1 Seconds
2022-09-07 12:02:04:  0: STDOUT: PROGRESS:  01485 (86): 1 Seconds
2022-09-07 12:02:05:  0: STDOUT: PROGRESS:  01486 (87): 1 Seconds
2022-09-07 12:02:09:  0: STDOUT: PROGRESS:  01487 (88): 4 Seconds
2022-09-07 12:02:10:  0: STDOUT: PROGRESS:  01488 (89): 1 Seconds
2022-09-07 12:04:02:  0: STDOUT: PROGRESS:  01489 (90): 1 Min, 52 Sec
2022-09-07 12:04:04:  0: STDOUT: PROGRESS:  01490 (91): 2 Seconds
2022-09-07 12:06:26:  0: STDOUT: PROGRESS:  01491 (92): 2 Min, 22 Sec
2022-09-07 12:06:26:  0: STDOUT: PROGRESS:  01492 (93): 0 Seconds
2022-09-07 12:06:26:  0: STDOUT: PROGRESS:  01493 (94): 1 Seconds
2022-09-07 12:06:27:  0: STDOUT: PROGRESS:  01494 (95): 0 Seconds
2022-09-07 12:06:27:  0: STDOUT: PROGRESS:  01495 (96): 0 Seconds
2022-09-07 12:06:27:  0: STDOUT: PROGRESS:  01496 (97): 0 Seconds
2022-09-07 12:06:27:  0: STDOUT: PROGRESS:  01497 (98): 1 Seconds
2022-09-07 12:06:28:  0: STDOUT: PROGRESS:  01498 (99): 0 Seconds
2022-09-07 12:06:28:  0: STDOUT: PROGRESS:  01499 (100): 0 Seconds
2022-09-07 12:06:34:  0: STDOUT: PROGRESS:  01500 (101): 6 Seconds
2022-09-07 12:06:37:  0: STDOUT: PROGRESS:  01501 (102): 3 Seconds
2022-09-07 12:06:38:  0: STDOUT: PROGRESS:  01502 (103): 1 Seconds
Success

Anyone have any ideas? I tried running the Worker in Admin mode but that didn’t seem to help at all

anthonygelatka · September 9, 2022, 7:31am

Is this possibly a network access issue? where the node is stuck or waiting to access the file as it’s in use elsewhere on the network?

If you submit the same scene again does it get stuck at the same frames?

Does a completely fresh project, submit and closed have the same problem?

JJ_Painter · September 9, 2022, 12:48pm

GM! Thanks for the reply!

I tried running a completely fresh project using no plugins (just layered a bunch of .exr and .png sequences) and the first frame took a long time to start. I tested it with just my PC first then I ran it on the whole render farm and the first frame took a long time to start in both cases. However, it did appear to run at a consistent speed once it got started rendering.

I resubmitted the same problem scene from before and it got hung up on the 8th frame consistently

I decided to disable our network throttling on Deadline to see if that could be contributing to the issue but I’m still getting the same issue with the first frame taking much longer to start than it should

Network traffic shouldn’t be an issue, I ran these tests before anyone else was in the building

JJ_Painter · September 9, 2022, 12:58pm

I just figured it out - I resubmitted the project file using After Effects 2021 instead of 2022 and it’s working flawlessly now. We are running Deadline version 10.1.20.2 which doesn’t officially support 2022 and we are using the 2021 submission script for 2022

Would it be possible to share the AE 2022 submission script? We are planning on upgrading Deadline to the latest version at the end of the month

anthonygelatka · September 9, 2022, 1:10pm

AfterEffects.zip (11.8 KB)
I imagine the script is only an adjustment to the .param file.

attached a rar in a zip as it didn’t like rar

JJ_Painter · September 9, 2022, 1:54pm

Thank you! Could you also send me the “SubmitAEToDeadline.jsx” file in \submission\AfterEffects\Main ?
I believe some tweaks got made to that as well

anthonygelatka · September 9, 2022, 2:58pm

DeadlineAfterEffectsClient.zip (1.2 KB)
got stuck in meeting, here you go
SubmitAEToDeadline.zip (23.2 KB)

JJ_Painter · September 9, 2022, 3:13pm

Thank you so much! I replaced my files with the ones you gave me but still getting long first frame renders. I’m going to hope this gets fixed when we upgrade Deadline to the latest version at the end of the month