Ticket 9482

Created attachment 15216 [details]
slurmctld logs

Created attachment 15217 [details]
sinfo output

Created attachment 15218 [details]
sdiag output

I'm looking into this.

 -Chad

The info you sent was helpful and from your sdiag output the main thing that stands out is this:

---
*******************************************************
sdiag output at Wed Jul 29 16:26:58 2020 (1596032818)
Data since      Wed Jul 29 02:00:00 2020 (1595980800)
*******************************************************
  ...
Remote Procedure Call statistics by message type
        MESSAGE_COMPOSITE                       (11001) count:650729 ave_time:137186 total_time:89271001097
---

This call relates to message aggregation (see MsgAggregationParams in your slurm.conf) and shows slurmctld is doing a lot of work handling it. Note that the time units are in microseconds.

There's been some recent work with a message aggregation fix that went into 19.05.7 so you should have that. However, there may be additional issues that have not been addressed.

Would it be possible for you to disable message aggregation to see if this helps your situation? This will require restarting all the Slurm daemons on all nodes and is not advisable while jobs are running so you may want to wait until you have some down time to do this.

Hello and thanks for your quick answer,

Given the number of tasks of the current running job array and 
the time they need to complete, I'll try to find a trade off
with the user to restart the daemons over the weekend.

Have a nice day,

Hell,

I've changed slurm.conf,

$ scontrol show conf | grep -i aggregation                                                                              
MsgAggregationParams    = (null)

restarted slurmctld and the slurmd on all nodes and did a
scontrol reconfigure.

I've then released the jobs. But if I launch a new scontrol reconfigure 
(without any change in slurm.conf), it still takes a lot of time

$ time scontrol reconfigure                                                                                       

real    1m20.187s
user    0m0.002s
sys     0m0.003s


$time scontrol reconfigure                                                                                       

real    0m35.119s
user    0m0.003s
sys     0m0.001s


So of course I have the corresponding warnings in the logs:

2020-08-03T10:27:15+02:00 maestro-sched slurmctld[16342]: Warning: Note very large processing time from _set_slurmd_addr: usec=35050418 began=10:26:40.948                                            
2020-08-03T10:27:16+02:00 maestro-sched slurmctld[16342]: Warning: Note very large processing time from read_slurm_conf: usec=35097971 began=10:26:40.945                                             
2020-08-03T10:27:16+02:00 maestro-sched slurmctld[16342]: Warning: Note very large processing time from _slurm_rpc_job_pack_alloc_info: usec=17300526 began=10:26:58.742                              
2020-08-03T10:27:16+02:00 maestro-sched slurmctld[16342]: Warning: Note very large processing time from _slurm_rpc_job_pack_alloc_info: usec=15521191 began=10:27:00.521                              
2020-08-03T10:27:16+02:00 maestro-sched slurmctld[16342]: Warning: Note very large processing time from _slurm_rpc_reconfigure_controller: usec=35106756 began=10:26:40.945                           
2020-08-03T10:27:16+02:00 maestro-sched slurmctld[16342]: Warning: Note very large processing time from dump_all_job_state: usec=32080389 began=10:26:44.001                                          
2020-08-03T10:27:16+02:00 maestro-sched slurmctld[16342]: SchedulerParameters=default_queue_depth=100,max_rpc_cnt=0,max_sched_time=2,partition_job_depth=0,sched_max_job_start=200,sched_min_interval=2000000
2020-08-03T10:27:16+02:00 maestro-sched slurmctld[16342]: Warning: Note very large processing time from _slurm_rpc_step_complete: usec=34919542 began=10:26:41.162                                    
2020-08-03T10:27:16+02:00 maestro-sched slurmctld[16342]: Warning: Note very large processing time from _slurm_rpc_epilog_complete: usec=32967448 began=10:26:43.114                                  
2020-08-03T10:27:16+02:00 maestro-sched slurmctld[16342]: Warning: Note very large processing time from _slurm_rpc_complete_batch_script: usec=34894060 began=10:26:41.188                            
2020-08-03T10:27:16+02:00 maestro-sched slurmctld[16342]: Warning: Note very large processing time from _slurm_rpc_epilog_complete: usec=33004328 began=10:26:43.115            


But it seems that it causes killing of some jobs (happened
at the same time at the second scontrol reconfigure):

2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_30110(285126) on node maestro-1008                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_29670(284686) on node maestro-1008                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_30342(285358) on node maestro-1012                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_28956(283972) on node maestro-1011                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_32769(287785) on node maestro-1004                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_32723(287739) on node maestro-1007                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_30036(285052) on node maestro-1006                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_30022(285038) on node maestro-1006                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_28893(283909) on node maestro-1020                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_28855(283871) on node maestro-1016                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_28907(283923) on node maestro-1017                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_32512(287528) on node maestro-1015                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_28804(283820) on node maestro-1014                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_30731(285747) on node maestro-1034                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_30363(285379) on node maestro-1033                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_29076(284092) on node maestro-1023                                                                             
2020-08-03T10:27:51+02:00 maestro-sched slurmctld[16342]: debug:  Killing JobId=204075_30724(285740) on node maestro-1029      


