I have noticed that low-priority, backfilled jobs sometimes seem to prevent high-priority jobs from starting. Typically, things look like this:
05/05 09:51:27 INFO: job '99468' reserved 64 tasks (partition IBA) to start in 00:19:47 on Tue May 5 10:11:12 05/05 09:51:40 INFO: job '99468' reserved 64 tasks (partition IBA) to start in 1:00:00 on Tue May 5 10:51:38 Job 99468 has top priority, so it already has a reservation in place. But somehow, this reservation tends to slip from time to time. I have turned up the LOGLEVEL and LOGFILEROLLDEPTH parameters, but the reason for this behaviour still eludes me. This is the (hopefully) relevant part of the logfile in all its glory. I have interspersed comments with my interpretation of what happens: 05/05 09:51:40 INFO: attempting to get resources for 99468 8 * (P: 1 M: 0 S: 0 D: 0) 05/05 09:51:40 MRECheck(node023,MJobGetSNRange-Start,FORCE) 05/05 09:51:40 INFO: N[node023]->RE[000] S 88801(2) -00:06:18 R: 'PROCS: 1'x2 05/05 09:51:40 INFO: N[node023]->RE[001] S 88802(3) -00:06:18 R: 'PROCS: 1'x2 05/05 09:51:40 INFO: N[node023]->RE[002] S 88807(4) -00:05:53 R: 'PROCS: 1'x2 05/05 09:51:40 INFO: N[node023]->RE[003] E 88801(2) 00:13:42 R: 'PROCS: 1'x2 05/05 09:51:40 INFO: N[node023]->RE[004] E 88802(3) 00:13:42 R: 'PROCS: 1'x2 05/05 09:51:40 INFO: N[node023]->RE[005] E 88807(4) 00:14:07 R: 'PROCS: 1'x2 05/05 09:51:40 INFO: N[node023]->RE[006] S SYSTEM.0(0) 23:05:08:22 R: 'PROCS: 8'x1 05/05 09:51:40 INFO: N[node023]->RE[007] E SYSTEM.0(0) 23:13:08:22 R: 'PROCS: 8'x1 Node023 will be unavailable at 10:11:12, leading to the delay (see below). Right now, everything looks fine: there are three reservations ending well before 10:11, plus one that starts in 23 days. Since job 99468 only requires 7 days of walltime, that should not be a problem. 05/05 09:51:40 INFO: initial resources: PROCS: 8 MEM: 7986M SWAP: 14G DISK: 1M 05/05 09:51:40 INFO: requested resources: PROCS: 1 (x8) 05/05 09:51:40 INFO: non-user reservation[2] '88801'x2 resources PROCS: 1 05/05 09:51:40 INFO: checking reservation 88801 start at time -00:06:18 (O: 822) 05/05 09:51:40 MResCheckJAccess(88801,99468,822,Same,Affinity) 05/05 09:51:40 INFO: exclusive (two job reservations) 05/05 09:51:40 INFO: reservations are exclusive 05/05 09:51:40 INFO: removed resources: PROCS: 1 (x2) 05/05 09:51:40 INFO: resulting resources: PROCS: [ALL] MEM: 7986M SWAP: 14G DISK: 1M 05/05 09:51:40 INFO: non-user reservation[3] '88802'x2 resources PROCS: 1 05/05 09:51:40 INFO: checking reservation 88802 start at time -00:06:18 (O: 822) 05/05 09:51:40 MResCheckJAccess(88802,99468,822,Same,Affinity) 05/05 09:51:40 INFO: exclusive (two job reservations) 05/05 09:51:40 INFO: reservations are exclusive 05/05 09:51:40 INFO: removed resources: PROCS: 1 (x2) 05/05 09:51:40 INFO: resulting resources: PROCS: [ALL] MEM: 7986M SWAP: 14G DISK: 1M 05/05 09:51:40 INFO: verifying resource access at -00:06:18 (1) 05/05 09:51:40 INFO: non-user reservation[4] '88807'x2 resources PROCS: 1 05/05 09:51:40 INFO: checking reservation 88807 start at time -00:05:53 (O: 847) 05/05 09:51:40 MResCheckJAccess(88807,99468,847,Same,Affinity) 05/05 09:51:40 INFO: exclusive (two job reservations) 05/05 09:51:40 INFO: reservations are exclusive 05/05 09:51:40 INFO: removed resources: PROCS: 1 (x2) 05/05 09:51:40 INFO: resulting resources: PROCS: [ALL] MEM: 7986M SWAP: 14G DISK: 1M 05/05 09:51:40 INFO: verifying resource access at -00:05:53 (2) 05/05 09:51:40 INFO: performing starttime check (3) 05/05 09:51:40 INFO: resources unavailable at time 00:00:00 There are various reservations extant, so we cannot start right now. Thus, look at each reservation's end in turn: 05/05 09:51:40 INFO: non-user reservation[2] '88801'x2 resources PROCS: 1 05/05 09:51:40 INFO: checking reservation 88801 end at time 00:13:42 (O: 822) 05/05 09:51:40 MResCheckJAccess(88801,99468,822,Same,Affinity) 05/05 09:51:40 INFO: exclusive (two job reservations) 05/05 09:51:40 INFO: reservations are exclusive 05/05 09:51:40 INFO: added resources: PROCS: 1 (x2) 05/05 09:51:40 INFO: resulting resources: PROCS: [ALL] MEM: 7986M SWAP: 14G DISK: 1M 05/05 09:51:40 INFO: non-user reservation[3] '88802'x2 resources PROCS: 1 05/05 09:51:40 INFO: checking reservation 88802 end at time 00:13:42 (O: 822) 05/05 09:51:40 MResCheckJAccess(88802,99468,822,Same,Affinity) 05/05 09:51:40 INFO: exclusive (two job reservations) 05/05 09:51:40 INFO: reservations are exclusive 05/05 09:51:40 INFO: added resources: PROCS: 1 (x2) 05/05 09:51:40 INFO: resulting resources: PROCS: [ALL] MEM: 7986M SWAP: 14G DISK: 1M 05/05 09:51:40 INFO: verifying resource access at 00:13:42 (4) 05/05 09:51:40 INFO: non-user reservation[4] '88807'x2 resources PROCS: 1 05/05 09:51:40 INFO: checking reservation 88807 end at time 00:14:07 (O: 847) 05/05 09:51:40 MResCheckJAccess(88807,99468,847,Same,Affinity) 05/05 09:51:40 INFO: exclusive (two job reservations) 05/05 09:51:40 INFO: reservations are exclusive 05/05 09:51:40 INFO: added resources: PROCS: 1 (x2) 05/05 09:51:40 INFO: resulting resources: MEM: 7986M SWAP: 14G DISK: 1M 05/05 09:51:40 INFO: verifying resource access at 00:14:07 (5) 05/05 09:51:40 INFO: resources available at time 00:14:07 during 88807 end As reservations end, more CPUs become available. At 09:51:40 + 00:14:07, the node should be free. 05/05 09:51:40 MNodeGetTC(node023,0,8,8,1,0) 05/05 09:51:40 INFO: TC from PROC: 0 05/05 09:51:40 INFO: ARange[0] adjusted (TC: 8 S: 1241510745) 1241510745 = 10:05:45 CEST 05/05 09:51:40 INFO: user reservation[0] 'SYSTEM.0'x1 resources PROCS: 8 05/05 09:51:40 INFO: checking reservation SYSTEM.0 start at time 23:05:08:22 (O: 28800) 05/05 09:51:40 MResCheckJAccess(SYSTEM.0,99468,28800,Same,Affinity) 05/05 09:51:40 INFO: reservations are exclusive 05/05 09:51:40 INFO: removed resources: PROCS: 8 (x1) 05/05 09:51:40 INFO: resulting resources: PROCS: [ALL] MEM: 7986M SWAP: 14G DISK: 1M 05/05 09:51:40 INFO: verifying resource access at 23:05:08:22 (6) 05/05 09:51:40 INFO: resources unavailable at time 23:05:08:22 during reservation SYSTEM.0 start (resources) 05/05 09:51:40 INFO: closing ARange[0] (00:14:07 -> 23:05:08:22 : 8) (1) After 23 days, the SYSGTEM.0 reservation kicks in, making the node unaccessible again, so we have from now + 0:14:07 to now + 23 days for our job. 05/05 09:51:40 INFO: user reservation[0] 'SYSTEM.0'x1 resources PROCS: 8 05/05 09:51:40 INFO: checking reservation SYSTEM.0 end at time 23:13:08:22 (O: 28800) 05/05 09:51:40 MResCheckJAccess(SYSTEM.0,99468,28800,Same,Affinity) 05/05 09:51:40 INFO: reservations are exclusive 05/05 09:51:40 INFO: added resources: PROCS: 8 (x1) 05/05 09:51:40 INFO: resulting resources: MEM: 7986M SWAP: 14G DISK: 1M 05/05 09:51:40 INFO: verifying resource access at 23:13:08:22 (7) 05/05 09:51:40 INFO: resources available at time 23:13:08:22 during SYSTEM.0 end After SYSTEM.0 ends, the nodes is available again. 05/05 09:51:40 MNodeGetTC(node023,0,8,8,1,0) 05/05 09:51:40 INFO: TC from PROC: 0 05/05 09:51:40 INFO: ARange[1] adjusted (TC: 8 S: 1243544400) 05/05 09:51:40 INFO: closing ARange[1] (23:13:08:22 -> INFINITY : 8) (4) ... forever. 1243544400 = May 28 23:00 CEST. 05/05 09:51:40 INFO: node node023 supports 8 tasks of job 99468:0 for 23:04:08:22 at 1:00:00 05/05 09:51:40 INFO: node node023 supports 8 tasks of job 99468:0 for INFINITY at 23:13:08:22 This, I do not understand. Why 1:00:00 rather than 0:14:07? There are hundreds of low-priority jobs in the queue; in this case, they need 2 CPUs and 20 minutes, so they will jump into the gap between 0:14:07 and 1:00:00, preventing job 99468 from starting earlier. Since the scenario presented above may repeat quite a few times, high-priority jobs sometimes take days to start even though free nodes are, in principle, available. I'd be grateful if anyone can shed some light on why this is happening. A. -- Ansgar Esztermann DV-Systemadministration Max-Planck-Institut für biophysikalische Chemie, Abteilung 105 _______________________________________________ mauiusers mailing list [email protected] http://www.supercluster.org/mailman/listinfo/mauiusers
