Ticket 860

I see 2 things.

1. why backup starts minutes after the primary? ~20
2. The state files dont seem to be in sync.

What could be the reason?


On June 4, 2014 7:04:54 PM PDT, bugs@schedmd.com wrote:
>http://bugs.schedmd.com/show_bug.cgi?id=860
>
>              Site: DownUnder GeoSolutions
>            Bug ID: 860
>           Summary: backup controller deleted a heap of job scripts
>           Product: SLURM
>           Version: 14.03.0
>          Hardware: Linux
>                OS: Linux
>            Status: UNCONFIRMED
>          Severity: 2 - High Impact
>          Priority: ---
>         Component: slurmctld daemon
>          Assignee: david@schedmd.com
>          Reporter: stuartm@dugeo.com
>               CC: da@schedmd.com, david@schedmd.com, jette@schedmd.com
>
>I redeployed slurm today to bring in a some of your patches... and it
>created a
>disaster.
>
>The redeploy basically installs the new software then does a 
>
>    pdsh -l root -w list '/etc/init.d/slurm restart'
>
>on all nodes that use slurm.
>
>When the backup controller was restarted... it "recovered" and did
>
>[2014-06-05T09:36:45.722] Purging files for defunct batch job 2618232
>
>then on the primary controller
>
>[2014-06-05T09:57:00.631] error: Error opening file
>/d/sw/slurm/var/spool/slurm_perth/job.2618232/script, No such file or
>directory
>[2014-06-05T09:57:00.631] error: Batch script is missing, aborting job
>2618232
>[2014-06-05T09:57:00.631] completing job 2618232 status 0
>[2014-06-05T09:57:00.639] sched: job_complete for JobId=2618232
>successful,
>exit code=0
>
>-- 
>You are receiving this mail because:
>You are on the CC list for the bug.
>You are the assignee for the bug.
>You are watching someone on the CC list of the bug.
>You are watching the assignee of the bug.

As part of the deploy, the backup may restart minutes later - whenever the pdsh gets to it... but either way, the state files "should" be in sync, they are coming off an NFS mount from a 3rd machine

can you attach more of the logs? I'd like to see the backup slurmctld log from the time it was assumed control.

Created attachment 902 [details]
backup controller log

Created attachment 903 [details]
primary controller log

We have stopped using the backup controller at the moment.  We found that having the state files on an nfs mount was just too slow and causing client commands to timeout trying to talk to slurmctld.  We have gone back to having the state files on a local disk.

I can address the job loss with a couple of changes, but there is a more fundamental problem that needs to be addressed.


https://github.com/SchedMD/slurm/commit/42ab25c3e7b0dfe9a8073985381f8932418d31e6
Test time when job_state file was written to detect multiple primary slurmctld daemons (e.g. both backup and primary are functioning as primary and there is a split brain problem). If the backup becomes the primary and finds the primary is still writing to the shared file system, then exit.

https://github.com/SchedMD/slurm/commit/25c53b8f5c61d930d5768edc17daa4ef741c811d
If the backup slurmctld assumes primary status, then do NOT purge any job state files (batch script and environment files) but if any attempt is made to re-use them consider this a fatal error. It may indicate that multiple primary slurmctld daemons are active (e.g. both backup and primary are functioning as primary and there is a split brain problem).

Here is the more fundamental issue, from the primary log:
[2014-06-05T09:37:14.024] _slurm_rpc_submit_batch_job JobId=2615283 usec=617437235

What the heck is the daemon doing for 10+ minutes? That's long enough for the backup to start responding, accepting new jobs, etc. I'm guessing that is what caused the bug 805. The job was accepted by the backup, then the primary started responding again and used the same job IDs for another job, assigned it different nodes, etc.

The only thing that stands out is SchedulingParameters=max_sched_time=15
That will cause the slurmctld to run the scheduler for 15 seconds at a time. During that time, thousands of RPCs might pile up and none of them will be serviced. Also note the threads are not necessarily serviced on a first-in first-out basis. Some systems schedule pthreads first-in last-out. In short, I would feel much better about removing the max_sched_time and using the backfill scheduler to manage most of the scheduling. The backfill scheduler releases locks every couple of seconds and is designed to handle large job counts (unlike the main scheduling loop).
SchedulingParameters for backfill might look like this:
bf_continue,bf_interval=300,max_job_test=50000,bf_resolution=300

There might also be delays related to NFS or something else causing delays, but all I can tell is that the system was unresponsive for 10+ minutes.

Thanks.