I attach a new sdiag output. 

Thanks for your help,

Created attachment 15272 [details]
sdiag after second scontrol reconfigure

The load of the machine was near 0, slurmctld was at 2 or 3% of CPU.

It appears that message aggregation is no longer the issue.

The two biggest time consumers seem to be related to job ends (and maybe starts) from the sdiag output you supplied (resorted sdiag RPC by message type largest total time to smallest):

>Remote Procedure Call statistics by message type
>
>        REQUEST_STEP_COMPLETE                   ( 5016) count: 18792  ave_time: 61077  total_time: 1147775841
>        REQUEST_COMPLETE_BATCH_SCRIPT           ( 5018) count: 9396   ave_time: 104812 total_time:  984816565
>        REQUEST_JOB_PACK_ALLOC_INFO             ( 4027) count: 12463  ave_time: 9331   total_time:  116303904
>        REQUEST_RECONFIGURE                    ( 1003) count: 2      ave_time: 57658152 total_time: 115316304
>        REQUEST_JOB_STEP_CREATE                 ( 5001) count: 12463  ave_time: 7552   total_time:   94121707
>        MESSAGE_NODE_REGISTRATION_STATUS        ( 1002) count: 950    ave_time: 97993  total_time:   93093454
>        MESSAGE_EPILOG_COMPLETE                 ( 6012) count: 9396   ave_time: 8236   total_time:   77391652
>        REQUEST_COMPLETE_PROLOG                 ( 6018) count: 12468  ave_time: 525    total_time:    6551868
>        REQUEST_JOB_INFO                        ( 2003) count: 2      ave_time: 5058   total_time:      10117
>        REQUEST_NODE_INFO                       ( 2007) count: 14     ave_time: 454    total_time:       6362
>        REQUEST_PARTITION_INFO                  ( 2009) count: 16     ave_time: 299    total_time:       4785
>        MESSAGE_COMPOSITE                      ( 11001) count: 1      ave_time: 1640   total_time:       1640
>        REQUEST_UPDATE_NODE                     ( 3002) count: 1      ave_time: 895    total_time:        895
>        REQUEST_BUILD_INFO                      ( 2001) count: 1      ave_time: 426    total_time:        426
>        REQUEST_STATS_INFO                      ( 2035) count: 1      ave_time: 338    total_time:        338
>        REQUEST_PING                            ( 1008) count: 1      ave_time: 162    total_time:        162

Could you send a full slurmctld.log so I can look closer? Also, if you could send another sdiag output, I'd be interested to see if/how the numbers have changed since your last one.

Thanks.

Hello,

  I had to wait because I discovered that all the new job array tasks
completed with FAILED status. I checked several things to understand
the reason of that new behavior and put a hold on the job arrays while
investigating.
I figured out that it was due to a change made by the user in the config
file of the program run by the job array tasks to try to prevent them
from running.
  Now that this config file is back to normal and job array tasks complete 
successfully, I notice that the scontrol reconfigure are instantaneous:

$ time scontrol reconfigure

real    0m0.070s
user    0m0.003s
sys     0m0.001s

$ time scontrol reconfigure

real    0m0.073s
user    0m0.002s
sys     0m0.002s

I don't have any warning anymore in the logs either. I attach another
sdiag output.

  I don't see how it could have interfered with the Slurm processing time 
but it's the only thing that has changed since my last message.

Created attachment 15297 [details]
sdiag output done on the 4th of August 4:25pm

I'm glad things are better. Let's have you continue running without the message aggregation for a few more days and see how things go.

Okay, let's do that.

For my information, do you know approximately when the next 20.02 release
is supposed to be announced? I would like to upgrade our preproduction
cluster when I have the opportunity.

Thanks and have a nice day,

We expect 20.02.4 to be released soon but we don't have a specific date yet as we are waiting on a few important fixes to be worked out first so we can include them. I'll provide an update once we have something more precise.

Also note that when 20.02.3 (latest version) was released, this statement was made:

--
Message Aggregation is off in Slurm by default, and is only enabled by
MsgAggregationParams=WindowMsgs=<msgs>, where <msgs> is greater than 1.
(Using Message Aggregation on your systems is not a recommended
configuration at this time, and we may retire this subsystem in a future
Slurm release in favor of other RPC aggregation techniques. Although
care must be taken before disabling this to avoid communication issues.)
--

So, if things continue well for you without it, you may want to leave it that way.

 -Chad

> So, if things continue well for you without it, you may want to leave
> it that way.

  Definitely.

  Thanks for highlighting that statement. Hope that 20.02.4 will be released
by the end of August. Finger crossed.

  Have a nice day,

(In reply to Sophie Créno from comment #17)
> Hope that 20.02.4 will be released
> by the end of August. Finger crossed.
Good news: 20.02.4 is scheduled to be released today! If you are not already, you may want to subscribe to the slurm-users mailing list. Releases announcements are posted on it. More info here:

https://slurm.schedmd.com/mail.html

 -Chad

I'm going to close this out for now. Feel free to submit a new ticket if you encounter future problems.

 -Chad