Hello,

In our Slurm setup (now 17.02.4) I've noticed several times now that backfilled jobs push back the start time of the highest priority job. I'm not sure if this is due to a configuration error or an scheduler error, and since I'm having a hard time diagnosing what's happening, I was hoping for some insightful tips.

What happens is that when the highest priority pending job needs a lot of resources (CPUs, ...), slurm will backfill lower priority jobs with less requirements but with a higher timelimit than the currently running jobs.

For example, the highest priority job needs a full node, and the first node will become available in 6 days; our slurm will happily backfill all pending lower priority 2-CPU 7-day jobs on every possible node in the cluster, thus pushing back the highest priority job 1 day.

Looking into the scheduler debugging info, I noticed some things I can't explain: 1) the highest priority job ("A") is not always scheduled to start on the first node ("1") that will become available; 2) in the same iteration, the backfill logic will start another, lower priority, smaller job with a timelimit longer than the expected start time of job "A" on the same node "1"; 3) when "A" is scheduled to start on another node, the scheduled starting time remains the same (i.e. it is not updated to the time that the new node becomes available). 4) the scheduled starting time of the highest priority job ("A") is sometimes later than the time that the node becomes available;

See below for some log entries for these events.

Does anybody have an idea what's going on here, and how we can fix it?

Robbert


1)
JobID=1315558 has a scheduled start time on node maxwell of 2017-06-22T19:11:16; forcing it to another node (by draining maxwell) reduces the start time to 2017-06-22T16:47:43. (But slurm is consistent: when maxwell is resumed, the job is scheduled there again, with the later start time.)
[2017-06-15T22:11:26.688] backfill: beginning
[2017-06-15T22:11:26.693] backfill test for JobID=1315558 Prio=22703485 
Partition=general
[2017-06-15T22:11:26.694] Job 1315558 to start at 2017-06-22T19:11:16, end at 
2017-06-27T07:11:00 on maxwell
[2017-06-15T22:11:26.694] backfill: reached end of job queue
[2017-06-15T22:11:52.223] update_node: node maxwell state set to DRAINING
[2017-06-15T22:11:56.695] backfill: beginning
[2017-06-15T22:11:56.701] backfill test for JobID=1315558 Prio=22703485 
Partition=general
[2017-06-15T22:11:56.703] Job 1315558 to start at 2017-06-22T16:47:43, end at 
2017-06-27T04:47:00 on parzen
[2017-06-15T22:11:56.703] backfill: reached end of job queue
...
[2017-06-15T22:34:46.036] backfill: beginning
[2017-06-15T22:34:46.039] =========================================
[2017-06-15T22:34:46.039] Begin:2017-06-15T22:34:46 End:2017-06-15T22:41:46 
Nodes:100plus,gauss,hopper,markov,neumann,parzen,sanger,viterbi,watson
[2017-06-15T22:34:46.039] =========================================
[2017-06-15T22:34:46.040] backfill test for JobID=1315558 Prio=22776428 
Partition=general
[2017-06-15T22:34:46.040] Test job 1315558 at 2017-06-15T22:34:46 on 
hopper,parzen,viterbi
[2017-06-15T22:34:46.040] Job 1315558 to start at 2017-06-22T16:47:43, end at 
2017-06-27T04:47:00 on parzen
[2017-06-15T22:34:46.040] backfill: reached end of job queue
[2017-06-15T22:34:55.236] update_node: node maxwell state set to ALLOCATED
[2017-06-15T22:35:16.041] backfill: beginning
[2017-06-15T22:35:16.045] =========================================
[2017-06-15T22:35:16.045] Begin:2017-06-15T22:35:16 End:2017-06-15T22:42:16 
Nodes:100plus,gauss,hopper,markov,maxwell,neumann,parzen,sanger,viterbi,watson
[2017-06-15T22:35:16.045] =========================================
[2017-06-15T22:35:16.045] backfill test for JobID=1315558 Prio=22776428 
Partition=general
[2017-06-15T22:35:16.045] Test job 1315558 at 2017-06-15T22:35:16 on 
hopper,maxwell,parzen,viterbi
[2017-06-15T22:35:16.046] Job 1315558 to start at 2017-06-22T19:11:16, end at 
2017-06-27T07:11:00 on maxwell
[2017-06-15T22:35:16.046] backfill: reached end of job queue

2)
Our highest prio job is now scheduled to start on maxwell at 2017-06-22T18:29:17, but then another job is backfilled on maxwell with EndTime=2017-06-22T21:02:10??
[2017-06-15T23:22:10.227] backfill: beginning
[2017-06-15T23:22:10.231] =========================================
[2017-06-15T23:22:10.231] Begin:2017-06-15T23:22:10 End:2017-06-15T23:29:10 
Nodes:100plus,gauss,hopper,markov,maxwell,neumann,parzen,sanger,viterbi,watson
[2017-06-15T23:22:10.231] =========================================
[2017-06-15T23:22:10.231] backfill test for JobID=1315558 Prio=22938897 
Partition=general
[2017-06-15T23:22:10.231] Test job 1315558 at 2017-06-15T23:22:10 on 
hopper,maxwell,parzen,viterbi
[2017-06-15T23:22:10.232] Job 1315558 to start at 2017-06-22T18:29:17, end at 
2017-06-27T06:29:00 on maxwell
[2017-06-15T23:22:10.232] backfill test for JobID=1314524 Prio=10000002 
Partition=general
[2017-06-15T23:22:10.233] Test job 1314524 at 2017-06-15T23:22:10 on 
gauss,hopper,markov,maxwell,neumann,parzen,sanger,viterbi,watson
[2017-06-15T23:22:10.233] backfill: Started JobId=1314524 in general on maxwell
[2017-06-15T23:22:10.237] backfill: reached end of job queue

