2014-09-11 10:01:07:  Queueing: ['5']
2014-09-11 10:01:07:  Dependency script returned 1 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-11 10:01:32:  Clean Up Thread - Performing house cleaning
2014-09-11 10:01:32:  Update timeout has been set to 300 seconds
2014-09-11 10:01:32:  Stdout Handling Enabled: False
2014-09-11 10:01:32:  Popup Handling Enabled: False
2014-09-11 10:01:32:  Using Process Tree: True
2014-09-11 10:01:32:  Hiding DOS Window: True
2014-09-11 10:01:32:  Creating New Console: False
2014-09-11 10:01:32:  Executable: "/opt/Thinkbox/Deadline6/bin/deadlinecommand.exe"
2014-09-11 10:01:32:  Argument: -DoHouseCleaning 10 True
2014-09-11 10:01:32:  Startup Directory: "/opt/Thinkbox/Deadline6/bin"
2014-09-11 10:01:32:  Process Priority: BelowNormal
2014-09-11 10:01:32:  Process Affinity: default
2014-09-11 10:01:32:  Process is now running
2014-09-11 10:01:38:  Performing Job Cleanup Scan...
2014-09-11 10:01:38:      Job Cleanup Scan - Loading completed jobs
2014-09-11 10:01:55:      Job Cleanup Scan - Loaded 9939 completed jobs in 16.583 s
2014-09-11 10:01:55:      Job Cleanup Scan - Scanning completed jobs
2014-09-11 10:01:56:      Job Cleanup Scan - Deleted completed job "[FAST7] Create Proxy Quicktime: GS_162_1570_2d_precomps_paint04_v0008" because Delete On Complete was enabled.
2014-09-11 10:01:59:      Pending Job Scan - Released pending tasks [5] because the frames they depends on have finished and/or their required assets are available.

52 seconds to queue a single task!

2014-09-11 10:02:00:  Queueing: ['89']
2014-09-11 10:02:00:  Dependency script returned 1 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-11 10:02:01:      Job Cleanup Scan - Deleted completed job "[EXO] Create Proxy Quicktime: RS_190_2050_Light-Tech_beauty_v0009_r" because Delete On Complete was enabled.
2014-09-11 10:02:04:      Job Cleanup Scan - Deleted completed job "[YETI] Create Proxy Quicktime: MR_246_0200_2d_slapcomps_fxslap_v0006" because Delete On Complete was enabled.
2014-09-11 10:02:08:      Job Cleanup Scan - Deleted completed job "[FAST7] Create Proxy Quicktime: SG_153_1010_2d_plates_bgarray_projection_rt_v0004" because Delete On Complete was enabled.
2014-09-11 10:02:10:      Job Cleanup Scan - Deleted completed job "[EXO] Create Proxy Quicktime: RS_190_2050_Light-Tech_beauty_v0009_r" because Delete On Complete was enabled.
2014-09-11 10:02:14:      Job Cleanup Scan - Deleted completed job "[MJ] Create Proxy Quicktime: RP_093_0230_2d_comps_main_v0020" because Delete On Complete was enabled.
2014-09-11 10:02:17:      Job Cleanup Scan - Deleted completed job "[FAST7] ShootBot: Avid QT TLR_000_1750_2d_tcomps_outside_exposure_wedge_v0002" because Delete On Complete was enabled.
2014-09-11 10:02:20:      Job Cleanup Scan - Deleted completed job "[FAST7] ShootBot: Avid QT SG_153_1010_2d_plates_bgarray_projection_rt_v0004" because Delete On Complete was enabled.
2014-09-11 10:02:23:      Job Cleanup Scan - Deleted completed job "[EXO] ShootBot: Avid QT RS_190_7030_FL-LeadSurfSprayMist_v0029" because Delete On Complete was enabled.
2014-09-11 10:02:23:      Job Cleanup Scan - Deleted 10 and archived 0 completed jobs in 28.379 s
2014-09-11 10:02:23:      Job Cleanup Scan - Done.
2014-09-11 10:02:23:  Purging Unsubmitted Jobs
2014-09-11 10:02:23:      Unsubmitted Job Scan - Loading unsubmitted jobs
2014-09-11 10:02:25:      Unsubmitted Job Scan - Loaded 2 unsubmitted jobs in 704.699 ms
2014-09-11 10:02:25:      Unsubmitted Job Scan - Deleted 0 unsubmitted jobs in 2.000 μs
2014-09-11 10:02:25:      Unsubmitted Job Scan - Done.
2014-09-11 10:02:25:  Purging Deleted Jobs
2014-09-11 10:02:25:      Deleted Job Scan - Loading deleted jobs
2014-09-11 10:02:25:      Deleted Job Scan - Loaded 9800 deleted jobs in 507.222 ms
2014-09-11 10:02:25:      Deleted Job Scan - Purging deleted job '541082811d5ce10ae4d77913' because it was deleted over 24 hour(s) ago
2014-09-11 10:02:26:      Deleted Job Scan - Purging deleted job '5410835761078a0c3c9b79cb' because it was deleted over 24 hour(s) ago
2014-09-11 10:02:26:      Deleted Job Scan - Purging deleted job '54108375ad996b1314b256cd' because it was deleted over 24 hour(s) ago
2014-09-11 10:02:27:      Deleted Job Scan - Purging deleted job '541082fe81dee029287d9ed6' because it was deleted over 24 hour(s) ago
2014-09-11 10:02:28:      Deleted Job Scan - Purging deleted job '5410833d069eb45dcc26406d' because it was deleted over 24 hour(s) ago
2014-09-11 10:02:29:      Deleted Job Scan - Purging deleted job '5410827b929e66467426d0d2' because it was deleted over 24 hour(s) ago
2014-09-11 10:02:30:      Deleted Job Scan - Purging deleted job '541082481c26ae48087e4414' because it was deleted over 24 hour(s) ago
2014-09-11 10:02:31:      Deleted Job Scan - Purging deleted job '541082844c2e5fbe5cdf5e8f' because it was deleted over 24 hour(s) ago
2014-09-11 10:02:31:      Deleted Job Scan - Purging deleted job '5410835461078a0a00965a40' because it was deleted over 24 hour(s) ago
2014-09-11 10:02:32:      Deleted Job Scan - Purging deleted job '5410836cad996b1ce4d0b233' because it was deleted over 24 hour(s) ago
2014-09-11 10:02:32:      Deleted Job Scan - Purging deleted job '54108372ad996b19749a89fb' because it was deleted over 24 hour(s) ago
2014-09-11 10:02:33:      Deleted Job Scan - Purged 11 deleted jobs in 7.873 s
2014-09-11 10:02:33:      Deleted Job Scan - Done.
2014-09-11 10:02:33:  Purging Old Job Auxiliary Files
2014-09-11 10:02:33:      Auxiliary File Scan - Scanning for auxiliary directories
2014-09-11 10:02:39:      Auxiliary File Scan - Found 25414 auxiliary directories in 6.430 s
2014-09-11 10:02:39:      Auxiliary File Scan - Loading job IDs
2014-09-11 10:02:41:      Auxiliary File Scan - Loaded 25406 job IDs in 1.684 s
2014-09-11 10:02:45:      Pending Job Scan - Released pending tasks [89] because the frames they depends on have finished and/or their required assets are available.

