Ticket 5166

Hi

Did you have any reservation in systems in that day?
If yes could you send me the output from "sacctmgr show reservation start=5/10/18"

Dominik

Aha, interesting, no intential reservations (other then test75):

sacctmgr show reservation start=5/10/18
   Cluster            Name                           TRES           TimeStart             TimeEnd UnusedWall 
---------- --------------- ------------------------------ ------------------- ------------------- ---------- 
    tiger2         root_24                       cpu=2240 2017-12-12T07:27:19 2018-12-12T06:00:00 3.4609e+07 
    tiger2         root_39                      cpu=15680 2018-04-10T06:00:00 2019-04-10T06:00:00 3.0672e+06 
    tiger2         root_40                       cpu=2240 2018-04-10T06:00:00 2019-04-10T06:00:00 3.0672e+06 
    tiger2          test75                         cpu=80 2018-05-03T21:32:59 2018-05-10T00:00:00 5.2682e+05 

I tried removing or editing those old reservations but with no luck

scontrol update reservation=root_40 EndTime=2018-04-10T14:00:00
Error updating the reservation: Requested reservation is invalid
slurm_update error: Requested reservation is invalid

and

scontrol delete reservation=root_40
delete_reservation reservation=root_40: Requested reservation is invalid

I assume these reservations are the reason for time problems? Any way to change them other then editing the DB directly?

Let me add that these reservations are not active.  We started adding very long maintenance reservations and then deleting them, e.g. for next few maintenances we have this waiting:

scontrol show reservation
ReservationName=root_43 StartTime=2018-06-12T06:00:00 EndTime=2019-06-12T06:00:00 Duration=365-00:00:00
   Nodes=tiger-h19c[1-2]n[1-24],tiger-h20c[1-2]n[1-24],tiger-h21c[1-2]n[1-24],tiger-h22c1n[1-24],tiger-h23c[1-2]n[1-24],tiger-h24c[1-2]n[1-24],tiger-h25c[1-2]n[1-24],tiger-h26c[1-2]n[1-24],tiger-i26c1n[1-24],tiger-i26c2n[1-8] NodeCnt=392 CoreCnt=15680 Features=(null) PartitionName=all Flags=MAINT,IGNORE_JOBS,SPEC_NODES,PART_NODES
   TRES=cpu=15680
   Users=root Accounts=(null) Licenses=(null) State=INACTIVE BurstBuffer=(null) Watts=n/a

ReservationName=root_44 StartTime=2018-06-12T06:00:00 EndTime=2019-06-12T06:00:00 Duration=365-00:00:00
   Nodes=tiger-i[19-23]g[1-16] NodeCnt=80 CoreCnt=2240 Features=(null) PartitionName=gpu Flags=MAINT,IGNORE_JOBS,SPEC_NODES,PART_NODES
   TRES=cpu=2240
   Users=root Accounts=(null) Licenses=(null) State=INACTIVE BurstBuffer=(null) Watts=n/a

I guess one could argue that deleted reservations should not be counted any more but I guess you could argue - until when.  Probably until they got deleted?  Can we suggest that code should be changed to update endtime of a reservation to the time of deletion?

We also still need a way to update these...

Thanks.

Hi

In a normal case when reservation is deleted its ending time should be updated. I can think about at least one situation when this can occur  (when slurmctld is started without resv_state file)
How exactly you deleted this reservation?

Dominik

Hullo,

we did nothing weird - just deleted it and as far as I can remember everything was up and running (slurmdbd, slurmctlds...).

Josko

Hi

Do you have any logs from time when you created/deleted these reservations?
I am still trying to recreate this.

Dominik

I checked and nothing obvious but some checking of the mysql table may point the way - these are relevant bits from tiger2_resv_table (current state but I checked our oldest daily backup from April 21st and it is almost the same - just the accounted time is different for "active" reservation): 

39,0,"2",36929,"tiger-h19c[1-2]n[1-24],tiger-h20c[1-2]n[1-24],tiger-h21c[1-2]n[1-24],tiger-h22c1n[1-24],tiger-h23c[1-2]n[1-24],tiger-h24c[1-2]n[1-24],tiger-h25c[1-2]n[1-24],tiger-h26c[1-2]n[1-24],tiger-i26c1n[1-24],tiger-i26c2n[1-8]","0-359,440-471","root_39",1523354400,1554890400,"1=15680",3618000
39,0,"2",36929,"tiger-h19c[1-2]n[1-24],tiger-h20c[1-2]n[1-24],tiger-h21c[1-2]n[1-24],tiger-h22c1n[1-24],tiger-h23c[1-2]n[1-24],tiger-h24c[1-2]n[1-24],tiger-h25c[1-2]n[1-24],tiger-h26c[1-2]n[1-24],tiger-i26c1n[1-24],tiger-i26c2n[1-8]","0-359,440-471","root_39",1523359983,1523367030,"1=15680",7047
39,1,"2",36929,"tiger-h19c[1-2]n[1-24],tiger-h20c[1-2]n[1-24],tiger-h21c[1-2]n[1-24],tiger-h22c1n[1-24],tiger-h23c[1-2]n[1-24],tiger-h24c[1-2]n[1-24],tiger-h25c[1-2]n[1-24],tiger-h26c[1-2]n[1-24],tiger-i26c1n[1-24],tiger-i26c2n[1-8]","0-359,440-471","root_39",1523367030,1523380986,"1=15680",13956
40,0,"2",36929,"tiger-i[19-23]g[1-16]","360-439","root_40",1523354400,1554890400,"1=2240",3618000
40,0,"2",36929,"tiger-i[19-23]g[1-16]","360-439","root_40",1523359983,1523367030,"1=2240",7047
40,1,"2",36929,"tiger-i[19-23]g[1-16]","360-439","root_40",1523367030,1523380978,"1=2240",13948