Given that we were seeing client commands time out, which we believe was due to the nfs mount (certainly that's what our straces seemed to indicate - ie. 60 RPCS/s max), I can imagine that the slurmctld would become unresponsive long enough for the backup to kick in.

I have removed our value of max_sched_time=15 and I assume it will now get the max default of 4.

(In reply to Moe Jette from comment #7)
> The only thing that stands out is SchedulingParameters=max_sched_time=15
> That will cause the slurmctld to run the scheduler for 15 seconds at a time.
> During that time, thousands of RPCs might pile up and none of them will be
> serviced. Also note the threads are not necessarily serviced on a first-in
> first-out basis. Some systems schedule pthreads first-in last-out. In short,
> I would feel much better about removing the max_sched_time and using the
> backfill scheduler to manage most of the scheduling. The backfill scheduler
> releases locks every couple of seconds and is designed to handle large job
> counts (unlike the main scheduling loop).
> SchedulingParameters for backfill might look like this:
> bf_continue,bf_interval=300,max_job_test=50000,bf_resolution=300

Created attachment 908 [details]
attachment-15222-0.html

Correct but you may need the backfill scheduler to check more jobs.

On June 5, 2014 7:15:37 PM PDT, bugs@schedmd.com wrote:
>http://bugs.schedmd.com/show_bug.cgi?id=860
>
>--- Comment #9 from Stuart Midgley <stuartm@dugeo.com> ---
>I have removed our value of max_sched_time=15 and I assume it will now
>get the
>max default of 4.
>
>(In reply to Moe Jette from comment #7)
>> The only thing that stands out is
>SchedulingParameters=max_sched_time=15
>> That will cause the slurmctld to run the scheduler for 15 seconds at
>a time.
>> During that time, thousands of RPCs might pile up and none of them
>will be
>> serviced. Also note the threads are not necessarily serviced on a
>first-in
>> first-out basis. Some systems schedule pthreads first-in last-out. In
>short,
>> I would feel much better about removing the max_sched_time and using
>the
>> backfill scheduler to manage most of the scheduling. The backfill
>scheduler
>> releases locks every couple of seconds and is designed to handle
>large job
>> counts (unlike the main scheduling loop).
>> SchedulingParameters for backfill might look like this:
>> bf_continue,bf_interval=300,max_job_test=50000,bf_resolution=300
>
>-- 
>You are receiving this mail because:
>You are on the CC list for the bug.
>You are the assignee for the bug.

Our current settings are

SchedulerParameters=bf_continue,bf_max_job_test=50000,bf_interval=300,bf_resolution=300,defer,max_depend_depth=3,sched_interval=20,batch_sched_delay=10

Created attachment 909 [details]
attachment-7754-0.html

That should be lower overhead. You also need SchedulerType=sched/backfill. The sdiag tool should help to see how it's working.

On June 5, 2014 7:31:08 PM PDT, bugs@schedmd.com wrote:
>http://bugs.schedmd.com/show_bug.cgi?id=860
>
>--- Comment #11 from Stuart Midgley <stuartm@dugeo.com> ---
>Our current settings are
>
>SchedulerParameters=bf_continue,bf_max_job_test=50000,bf_interval=300,bf_resolution=300,defer,max_depend_depth=3,sched_interval=20,batch_sched_delay=10
>
>-- 
>You are receiving this mail because:
>You are on the CC list for the bug.
>You are the assignee for the bug.

Yes, we have

SchedulerType=sched/backfill

FWIW

*******************************************************
sdiag output at Fri Jun  6 10:48:56 2014
Data since      Fri Jun  6 10:17:09 2014
*******************************************************
Server thread count: 3
Agent queue size:    0

Jobs submitted: 242
Jobs started:   630
Jobs completed: 574
Jobs canceled:  531
Jobs failed:    0

Main schedule statistics (microseconds):
        Last cycle:   64104
        Max cycle:    578622
        Total cycles: 118
        Mean cycle:   64736
        Mean depth cycle:  190
        Cycles per minute: 3
        Last queue length: 2883

Backfilling stats
        Total backfilled jobs (since last slurm start): 18
        Total backfilled jobs (since last stats cycle start): 18
        Total cycles: 5
        Last cycle when: Fri Jun  6 10:42:04 2014
        Last cycle: 963180
        Max cycle:  1219593
        Mean cycle: 984140
        Last depth cycle: 1165
        Last depth cycle (try sched): 1034
        Depth Mean: 1142
        Depth Mean (try depth): 1035
        Last queue length: 3012
        Queue length mean: 2786

Some hours later... it doesn't appear backfill is giving us much.


*******************************************************
sdiag output at Fri Jun  6 13:21:46 2014
Data since      Fri Jun  6 10:17:09 2014
*******************************************************
Server thread count: 3
Agent queue size:    0

Jobs submitted: 1232
Jobs started:   12647
Jobs completed: 11716
Jobs canceled:  763
Jobs failed:    0

Main schedule statistics (microseconds):
        Last cycle:   607295
        Max cycle:    1164293
        Total cycles: 694
        Mean cycle:   106711
        Mean depth cycle:  224
        Cycles per minute: 3
        Last queue length: 4079

Backfilling stats
        Total backfilled jobs (since last slurm start): 237
        Total backfilled jobs (since last stats cycle start): 237
        Total cycles: 29
        Last cycle when: Fri Jun  6 13:13:14 2014
        Last cycle: 3832556
        Max cycle:  6533449
        Mean cycle: 2317317
        Last depth cycle: 2302
        Last depth cycle (try sched): 2299
        Depth Mean: 1520
        Depth Mean (try depth): 1439
        Last queue length: 2976
        Queue length mean: 2721