45 seconds for a single task

2014-09-11 10:02:46:  Queueing: ['89']
2014-09-11 10:02:46:  Dependency script returned 1 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-11 10:03:08:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-11 10:03:08:  Server Thread - Auto Config: Picking configuration based on:
2014-09-11 10:03:08:  Server Thread -   LAPRO0419
2014-09-11 10:03:08:  Server Thread -   ::ffff:172.18.3.69
2014-09-11 10:03:08:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-11 10:03:08:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-11 10:03:08:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.3.69
2014-09-11 10:03:08:  Server Thread - Auto Config: Configuration sent
2014-09-11 10:03:36:      Pending Job Scan - Released pending tasks [89] because the frames they depends on have finished and/or their required assets are available.

50 seconds, single task

Did you see that beta 1 of Deadline 6.2.1 was released earlier this week?
viewtopic.php?f=85&t=12331

This includes the fix that Jon made that should help with the performance of releasing these pending tasks. You should be able to just update your Pulse machine initially to see if this helps.

Cheers,
Ryan

After killing all deadline processes and restarting them again, its somewhat faster:

2014-09-11 10:25:05:  Queueing: ['8', '14', '15']
2014-09-11 10:25:05:  Dependency script returned 3 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-11 10:25:15:      Pending Job Scan - Released pending tasks [8,14,15] because the frames they depends on have finished and/or their required assets are available.

10 seconds for 3 tasks, faster than before, but about 1/100th the speed that it should be,… this should take a ~50-100ms, if that.

Something is going on in there guys thats making things very sad for us…