Our original reservation started at 6am and we set its end date to +1 year (to avoid having to extend it) but it looks we had another set added starting at 7:33am and ending at 9:30am, then another from 9:30am until (real) end of maintenance at 13:23.

Now, we upgraded from 17.02 to 17.11 on April 10 and there were no duplicate reservations before maintenance (from pre-upgrade backup of db):

39,0,'2',36929,'tiger-h19c[1-2]n[1-24],tiger-h20c[1-2]n[1-24],tiger-h21c[1-2]n[1-24],tiger-h22c1n[1-24],tiger-h23c[1-2]n[1-24],tiger-h24c[1-2]n[1-24],tiger-h25c[1-2]n[1-24],tiger-h26c[1-2]n[1-24],tiger-i26c1n[1-24],tiger-i26c2n[1-8]','0-359,440-471','root_39',1523354400,1554890400,'1=15680'
40,0,'2',36929,'tiger-i[19-23]g[1-16]','360-439','root_40',1523354400,1554890400,'1=2240'

I guess I see how I could solve the problem at hand - i.e. I could update by hand those tables, probably set the end time of the tiger reservation to start of the next one though not sure about time/last param what it should be.  But how did it get this way? Was it because we restarted slurmctld at some point (or slurmdbd) or ...?

Hi

I tried to understand and recreate this. 
We don’t have anything similar to "sacctmgr show runaway" for reservations. I don’t see any easy way to force recalculating of unused_wall and assoc usage.
unused_wall=(resv_end -resv_start) - sum(job_wall_time * (job_tres/resv_tres))
if we assume there was no job in this reservation, we can set equally to (resv_end -resv_start).

Dominik

There were no jobs, it was for a maintenance and we are OK if this temporarily messes up time stats. I guess you are OK with me fixing it via some sql calls?

Also, I guess we don't understand how this happened? And this is not the first time it happened - we have that earlier reservation from 2017 that had the similar problem.

Hi

I finally recreated this.
To did this I needed to restart slurctld multiple times while slurmdbd was down. Have you corrected corrupted record in MySQL already?

Dominik

Hullo,

no, we haven't touched them yet - was waiting on your opinion.  Do you have a good recipe to do this or should I attempt something on my own.

Also good to hear that you reproduced it - I assume some kind of a fix will be forthcoming?

Thanks!

(In reply to Josko Plazonic from comment #11)
> Hullo,
> 
> no, we haven't touched them yet - was waiting on your opinion.  Do you have
> a good recipe to do this or should I attempt something on my own.
> 

I have applied this procedure on my devbox :
1) stop slurmdbd 
2) update <cluster>_resv_table set unused_wall=0,time_end=<> where id_resv=<resv_id> and time_start=<>; (fix reservation record )
next steps are only required to recalculate used records
3) update <cluster>_last_ran_table set hourly_rollup=<time_start>,daily_rollup=<time_start>; (force rollup on slurmdbd start)
4) delete from <cluster>_assoc_usage_hour_table where time_start > <time_start>;
5) delete from <cluster>_assoc_usage_day_table where time_start > <time_start>;
5) start slurmdbd

It's an experimental procedure, I will ask Tim to check if he sees any weak points in it.
Of course, backup MySQL db before any manual modification is strongly recommended.


> Also good to hear that you reproduced it - I assume some kind of a fix will
> be forthcoming?
> 
Yes, this is a bug and we will fix it.
Dominik
> Thanks!

Hi

We think the procedure from comment can be simplified and should look like this:

1) stop slurmdbd 
2) update <cluster>_resv_table set unused_wall=0,time_end=<> where id_resv=<resv_id> and time_start=<>; (fix reservation record )
next steps are only required to recalculate used records
3) update <cluster>_last_ran_table set hourly_rollup=<time_start>,daily_rollup=<time_start>,monthly_rollup=<time_start>; (force rollup on slurmdbd start)
4) start slurmdbd


Dominik

*** Ticket 5341 has been marked as a duplicate of this ticket. ***

Hi
I prepared this queries, first one lists all reservations that end after the next record started, the second one fixes ending time and clears unused wall for these records

SELECT  *,(SELECT time_start FROM test_resv_table resv_tmp WHERE resv_tmp.time_start>test_resv_table.time_start and resv_tmp.id_resv=test_resv_table.id_resv ORDER BY resv_tmp.time_start LIMIT 0, 1) AS next_start
        FROM test_resv_table 
        WHERE time_end != (SELECT time_start FROM test_resv_table resv_tmp WHERE resv_tmp.time_start>test_resv_table.time_start and resv_tmp.id_resv=test_resv_table.id_resv ORDER BY resv_tmp.time_start LIMIT 0, 1);

UPDATE test_resv_table AS resv INNER JOIN test_resv_table AS resv_tmp
        ON resv.id_resv = resv_tmp.id_resv AND
        resv.time_end > resv_tmp.time_start AND
        resv_tmp.time_start =
                (SELECT time_start FROM (SELECT * FROM test_resv_table) AS tmp WHERE
                        tmp.time_start>resv.time_start AND
                        tmp.id_resv=resv.id_resv
                        ORDER BY tmp.time_start LIMIT 0, 1)
        SET resv.time_end=resv_tmp.time_start , resv.unused_wall=0; 


Dominik

Hi

Finally, we commit fix for this issue:
https://github.com/SchedMD/slurm/commit/e42b0927f3b121f3b
It is in 18.08 branch and will be in all future 18.08 releases.

Sorry that this took so long.
Closing as resolved/fixed, please reopen if needed.

Dominik

Great - thanks!