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 sentlog #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.pylog #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.Hey Laszlo,
I thought I mentioned this in the support ticket but maybe not… The reason that the releasing of Tasks is taking so long is likely because the DB is getting hammered, and Pulse is waiting to get a write lock. The change I made in the recent patch dramatically reduced the number of calls made by Pulse to the DB to get this done, which should result in overall faster performance and less contribution of DB load for this particular operation.
However, if the DB is already being hammered by something else, Pulse might have to wait a while to get a write-lock in order to release the Tasks anyways. I think this is what’s happening. Was the farm largely idle at the time those logs were taken? I’m guessing not, since it actually had stuff to release… What do your Monitor refresh intervals and Slave wait times look like currently? Have you tried dialing those back to see if it makes a difference?
Note that if this is indeed a DB lock issue like we suspect it is, parallelizing the dependency checking won’t do much to improve this, as you’d just end up with multiple threads waiting for a lock instead of just one…
Also, did you see my last post in this thread re: Pulse crashing? viewtopic.php?f=86&t=12125&start=20#p54771
I snuck it in just before your previous one, so I wasn’t sure if you saw it. If so, have you guys tried dialing back the verbosity yet?
Thanks Jon, i missed that post! I’ve turned verbose logging off now.
It could be the db load, in which case yeah, parallel access wont help at all. But we are desperate to try anything right now.
The thing is, in some of the logs i saw, everything is running fairly fast (<1s average per job), but it still takes 10-15 mins to finish a single cycle.
Since we have multiple chained dependencies, these 10-15 min delays end up creating a 60-90+ delay before the first frame comes off the farm after a sim has been send off. That slows down artist iterations greatly.
Our current plan is: first off, implementing a ‘manual’ dependency check for the artists that they can trigger from the monitor, second step will be completely rewriting the pending check mechanism of pulse and running several of those parallel as our own service.
Attached is a drop-in (Linux!) replacement for Deadline.dll on the Pulse machine, that splits out the logging of Dependency checks in a completely separate file.
Hopefully this addresses Pulse’s crashing problem you guys have started running into; let me know how it goes!
deadline.zip (470 KB)
Thank you Jon, this is great… separate logs. This will make my life much easier
I see the logs for the dependency checking. EDIT I see the housecleaning log still goes to the main log
The main pulse log has this in it:
2014-09-16 16:15:21: BEGIN - deadline02.scanlinevfxla.com\root
2014-09-16 16:15:21: Deadline Pulse 6.2 [v6.2.1.38 R (8c2623aff)]
2014-09-16 16:15:21: Connecting to repository
2014-09-16 16:15:48: Autoconfiguring Pulse
2014-09-16 16:15:48: Purging old logs
2014-09-16 16:15:48: Server Thread - Auto Config: Listening for auto configuration requests on :::17061:17061
2014-09-16 16:15:48: Web Service - Web Service is disabled. It can be enabled in the Pulse Settings in the Repository Options.
2014-09-16 16:15:48: Web Service - If the Web service is enabled while Pulse is running, Pulse must be restarted for the changes to take effect.
2014-09-16 16:17:17: Update timeout has been set to 300 seconds
2014-09-16 16:17:17: Stdout Handling Enabled: False
2014-09-16 16:17:17: Popup Handling Enabled: False
2014-09-16 16:17:17: Using Process Tree: True
2014-09-16 16:17:17: Hiding DOS Window: True
2014-09-16 16:17:17: Creating New Console: False
2014-09-16 16:17:17: Executable: "/opt/Thinkbox/Deadline6/bin/deadlinecommand.exe"
2014-09-16 16:17:17: Argument: -DoHouseCleaning 10 False
2014-09-16 16:17:17: Startup Directory: "/opt/Thinkbox/Deadline6/bin"
2014-09-16 16:17:17: Process Priority: BelowNormal
2014-09-16 16:17:17: Process Affinity: default
2014-09-16 16:17:17: Process is now running
2014-09-16 16:17:28: Performing Job Cleanup Scan...
2014-09-16 16:17:29: Job Cleanup Scan - Loading completed jobs
2014-09-16 16:17:42: Job Cleanup Scan - Loaded 8490 completed jobs in 13.410 s
2014-09-16 16:17:42: Job Cleanup Scan - Scanning completed jobsIt only shows that the housecleaning is running/started, even though:
[root@deadline02 Deadline6]# ps aux | grep deadline
root 5730 2.1 0.3 788208 110880 pts/2 Sl 16:16 0:06 /opt/mono-2.10.9/bin/mono /opt/Thinkbox/Deadline6/bin/deadlinecommand.exe -DoPendingJobScan False
root 7592 0.4 0.1 4592796 43080 pts/2 Sl Sep12 25:25 mono --runtime=v4.0 /opt/Thinkbox/Deadline6/bin/deadlinelauncher.exe -nogui
root 17003 0.0 0.0 103248 852 pts/1 S+ 16:22 0:00 grep deadline
root 19368 5.3 2.4 1425668 820328 pts/2 Dl 16:17 0:15 /opt/mono-2.10.9/bin/mono /opt/Thinkbox/Deadline6/bin/deadlinecommand.exe -DoHouseCleaning 10 False
root 30022 55.9 0.1 1256788 53576 pts/2 Sl 16:15 3:45 mono --runtime=v4.0 /opt/Thinkbox/Deadline6/bin/deadlinepulse.exe -nogui
Also i see an active log for the dep checking:
/var/log/Thinkbox/Deadline6/dependencychecking-deadline02-2014-09-16.log
With nice entries and all.
One other thing i noticed, is that the actual task release doesn’t seem to be logged any longer. Green is the previous task check, blue is the next one starting up:
2014-09-16 16:17:27: Queueing: [‘117’, ‘118’, ‘119’, ‘120’, ‘121’, ‘122’, ‘123’, ‘124’, ‘125’, ‘126’, ‘127’, ‘128’, ‘129’, ‘130’, ‘131’, ‘132’]
2014-09-16 16:17:27: Dependency script returned 16 tasks that can start: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
2014-09-16 16:17:33: 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-16 16:17:33: Executing dependency script: /mnt/s2/exchange/software/managed/pythonScripts/site-packages/scl/deadline/scriptDependency.py
Attached is a log with the new build
The first scan took ~20 mins 
2014-09-16 16:36:29: Pending Job Scan - Released 103 pending jobs and 1584 pending tasks in 19.178 m
Queuing tasks is still taking ages. One of the last entries (96 tasks) too about 7 mins to queue alone.
dependencychecking-deadline02-2014-09-16.zip (84.5 KB)
Hey Laszlo,
First of all, some of the output is missing because you still have Pulse Verbose logging off presumably (should be able to turn that back on now) . Also, we’ve omitted the output of the actual Dependency Check process from the Pulse log, since we believe that may have been contributing to the regular Pulse crashing you guys were seeing.
Second, Housecleaning wasn’t split out yet because the Job Dependency stuff seemed to contribute the most verbose output, and I wanted to get a build for you to try ASAP while keeping the changes light. Housecleaning has been split up in the next build of 6.2 which will probably go up next week, along with Repo Options to turn that on/off.
Finally, this change wasn’t intended to address the performance of the check, just for stability, as an attempt to eliminate the crashing you guys were experiencing. Has Pulse still been crashing regularly since you patched the DLL?
Cheers,
Jon
Hey Jon, thanks for the explanation, ill turn verbose logging back on.
Yes, its still crashing, had 5 crashes after the patch was applied last night:
-rw-r–r-- 1 root root 22791 Sep 16 19:20 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-16-0024.log
-rw-r–r-- 1 root root 24276 Sep 16 20:35 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-16-0025.log
-rw-r–r-- 1 root root 24108 Sep 16 21:45 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-16-0026.log
-rw-r–r-- 1 root root 22486 Sep 16 22:53 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-16-0027.log
-rw-r–r-- 1 root root 17990 Sep 16 23:55 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-16-0028.log
and 9 since midnight:
-rw-r–r-- 1 root root 7238 Sep 17 00:12 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-17-0000.log
-rw-r–r-- 1 root root 25489 Sep 17 01:18 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-17-0001.log
-rw-r–r-- 1 root root 24191 Sep 17 02:30 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-17-0002.log
-rw-r–r-- 1 root root 24988 Sep 17 03:36 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-17-0003.log
-rw-r–r-- 1 root root 24498 Sep 17 04:38 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-17-0004.log
-rw-r–r-- 1 root root 24220 Sep 17 05:38 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-17-0005.log
-rw-r–r-- 1 root root 24408 Sep 17 06:37 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-17-0006.log
-rw-r–r-- 1 root root 24188 Sep 17 07:38 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-17-0007.log
-rw-r–r-- 1 root root 24393 Sep 17 08:39 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-17-0008.log
-rw-r–r-- 1 root root 18793 Sep 17 09:29 /var/log/Thinkbox/Deadline6/deadlinepulse-deadline02-2014-09-17-0009.log
the var/log/messages looks like this:
Sep 17 00:19:15 deadline02 abrt[17969]: Saved core dump of pid 21944 (/opt/mono-2.10.9/bin/mono) to /var/spool/abrt/ccpp-2014-09-17-00:13:16-21944 (3409707008 bytes)
Sep 17 00:19:15 deadline02 abrtd: Directory 'ccpp-2014-09-17-00:13:16-21944' creation detected
Sep 17 00:19:15 deadline02 abrtd: Executable '/opt/mono-2.10.9/bin/mono' doesn't belong to any package
Sep 17 00:19:15 deadline02 abrtd: 'post-create' on '/var/spool/abrt/ccpp-2014-09-17-00:13:16-21944' exited with 1
Sep 17 00:19:15 deadline02 abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2014-09-17-00:13:16-21944, deleting
Sep 17 01:26:47 deadline02 abrt[21345]: Saved core dump of pid 17080 (/opt/mono-2.10.9/bin/mono) to /var/spool/abrt/ccpp-2014-09-17-01:21:54-17080 (3061424128 bytes)
Sep 17 01:26:47 deadline02 abrtd: Directory 'ccpp-2014-09-17-01:21:54-17080' creation detected
Sep 17 01:26:47 deadline02 abrtd: Executable '/opt/mono-2.10.9/bin/mono' doesn't belong to any package
Sep 17 01:26:47 deadline02 abrtd: 'post-create' on '/var/spool/abrt/ccpp-2014-09-17-01:21:54-17080' exited with 1
Sep 17 01:26:47 deadline02 abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2014-09-17-01:21:54-17080, deleting
Sep 17 02:37:30 deadline02 abrt[3567]: Saved core dump of pid 3747 (/opt/mono-2.10.9/bin/mono) to /var/spool/abrt/ccpp-2014-09-17-02:31:50-3747 (3392536576 bytes)
Sep 17 02:37:30 deadline02 abrtd: Directory 'ccpp-2014-09-17-02:31:50-3747' creation detected
Sep 17 02:37:30 deadline02 abrtd: Executable '/opt/mono-2.10.9/bin/mono' doesn't belong to any package
Sep 17 02:37:30 deadline02 abrtd: 'post-create' on '/var/spool/abrt/ccpp-2014-09-17-02:31:50-3747' exited with 1
Sep 17 02:37:30 deadline02 abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2014-09-17-02:31:50-3747, deleting
Sep 17 03:41:12 deadline02 abrt[9537]: Saved core dump of pid 19185 (/opt/mono-2.10.9/bin/mono) to /var/spool/abrt/ccpp-2014-09-17-03:37:00-19185 (2965553152 bytes)
Sep 17 03:41:12 deadline02 abrtd: Directory 'ccpp-2014-09-17-03:37:00-19185' creation detected
Sep 17 03:41:12 deadline02 abrtd: Executable '/opt/mono-2.10.9/bin/mono' doesn't belong to any package
Sep 17 03:41:12 deadline02 abrtd: 'post-create' on '/var/spool/abrt/ccpp-2014-09-17-03:37:00-19185' exited with 1
Sep 17 03:41:12 deadline02 abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2014-09-17-03:37:00-19185, deleting
Sep 17 04:42:40 deadline02 abrt[31244]: Saved core dump of pid 22416 (/opt/mono-2.10.9/bin/mono) to /var/spool/abrt/ccpp-2014-09-17-04:38:21-22416 (3017170944 bytes)
Sep 17 04:42:40 deadline02 abrtd: Directory 'ccpp-2014-09-17-04:38:21-22416' creation detected
Sep 17 04:42:41 deadline02 abrtd: Executable '/opt/mono-2.10.9/bin/mono' doesn't belong to any package
Sep 17 04:42:41 deadline02 abrtd: 'post-create' on '/var/spool/abrt/ccpp-2014-09-17-04:38:21-22416' exited with 1
Sep 17 04:42:41 deadline02 abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2014-09-17-04:38:21-22416, deleting
Sep 17 05:43:39 deadline02 abrt[32198]: Saved core dump of pid 29940 (/opt/mono-2.10.9/bin/mono) to /var/spool/abrt/ccpp-2014-09-17-05:39:35-29940 (2989305856 bytes)
Sep 17 05:43:39 deadline02 abrtd: Directory 'ccpp-2014-09-17-05:39:35-29940' creation detected
Sep 17 05:43:39 deadline02 abrtd: Executable '/opt/mono-2.10.9/bin/mono' doesn't belong to any package
Sep 17 05:43:39 deadline02 abrtd: 'post-create' on '/var/spool/abrt/ccpp-2014-09-17-05:39:35-29940' exited with 1
Sep 17 05:43:39 deadline02 abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2014-09-17-05:39:35-29940, deleting
Sep 17 06:43:07 deadline02 abrt[16952]: Saved core dump of pid 28852 (/opt/mono-2.10.9/bin/mono) to /var/spool/abrt/ccpp-2014-09-17-06:38:47-28852 (2868629504 bytes)
Sep 17 06:43:07 deadline02 abrtd: Directory 'ccpp-2014-09-17-06:38:47-28852' creation detected
Sep 17 06:43:07 deadline02 abrtd: Executable '/opt/mono-2.10.9/bin/mono' doesn't belong to any package
Sep 17 06:43:07 deadline02 abrtd: 'post-create' on '/var/spool/abrt/ccpp-2014-09-17-06:38:47-28852' exited with 1
Sep 17 06:43:07 deadline02 abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2014-09-17-06:38:47-28852, deleting
Sep 17 07:44:30 deadline02 abrt[24776]: Saved core dump of pid 3483 (/opt/mono-2.10.9/bin/mono) to /var/spool/abrt/ccpp-2014-09-17-07:40:16-3483 (2952093696 bytes)
Sep 17 07:44:30 deadline02 abrtd: Directory 'ccpp-2014-09-17-07:40:16-3483' creation detected
Sep 17 07:44:30 deadline02 abrtd: Executable '/opt/mono-2.10.9/bin/mono' doesn't belong to any package
Sep 17 07:44:30 deadline02 abrtd: 'post-create' on '/var/spool/abrt/ccpp-2014-09-17-07:40:16-3483' exited with 1
Sep 17 07:44:30 deadline02 abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2014-09-17-07:40:16-3483, deleting
Sep 17 08:46:53 deadline02 abrt[6992]: Saved core dump of pid 24723 (/opt/mono-2.10.9/bin/mono) to /var/spool/abrt/ccpp-2014-09-17-08:42:01-24723 (3309395968 bytes)
Sep 17 08:46:53 deadline02 abrtd: Directory 'ccpp-2014-09-17-08:42:01-24723' creation detected
Sep 17 08:46:53 deadline02 abrtd: Executable '/opt/mono-2.10.9/bin/mono' doesn't belong to any package
Sep 17 08:46:53 deadline02 abrtd: 'post-create' on '/var/spool/abrt/ccpp-2014-09-17-08:42:01-24723' exited with 1
Sep 17 08:46:53 deadline02 abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2014-09-17-08:42:01-24723, deletingFor some reason the crash dumps dont seem to work…