3 and 4)
Our job is immediately scheduled on another node, however the scheduled starting time 2017-06-22T18:29:17 remains the same, although the current longest jobs on parzen has EndTime=2017-06-22T15:27:08. Almost an hour later the start time is updated (note: the job complete should be unrelated since the job ran on maxwell, right?). Then 40 minutes later the start time is updated again, pushed back (while no new jobs were started on parzen in the mean time, and we don't suspend; there was however another job complete on maxwell?).
[2017-06-15T23:22:40.237] backfill: beginning
[2017-06-15T23:22:40.241] =========================================
[2017-06-15T23:22:40.242] Begin:2017-06-15T23:22:40 End:2017-06-15T23:29:40 
Nodes:100plus,gauss,hopper,markov,maxwell,neumann,parzen,sanger,viterbi,watson
[2017-06-15T23:22:40.242] =========================================
[2017-06-15T23:22:40.242] backfill test for JobID=1315558 Prio=22938897 
Partition=general
[2017-06-15T23:22:40.242] Test job 1315558 at 2017-06-15T23:22:40 on 
hopper,maxwell,parzen,viterbi
[2017-06-15T23:22:40.243] Job 1315558 to start at 2017-06-22T18:29:17, end at 
2017-06-27T06:29:00 on parzen
[2017-06-15T23:22:40.243] backfill: reached end of job queue
...
[2017-06-16T00:16:06.161] backfill: beginning
[2017-06-16T00:16:06.165] =========================================
[2017-06-16T00:16:06.165] Begin:2017-06-16T00:16:06 End:2017-06-16T00:23:06 
Nodes:100plus,gauss,hopper,markov,maxwell,neumann,parzen,sanger,viterbi,watson
[2017-06-16T00:16:06.165] =========================================
[2017-06-16T00:16:06.165] backfill test for JobID=1315558 Prio=23087721 
Partition=general
[2017-06-16T00:16:06.165] Test job 1315558 at 2017-06-16T00:16:06 on 
hopper,maxwell,parzen,viterbi
[2017-06-16T00:16:06.166] Job 1315558 to start at 2017-06-22T18:29:17, end at 
2017-06-27T06:29:00 on parzen
[2017-06-16T00:16:06.167] backfill: reached end of job queue
[2017-06-16T00:16:12.763] job_complete: JobID=1316201 State=0x8003 NodeCnt=1 
done
[2017-06-16T00:16:36.167] backfill: beginning
[2017-06-16T00:16:36.170] =========================================
[2017-06-16T00:16:36.170] Begin:2017-06-16T00:16:36 End:2017-06-16T00:23:36 
Nodes:100plus,gauss,hopper,markov,maxwell,neumann,parzen,sanger,viterbi,watson
[2017-06-16T00:16:36.170] =========================================
[2017-06-16T00:16:36.170] backfill test for JobID=1315558 Prio=23101442 
Partition=general
[2017-06-16T00:16:36.170] Test job 1315558 at 2017-06-16T00:16:36 on 
hopper,maxwell,parzen,viterbi
[2017-06-16T00:16:36.171] Job 1315558 to start at 2017-06-22T16:41:17, end at 
2017-06-27T04:41:00 on parzen
[2017-06-16T00:16:36.171] backfill: reached end of job queue
...
[2017-06-16T00:55:41.642] backfill: beginning
[2017-06-16T00:55:41.646] =========================================
[2017-06-16T00:55:41.646] Begin:2017-06-16T00:55:41 End:2017-06-16T01:02:41 
Nodes:100plus,gauss,hopper,markov,maxwell,neumann,parzen,sanger,viterbi,watson
[2017-06-16T00:55:41.646] =========================================
[2017-06-16T00:55:41.646] backfill test for JobID=1315558 Prio=23186871 
Partition=general
[2017-06-16T00:55:41.646] Test job 1315558 at 2017-06-16T00:55:41 on 
hopper,maxwell,parzen,viterbi
[2017-06-16T00:55:41.647] Job 1315558 to start at 2017-06-22T16:41:17, end at 
2017-06-27T04:41:00 on parzen
[2017-06-16T00:55:41.694] backfill: reached end of job queue
[2017-06-16T00:55:47.592] job_complete: JobID=1316353 State=0x1 NodeCnt=1 
WEXITSTATUS 0
[2017-06-16T00:55:47.598] job_complete: JobID=1316353 State=0x8003 NodeCnt=1 
done
[2017-06-16T00:56:11.695] backfill: beginning
[2017-06-16T00:56:11.701] =========================================
[2017-06-16T00:56:11.701] Begin:2017-06-16T00:56:11 End:2017-06-16T01:03:11 
Nodes:100plus,gauss,hopper,markov,maxwell,neumann,parzen,sanger,viterbi,watson
[2017-06-16T00:56:11.701] =========================================
[2017-06-16T00:56:11.701] backfill test for JobID=1315558 Prio=23186871 
Partition=general
[2017-06-16T00:56:11.701] Test job 1315558 at 2017-06-16T00:56:11 on 
hopper,maxwell,parzen,viterbi
[2017-06-16T00:56:11.703] Job 1315558 to start at 2017-06-22T18:01:33, end at 
2017-06-27T06:01:00 on parzen
[2017-06-16T00:56:11.703] backfill: reached end of job queue

Reply via email to