If you're using the cons_res select plugin, the backfill algorithm uses a doubling factor on the backfill time window, as it goes through the running jobs. The further out you get, the wider the window will be. In your case, being out 6 days means that the granularity for the backfill window may be more than a day wide, so your high priority jobs that can't start right away will seem to be pushed out further into the distance.
I saw the same problem with large parallel job reservations continuing to drift into the future. There's a patch to fix this, but it isn't in the 17.02 tarball. Take a look at https://github.com/SchedMD/slurm/commit/3f7e10f868145a505b1dad6a69b040a167eaa541 ----- Gary Skouson -----Original Message----- From: Robbert Eggermont [mailto:[email protected]] Sent: Thursday, June 15, 2017 4:15 PM To: slurm-dev <[email protected]> Subject: [slurm-dev] Scheduling weirdness 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