Did you see my previous post (viewtopic.php?f=86&t=12125&p=54660#p54656)?

No i havent!

Will check the new build asap

Ooh, nice. Is it safe to assume that this update will be safe to deploy via the client auto-upgrade feature when the time comes?

We just found a bug in the build that was preventing Slaves from properly marking Jobs as failed through Failure Detection, so if you rely heavily on Failure Detection, I’d recommend waiting for the next patch. I fixed the issue internally already, so we should get another build out relatively quickly.

But yeah, when the time comes, auto-upgrade should work .

Laszlo, I think you should still put the new build on your Pulse machine at least though, if you have time. This shouldn’t impact Failure Detection, and should help lighten the load on the DB when doing dependency checks.

Cheers,
Jon

Cool, ill do that and see how it behaves!

2014-09-12 11:23:08: Queueing: [‘110’, ‘111’, ‘112’, ‘113’, ‘114’]
2014-09-12 11:23:08: Dependency script returned 5 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-12 11:23:08: Pending Job Scan - Released pending tasks [110,111,112,113,114] because the frames they depends on have finished and/or their required assets are available.

So far, this is working GREAT!

Checking the logs, even the old version finished queuing in <1 second this morning, so we will have to keep an eye on it before declaring victory.

The new build is working so far, but its much crashier. We get a pulse crash every 50 mins or so

Some of the last lines in the log are:

log #9

2014-09-12 13:56:37:  Queueing: ['16', '17']
2014-09-12 13:56:37:  Dependency script returned 2 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-12 13:56:37:      Pending Job Scan - Released pending tasks [16,17] because the frames they depends on have finished and/or their required assets are available.

log #10

2014-09-12 14:37:49:  Queueing: []
2014-09-12 14:37:49:  Dependency script returned 0 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-12 14:37:51:      Job Cleanup Scan - Loaded 9925 completed jobs in 12.748 s
2014-09-12 14:37:51:      Job Cleanup Scan - Scanning completed jobs
2014-09-12 14:37:53:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-12 14:37:53:  Server Thread - Auto Config: Picking configuration based on:
2014-09-12 14:37:53:  Server Thread -   LAPRO0481
2014-09-12 14:37:53:  Server Thread -   ::ffff:172.18.3.131
2014-09-12 14:37:53:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-12 14:37:53:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-12 14:37:53:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.3.131
2014-09-12 14:37:53:  Server Thread - Auto Config: Configuration sent

log #11:

2014-09-12 15:30:18:  Dependency script returned 0 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-12 15:30:18:      Pending Job Scan - Released pending job "[GOLD] Create Proxy Quicktime: BL_000_0015_2d_plates_bg1_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:18:      Pending Job Scan - Released pending job "[GOLD] Create Proxy Quicktime: AG_000_0055_AutoATC3dsmax_beautyJPG_v0004" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:19:      Pending Job Scan - Released pending job "[GOLD] Create Proxy Quicktime: AG_000_0055_FL-DamHappySur_beautyJPG_v0005" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:20:      Pending Job Scan - Released pending job "[GOLD] Create Proxy Quicktime: BL_000_0055_2d_plates_bg1_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:21:      Pending Job Scan - Released pending job "[GOLD] Create Proxy Quicktime: SB_000_0015_Light-Buildings_beauty_v0005" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:21:      Pending Job Scan - Released pending job "[GOLD] Create Proxy Quicktime: RB_000_0367_2d_tcomps_gsrs1_key_dn_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:21:      Pending Job Scan - Released pending job "[FAST7] Create Proxy Quicktime: PC_200_1648_2d_roto_bg_mb_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:22:      Pending Job Scan - Released pending job "[YETI] Create Proxy Quicktime: KA_060_0130_2d_tcomps_main_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:22:      Pending Job Scan - Released pending job "[GOLD] Create Proxy Quicktime: BL_000_0020_2d_plates_bg1_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:22:      Pending Job Scan - Released pending job "[GOLD] Create Proxy Quicktime: BL_000_0030_2d_plates_bg1_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:23:      Pending Job Scan - Released pending job "[GOLD] Create Proxy Quicktime: CS_000_0120_2d_precomps_gs1_key_wr_v0010" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:23:      Pending Job Scan - Released pending job "[FAST7] Create Proxy Quicktime: PC_200_1648_2d_roto_bg_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:23:      Pending Job Scan - Released pending job "[YETI] Upload Proxy Quicktime: MR_248_0610_2d_slapcomps_animAllRender_v0003" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:26:      Pending Job Scan - Released pending job "[EXO] Upload Proxy Quicktime: RS_190_1980_FL-Happy_beauty_v0041_l" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:27:      Pending Job Scan - Released pending job "[GOLD] Upload Proxy Quicktime: BL_000_0035_2d_plates_bg1_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:27:      Pending Job Scan - Released pending job "[FAST7] Upload Proxy Quicktime: TJ_117_1550_FXTP-GlassShatter-QCcheck_beautyJPG_v0040" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:28:      Pending Job Scan - Released pending job "[MJ] Upload Proxy Quicktime: RP_093_0180_2d_precomps_bg_dpo_v0057" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:28:      Pending Job Scan - Released pending job "[MJ] Upload Proxy Quicktime: RP_093_0180_2d_comps_main_v0057" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:29:      Pending Job Scan - Released pending job "[FAST7] Upload Proxy Quicktime: TJ_117_1910_2d_slapcomps_test_v0024" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:29:      Pending Job Scan - Released pending job "[GOLD] Upload Proxy Quicktime: BL_000_0045_2d_plates_bg1_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:30:      Pending Job Scan - Released pending job "[GOLD] Upload Proxy Quicktime: BL_000_0025_2d_plates_bg1_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:30:      Pending Job Scan - Released pending job "[GOLD] Upload Proxy Quicktime: BL_000_0050_2d_plates_bg1_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:30:      Pending Job Scan - Released pending job "[FAST7] Upload Proxy Quicktime: GS_162_3450_pano_beauty_v0013" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:30:      Pending Job Scan - Released pending job "[YETI] Upload Proxy Quicktime: MR_249_1200_2d_comps_main_v0004" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:31:      Pending Job Scan - Released pending job "[GOLD] Upload Proxy Quicktime: BL_000_0060_2d_plates_bg1_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:31:      Pending Job Scan - Released pending job "[GOLD] Upload Proxy Quicktime: BL_000_0040_2d_plates_bg1_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:31:      Pending Job Scan - Released pending job "[UMP] Upload Proxy Quicktime: EP_144_0185_sr_cylinder_tower_mt_v0014" because its dependencies are finished and/or its required assets are available.
2014-09-12 15:30:31:      Pending Job Scan - Released pending job "[GOLD] Upload Proxy Quicktime: BL_000_0060_2d_plates_bg1_v0001" because its dependencies are finished and/or its required assets are available.

log #12

2014-09-12 16:40:58:  Queueing: ['36']
2014-09-12 16:40:58:  Dependency script returned 1 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-12 16:40:59:      Pending Job Scan - Released pending tasks [36] because the frames they depends on have finished and/or their required assets are available.
2014-09-12 16:40:59:  CheckPathMapping: Swapped "//S2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py" with "/mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py"
2014-09-12 16:40:59:  Executing dependency script: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-12 16:40:59:  Running Scanline handleJobDependencies checker v0.42 for JobID: 541319c402949860786ae68f TaskIDs: [u'48', u'49', u'50', u'51', u'52', u'53', u'54', u'55', u'56', u'57', u'58', u'59', u'60', u'61', u'62', u'63', u'64', u'65', u'66', u'67', u'68', u'69', u'70', u'71', u'72', u'73', u'74', u'75', u'76', u'77', u'78', u'79', u'80', u'81', u'82', u'83', u'84', u'85', u'86', u'87', u'88', u'89', u'90', u'91', u'92', u'93', u'94', u'95', u'96', u'97', u'98', u'99', u'100', u'101', u'102', u'103', u'104', u'105', u'106', u'107', u'108', u'109', u'110', u'111', u'112', u'113', u'114', u'115', u'116', u'117', u'118', u'119', u'120', u'121', u'122', u'123', u'124', u'125', u'126', u'127', u'128', u'129', u'130', u'131', u'132', u'133', u'134', u'135', u'136', u'137', u'138', u'139']
2014-09-12 16:40:59:    Dependency to check: [Flowline] /mnt/isila/projects/exo/scenes/RS_190_1578/cache/flowline/LeadSpray/v0010_str_LeadMoreInhe2/LeadSpray
2014-09-12 16:40:59:  Found: Spacial 16
2014-09-12 16:40:59:  globbing: set([])
2014-09-12 16:40:59:  Spacial/Cluster flowline sim. Testing per frame. Existing folders: [977, 978, 979, 980, 981, 982, 983, 984, 985, 986, 987, 988, 989, 990, 991, 992, 993, 994, 995, 996, 997, 998, 999, 1000, 1001, 1002, 1003, 1004, 1005, 1006, 1007, 1008, 1009, 1010, 1011, 1012, 1013, 1014, 1015, 1016, 1017, 1018, 1019, 1020, 1021, 1022, 1023, 1024, 1025, 1026, 1027, 1028, 1029, 1030, 1031, 1032, 1033, 1034, 1035, 1036, 1037, 1038, 1039, 1040, 1041, 1042, 1043, 1044, 1045, 1046, 1047, 1048, 1049, 1050, 1051, 1052, 1053, 1054, 1055, 1056, 1057, 1058, 1059, 1060, 1061, 1062, 1063, 1064, 1065, 1066, 1067, 1068, 1069, 1070, 1071, 1072, 1073, 1074, 1075, 1076, 1077, 1078, 1079, 1080, 1081, 1082, 1083, 1084, 1085, 1086, 1087, 1088, 1089, 1090, 1091, 1092, 1093, 1094, 1095, 1096, 1097, 1098, 1099, 1100, 1101, 1102, 1103, 1104, 1105, 1106, 1107, 1108, 1109, 1110, 1111, 1112, 1113, 1114, 1115]
2014-09-12 16:40:59:    globbing done. Checking against task list..

log #13

2014-09-12 17:37:09:    globbing done. Checking against task list..
2014-09-12 17:37:09:  Queueing: ['75', '76']
2014-09-12 17:37:09:  Dependency script returned 2 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py

log #14

2014-09-12 18:25:16:  Queueing: []
2014-09-12 18:25:16:  Dependency script returned 0 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-12 18:25:16:      Pending Job Scan - Released pending job "[FAST7] Create Proxy Quicktime: TJ_117_1910_2d_mp_mpbg_v0003" because its dependencies are finished and/or its required assets are available.
2014-09-12 18:25:16:      Pending Job Scan - Released pending job "[SEA] Create Proxy Quicktime: ESS_032_0940_Light-Sea_beauty_v0007" because its dependencies are finished and/or its required assets are available.
2014-09-12 18:25:16:      Pending Job Scan - Released pending job "[FAST7] Create Proxy Quicktime: TJ_117_1910_2d_mp_mpbg_v0004" because its dependencies are finished and/or its required assets are available.
2014-09-12 18:25:16:      Pending Job Scan - Released pending job "[SEA] Create Proxy Quicktime: SQU_039_0510_comp_breakdown_v0008" because its dependencies are finished and/or its required assets are available.
2014-09-12 18:25:16:      Pending Job Scan - Released pending job "[GOLD] Upload Proxy Quicktime: CS_000_0145_2d_slapcomps_lightingslapcomp_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 18:25:17:      Pending Job Scan - Released pending job "[UMP] Upload Proxy Quicktime: EP_144_0185_tcomp_paint_test_v0014" because its dependencies are finished and/or its required assets are available.
2014-09-12 18:25:17:      Pending Job Scan - Released pending job "[GOLD] Upload Proxy Quicktime: RB_000_0545_AutoATCMaya_proxy_v0005" because its dependencies are finished and/or its required assets are available.
2014-09-12 18:25:17:      Pending Job Scan - Released pending job "[EXO] Upload Proxy Quicktime: RS_190_7030_FL-LeadSurfaceB04_beauty_v0088_l" because its dependencies are finished and/or its required assets are available.
2014-09-12 18:25:17:      Pending Job Scan - Released pending job "[MJ] Upload Proxy Quicktime: RP_093_0220_2d_comps_main_v0061" because its dependencies are finished and/or its required assets are available.
2014-09-12 18:25:17:      Pending Job Scan - Released pending job "[MJ] ShootBot: Editorial Sync RP_093_0220_2d_comps_main_v0061" because its dependencies are finished and/or its required assets are available.
2014-09-12 18:25:17:      Pending Job Scan - Released pending job "[FAST7] ShootBot: Editorial Sync TJ_117_1810_2d_slapcomps_fxsparks_v0001" because its dependencies are finished and/or its required assets are available.
2014-09-12 18:25:17:      Pending Job Scan - Released 11 pending jobs and 171 pending tasks in 34.193 s
2014-09-12 18:25:17:      Pending Job Scan - Done.
2014-09-12 18:25:18:  Process exit code: 0
2014-09-12 18:25:26:      Job Cleanup Scan - Archived completed job "[EXO] RS_190_2060_v0630_str_FullLeadLatest_cache_flowline_LeadHappy_0 " because Auto Job Cleanup is enabled and this job has been complete for more than 10 days.
2014-09-12 18:25:27:      Job Cleanup Scan - Deleted completed job "[MJ] Create Proxy Quicktime: RP_093_0220_2d_comps_main_v0061" because Delete On Complete was enabled.
2014-09-12 18:25:27:      Job Cleanup Scan - Deleted completed job "[GOLD] Create Proxy Quicktime: CS_000_0145_2d_slapcomps_lightingslapcomp_v0001" because Delete On Complete was enabled.

With the exception of log 12, they all seem to be crashing around the time the executable gets the list of frames to set to queued.

We have a cronjob that asks the launcher to restart pulse every 5 mins, so thankfull this isn’t causing any major problems…

Sadly the core-dumps dont seem to be working:

Sep 12 19:14:19 deadline02 abrt[32345]: Saved core dump of pid 21776 (/opt/mono-2.10.9/bin/mono) to /var/spool/abrt/ccpp-2014-09-12-19:11:02-21776 (3248226304 bytes)
Sep 12 19:14:19 deadline02 abrtd: Directory ‘ccpp-2014-09-12-19:11:02-21776’ creation detected
Sep 12 19:14:19 deadline02 abrtd: Executable ‘/opt/mono-2.10.9/bin/mono’ doesn’t belong to any package
Sep 12 19:14:19 deadline02 abrtd: ‘post-create’ on ‘/var/spool/abrt/ccpp-2014-09-12-19:11:02-21776’ exited with 1
Sep 12 19:14:19 deadline02 abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2014-09-12-19:11:02-21776, deleting

What exactly is the cronjob doing? Does it just check if Pulse is running and start it back up again if it’s not, or does it always try to restart Pulse even if it’s running? If it’s the latter, I’m wondering if the crash is due to Pulse being killed because it’s not exiting in a timely fashion when being told to shutdown.

Thanks!
Ryan

It asks the launcher to start pulse

0-59/2 * * * * /opt/Thinkbox/Deadline6/bin/deadlinelauncher -pulse -nogui >/dev/null 2>&1

Also, this type of crashing was not happening before this build (and this auto-restarting has been there for about a year)

Based on the logs, the crashes happen out of sync with the restart attempts (which is every 5 mins)

2014-09-13 22:32:15: CheckPathMapping: Swapped “//S2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py” with “/mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py”
2014-09-13 22:32:15: Executing dependency script: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-13 22:32:15: Running Scanline handleJobDependencies checker v0.42 for JobID: 5414d41010f8520ee4f853e3 TaskIDs: [u’129’, u’130’, u’131’, u’132’, u’133’, u’134’, u’135’, u’136’, u’137’, u’138’, u’139’, u’140’, u’141’, u’142’, u’143’, u’144’, u’145’, u’146’, u’147’, u’148’, u’149’, u’150’, u’151’, u’152’, u’153’, u’154’, u’155’, u’156’, u’157’, u’158’, u’159’, u’160’, u’161’, u’162’, u’163’, u’164’, u’165’, u’166’, u’167’, u’168’, u’169’, u’170’, u’171’, u’172’, u’173’, u’174’, u’175’, u’176’, u’177’, u’178’, u’179’, u’180’, u’181’, u’182’, u’183’, u’184’, u’185’, u’186’, u’187’, u’188’, u’189’, u’190’, u’191’, u’192’, u’193’, u’194’, u’195’, u’196’, u’197’, u’198’, u’199’, u’200’, u’201’, u’202’, u’203’, u’204’, u’205’, u’206’, u’207’, u’208’]

Happened 2 mins after the attempted restart, and 3 mins before the next attemp. Same with the crashed pulse logs i posted earlier

After talking this over with Ryan, we think this might be related to the Standard Out redirection to Pulse. This would definitely have been made worse by the recent builds, given that we are always doing all housecleaning operations, and we made the dependency checks faster (making Pulse in general a lot more verbose).

So the plan right now is to try and get you a new DLL you can drop in that will split out the logs for housecleaning/dependency checks (and NOT redirect them to the Pulse log). We were planning on doing this for you guys eventually anyways, so we figure this way we will hopefully get two birds with one stone

It shouldn’t be too bad to do, we should definitely be able to get you something to test out this week. In the meantime, can you try turning off the Pulse Verbose Logging, and maybe take out some of the output logging in the actual dependency script? I’d be curious to see if that makes a difference in Pulse’s stability.

Cheers,
Jon

Aside from the crashing issue, which i guess you guys are looking into, i ran some metrics as to why its taking such a long time to do the checks:

These are just 4 random pending checks from a saturday. You can see that while the ‘releasing’ time really improved (slowest is around 3 seconds, averaging around 0.3), it simply just takes ages to run all these checks consecutively.
We are currently investigating options to parallelize the checking, essentially rewrite the whole pending check as a standalone script and run 50 of those checks parallel, independent of pulse. We almost missed a delivery this weekend due to this issue

Pending Check 00, Start: 2014-09-13 22:38:02 End: 2014-09-13 22:52:51 Duration: 0:14:49 Total Check Count: 441
Average time taken to run checks: 1.14512471655s Longest check: 5s (#42) Quickest Check: 0
Average time taken to release tasks: 0.361413043478s Longest check: 3s (#63) Quickest Check: 0

Pending Check 01, Start: 2014-09-13 22:54:27 End: 2014-09-13 23:04:34 Duration: 0:10:07 Total Check Count: 448
Average time taken to run checks: 0.866071428571s Longest check: 6s (#433) Quickest Check: 0
Average time taken to release tasks: 0.31328320802s Longest check: 3s (#7) Quickest Check: 0

Pending Check 02, Start: 2014-09-13 23:06:00 End: 2014-09-13 23:16:46 Duration: 0:10:46 Total Check Count: 438
Average time taken to run checks: 0.915525114155s Longest check: 20s (#432) Quickest Check: 0
Average time taken to release tasks: 0.195195195195s Longest check: 3s (#1) Quickest Check: 0

Pending Check 03, Start: 2014-09-13 23:18:11 End: 2014-09-13 23:25:20 Duration: 0:07:09 Total Check Count: 434
Average time taken to run checks: 0.608294930876s Longest check: 25s (#426) Quickest Check: 0
Average time taken to release tasks: 0.112121212121s Longest check: 2s (#171) Quickest Check: 0

Analyzing further logs, i still am finding periods of release that are extremely slow (50-150 seconds for a single job):

104 seconds, 1 job:

2014-09-14 15:48:28:  Dependency script returned 209 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-14 15:48:49:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:48:49:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:48:49:  Server Thread -   LAPRO1642
2014-09-14 15:48:49:  Server Thread -   ::ffff:172.18.15.52
2014-09-14 15:48:49:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:48:49:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:48:49:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.15.52
2014-09-14 15:48:49:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:48:51:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:48:51:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:48:51:  Server Thread -   lapro1412
2014-09-14 15:48:51:  Server Thread -   ::ffff:172.18.0.112
2014-09-14 15:48:51:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:48:51:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:48:51:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.112
2014-09-14 15:48:51:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:49:11:      Job Report Scan - Purging job reports for '541259ff10f85214f4f8301e' because the job no longer exists
2014-09-14 15:49:12:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:49:12:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:49:12:  Server Thread -   LAPRO1642
2014-09-14 15:49:12:  Server Thread -   ::ffff:172.18.15.52
2014-09-14 15:49:12:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:49:12:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:49:12:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.15.52
2014-09-14 15:49:12:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:49:34:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:49:34:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:49:34:  Server Thread -   lapro1408
2014-09-14 15:49:34:  Server Thread -   ::ffff:172.18.0.108
2014-09-14 15:49:34:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:49:34:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:49:34:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.108
2014-09-14 15:49:34:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:50:11:      Job Report Scan - Purging job reports for '54125a0710f852210c4e68fb' because the job no longer exists
2014-09-14 15:50:12:      Pending Job Scan - Released pending tasks [-1,0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179,180,181,182,183,184,185,186,187,188,189,190,191,192,193,194,195,196,197,198,199,200,201,202,203,204,205,206,207,208] because the frames they depends on have finished and/or their required assets are available.

59 seconds, 1 job:

2014-09-14 15:58:27:  Queueing: ['0', '1', '2', '3', '4', '5', '6', '7', '8', '9', '10', '11', '12', '13', '14', '15', '16', '17', '18', '19', '20', '21', '22', '23', '24', '25', '26', '27', '28', '29', '30', '31', '32', '33', '34', '35', '36', '37', '38', '39', '40', '41', '42', '43', '44', '45', '46', '47', '48', '49', '50', '51', '52', '53', '54', '55', '56', '57', '58', '59', '60', '61', '62', '63', '64', '65', '66', '67', '68', '69', '70', '71', '72', '73', '74', '75', '76', '77', '78', '79', '80', '81', '82', '83', '84', '85', '86', '87', '88', '89', '90', '91', '92', '93', '94', '95', '96', '97', '98', '99', '100', '101', '102', '103', '104', '105', '106', '107', '108', '109', '110', '111', '112', '113', '114', '115', '116', '117', '118', '119']
2014-09-14 15:58:27:  Dependency script returned 120 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-14 15:58:28:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:28:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:28:  Server Thread -   lapro1343
2014-09-14 15:58:28:  Server Thread -   ::ffff:172.18.0.43
2014-09-14 15:58:28:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:28:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:28:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.43
2014-09-14 15:58:28:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:29:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:29:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:29:  Server Thread -   lapro1348
2014-09-14 15:58:29:  Server Thread -   ::ffff:172.18.0.48
2014-09-14 15:58:29:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:29:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:29:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.48
2014-09-14 15:58:29:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:29:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:29:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:29:  Server Thread -   lapro1339
2014-09-14 15:58:29:  Server Thread -   ::ffff:172.18.0.39
2014-09-14 15:58:29:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:29:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:29:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.39
2014-09-14 15:58:29:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:30:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:30:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:30:  Server Thread -   LAPRO1646
2014-09-14 15:58:30:  Server Thread -   ::ffff:172.18.15.56
2014-09-14 15:58:30:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:30:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:30:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.15.56
2014-09-14 15:58:30:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:31:      Job Report Scan - Purging job reports for '54125a5110f8520ac8020f7d' because the job no longer exists
2014-09-14 15:58:31:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:31:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:31:  Server Thread -   lapro1405
2014-09-14 15:58:31:  Server Thread -   ::ffff:172.18.0.105
2014-09-14 15:58:31:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:31:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:31:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.105
2014-09-14 15:58:31:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:31:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:31:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:31:  Server Thread -   lapro1408
2014-09-14 15:58:31:  Server Thread -   ::ffff:172.18.0.108
2014-09-14 15:58:31:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:31:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:31:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.108
2014-09-14 15:58:31:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:34:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:34:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:34:  Server Thread -   lapro1393
2014-09-14 15:58:34:  Server Thread -   ::ffff:172.18.0.93
2014-09-14 15:58:34:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:34:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:34:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.93
2014-09-14 15:58:34:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:42:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:42:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:42:  Server Thread -   lapro1386
2014-09-14 15:58:42:  Server Thread -   ::ffff:172.18.0.86
2014-09-14 15:58:42:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:42:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:42:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.86
2014-09-14 15:58:42:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:44:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:44:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:44:  Server Thread -   lapro1409
2014-09-14 15:58:44:  Server Thread -   ::ffff:172.18.0.109
2014-09-14 15:58:44:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:44:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:44:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.109
2014-09-14 15:58:44:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:50:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:50:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:50:  Server Thread -   lapro1396
2014-09-14 15:58:50:  Server Thread -   ::ffff:172.18.0.96
2014-09-14 15:58:50:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:50:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:50:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.96
2014-09-14 15:58:50:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:54:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:54:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:54:  Server Thread -   lapro1399
2014-09-14 15:58:54:  Server Thread -   ::ffff:172.18.0.99
2014-09-14 15:58:54:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:54:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:54:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.99
2014-09-14 15:58:54:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:54:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:54:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:54:  Server Thread -   LAPRO1625
2014-09-14 15:58:54:  Server Thread -   ::ffff:172.18.15.35
2014-09-14 15:58:54:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:54:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:54:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.15.35
2014-09-14 15:58:54:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:55:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:55:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:55:  Server Thread -   lapro1397
2014-09-14 15:58:55:  Server Thread -   ::ffff:172.18.0.97
2014-09-14 15:58:55:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:55:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:55:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.97
2014-09-14 15:58:55:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:58:56:      Job Report Scan - Purging job reports for '54125a5510f85226ec87a8c7' because the job no longer exists
2014-09-14 15:58:57:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:58:57:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:58:57:  Server Thread -   LAPRO1651
2014-09-14 15:58:57:  Server Thread -   ::ffff:172.18.15.61
2014-09-14 15:58:57:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:58:57:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:58:57:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.15.61
2014-09-14 15:58:57:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:59:04:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 15:59:04:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 15:59:04:  Server Thread -   LAPRO1610
2014-09-14 15:59:04:  Server Thread -   ::ffff:172.18.15.20
2014-09-14 15:59:04:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 15:59:04:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 15:59:04:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.15.20
2014-09-14 15:59:04:  Server Thread - Auto Config: Configuration sent
2014-09-14 15:59:26:      Pending Job Scan - Released pending tasks [-1,0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119] because the frames they depends on have finished and/or their required assets are available.

This on takes 155 seconds for a single job:

2014-09-14 16:27:45:  Dependency script returned 209 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-14 16:27:56:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 16:27:56:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 16:27:56:  Server Thread -   lapro1452
2014-09-14 16:27:56:  Server Thread -   ::ffff:172.18.0.152
2014-09-14 16:27:56:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 16:27:56:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 16:27:56:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.152
2014-09-14 16:27:56:  Server Thread - Auto Config: Configuration sent
2014-09-14 16:28:26:      Job Report Scan - Purging job reports for '541355ce10f8522e48e55fd1' because the job no longer exists
2014-09-14 16:28:27:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 16:28:27:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 16:28:27:  Server Thread -   lapro1454
2014-09-14 16:28:27:  Server Thread -   ::ffff:172.18.0.154
2014-09-14 16:28:27:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 16:28:27:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 16:28:27:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.154
2014-09-14 16:28:27:  Server Thread - Auto Config: Configuration sent
2014-09-14 16:28:30:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 16:28:30:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 16:28:30:  Server Thread -   lapro1456
2014-09-14 16:28:30:  Server Thread -   ::ffff:172.18.0.156
2014-09-14 16:28:30:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 16:28:30:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 16:28:30:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.156
2014-09-14 16:28:30:  Server Thread - Auto Config: Configuration sent
2014-09-14 16:28:34:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 16:28:34:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 16:28:34:  Server Thread -   lapro1460
2014-09-14 16:28:34:  Server Thread -   ::ffff:172.18.0.160
2014-09-14 16:28:34:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 16:28:34:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 16:28:34:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.160
2014-09-14 16:28:34:  Server Thread - Auto Config: Configuration sent
2014-09-14 16:28:43:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 16:28:43:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 16:28:43:  Server Thread -   lapro1450
2014-09-14 16:28:43:  Server Thread -   ::ffff:172.18.0.150
2014-09-14 16:28:43:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 16:28:43:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 16:28:43:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.150
2014-09-14 16:28:43:  Server Thread - Auto Config: Configuration sent
2014-09-14 16:28:51:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 16:28:51:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 16:28:51:  Server Thread -   lapro1432
2014-09-14 16:28:51:  Server Thread -   ::ffff:172.18.0.132
2014-09-14 16:28:51:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 16:28:51:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 16:28:51:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.132
2014-09-14 16:28:51:  Server Thread - Auto Config: Configuration sent
2014-09-14 16:28:58:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 16:28:58:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 16:28:58:  Server Thread -   lapro1456
2014-09-14 16:28:58:  Server Thread -   ::ffff:172.18.0.156
2014-09-14 16:28:58:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 16:28:58:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 16:28:58:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.156
2014-09-14 16:28:58:  Server Thread - Auto Config: Configuration sent
2014-09-14 16:29:03:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 16:29:03:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 16:29:03:  Server Thread -   lapro1460
2014-09-14 16:29:03:  Server Thread -   ::ffff:172.18.0.160
2014-09-14 16:29:03:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 16:29:03:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 16:29:03:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.160
2014-09-14 16:29:03:  Server Thread - Auto Config: Configuration sent
2014-09-14 16:29:05:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 16:29:05:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 16:29:05:  Server Thread -   lapro1450
2014-09-14 16:29:05:  Server Thread -   ::ffff:172.18.0.150
2014-09-14 16:29:05:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 16:29:05:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 16:29:05:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.150
2014-09-14 16:29:05:  Server Thread - Auto Config: Configuration sent
2014-09-14 16:30:01:  Server Thread - Auto Config: Received packet on autoconfig port
2014-09-14 16:30:01:  Server Thread - Auto Config: Picking configuration based on:
2014-09-14 16:30:01:  Server Thread -   lapro1444
2014-09-14 16:30:01:  Server Thread -   ::ffff:172.18.0.144
2014-09-14 16:30:01:  Server Thread - Auto Config: Match found for rule Dedicated Render (HostnameRegex)
2014-09-14 16:30:01:  Server Thread - Auto Config: Created a configuration worth sending
2014-09-14 16:30:01:  Server Thread - Auto Config: Received a request for configuration from ::ffff:172.18.0.144
2014-09-14 16:30:01:  Server Thread - Auto Config: Configuration sent
2014-09-14 16:30:20:      Pending Job Scan - Released pending tasks [-1,0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179,180,181,182,183,184,185,186,187,188,189,190,191,192,193,194,195,196,197,198,199,200,201,202,203,204,205,206,207,208] because the frames they depends on have finished and/or their required assets are available.

141 seconds, 1 job:

014-09-14 17:14:19:  Dependency script returned 209 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-14 17:16:28:      Job Report Scan - Purging job reports for '541385bd10f8522b8cd78870' because the job no longer exists
2014-09-14 17:16:40:      Pending Job Scan - Released pending tasks [-1,0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179,180,181,182,183,184,185,186,187,188,189,190,191,192,193,194,195,196,197,198,199,200,201,202,203,204,205,206,207,208] because the frames they depends on have finished and/or their required assets are available.