Aws-parallelcluster: Job submitted to scaled down cluster

[awacs]

Old thread: https://github.com/awslabs/cfncluster/issues/208
I've just confirmed that this issue can still happen, especially when there is large number of nodes being scaled down very fast.

The output from qstat -f is below
all.[email protected] BIP 0/2/1 -NA- lx-amd64 aduo
2863 0.60500 cromwell_f ec2-user r 03/06/2018 18:44:21 2
I confirmed using intermediate files that this job did not start at all.

[awacs]

Side question, is there a way to configure cfncluster so the scaling down doesn't happen so fast?

[mohanasudhan]

Please look at http://cfncluster.readthedocs.io/en/latest/configuration.html#scaling-cooldown which can help in scaling down slower. Note this parameter can affect your scale up behavior too

[awacs]

Is there a way for the SGE system to detect such events and exit out the jobs on these scaled down/dead clusters with an error code?

[awacs]

In addition, I have observed times where the node was scaled down while the job was still running.

[enrico-usai]

This bug has been resolved in the upcoming 1.6.0 release:
https://github.com/awslabs/cfncluster/blob/develop/CHANGELOG.rst#160

If you are willing to test the release candindate you can install it with:
pip install -Iv cfncluster==1.6.0rc1

Please keep us updated if you have the opportunity to test the rc1 or please stay tuned for the upcoming 1.6.0 release.

[tkuzuhara]

We have been running v1.6.1 for almost a week now, and continue to see this issue, along with #334. I think these two issues are related.

I documented one instance here: https://github.com/awslabs/cfncluster/issues/334#issuecomment-435142259

The problem occurs rather frequently, at least once a day or so, and often requires manual intervention to clear out. Note that we also were experiencing the problem prior to v1.6.1 as well. Any help on this would be appreciated. I would also be interested in knowing if others have been experiencing this as well.

[keien]

FYI we (same org as @tkuzuhara) still have this issue on pcluster 2.1.1

An example of a job that ran into this (just a hostname; sleep X):

$ qacct -j 149
==============================================================
qname        all.q
hostname     ip-172-31-128-119.us-west-2.compute.internal
group        eng
owner        keien
project      NONE
department   defaultdepartment
jobname      hostname
jobnumber    149
taskid       undefined
account      sge
priority     0
qsub_time    Fri Feb 15 13:30:37 2019
start_time   -/-
end_time     -/-
granted_pe   smp
slots        36
failed       25  : rescheduling
exit_status  0
ru_wallclock 0s
ru_utime     0.000s
ru_stime     0.000s
ru_maxrss    0.000B
ru_ixrss     0.000B
ru_ismrss    0.000B
ru_idrss     0.000B
ru_isrss     0.000B
ru_minflt    0
ru_majflt    0
ru_nswap     0
ru_inblock   0
ru_oublock   0
ru_msgsnd    0
ru_msgrcv    0
ru_nsignals  0
ru_nvcsw     0
ru_nivcsw    0
cpu          0.000s
mem          0.000Bs
io           0.000B
iow          0.000s
maxvmem      0.000B
arid         undefined
ar_sub_time  undefined
category     -l h_rt=86400,s_rt=86400 -pe smp 36
==============================================================
qname        all.q
hostname     ip-172-31-128-19.us-west-2.compute.internal
group        eng
owner        keien
project      NONE
department   defaultdepartment
jobname      hostname
jobnumber    149
taskid       undefined
account      sge
priority     0
qsub_time    Fri Feb 15 13:50:26 2019
start_time   Fri Feb 15 13:51:27 2019
end_time     Fri Feb 15 16:05:49 2019
granted_pe   smp
slots        36
failed       100 : assumedly after job
exit_status  137                  (Killed)
ru_wallclock 8062s
ru_utime     0.065s
ru_stime     0.107s
ru_maxrss    2.812KB
ru_ixrss     0.000B
ru_ismrss    0.000B
ru_idrss     0.000B
ru_isrss     0.000B
ru_minflt    29458
ru_majflt    0
ru_nswap     0
ru_inblock   64
ru_oublock   184
ru_msgsnd    0
ru_msgrcv    0
ru_nsignals  0
ru_nvcsw     301
ru_nivcsw    65
cpu          0.172s
mem          17.826KBs
io           2.392MB
iow          0.000s
maxvmem      2.160MB
arid         undefined
ar_sub_time  undefined
category     -l h_rt=86400,s_rt=86400 -pe smp 36

the host it was initially put on was brought up, then quickly brought down:

$ grep 128-119 /var/log/sqswatcher
2019-02-15 13:49:13,299 INFO [sqswatcher:pollQueue] Adding Hostname: ip-172-31-128-119
2019-02-15 13:49:13,299 INFO [sge:addHost] Adding ip-172-31-128-119 with 36 slots
ip-172-31-128-119.us-west-2.compute.internal added to administrative host list
ip-172-31-128-119.us-west-2.compute.internal added to submit host list
[email protected] added "ip-172-31-128-119.us-west-2.compute.internal" to exechost list
2019-02-15 13:49:13,340 INFO [sge:addHost] Connecting to host: ip-172-31-128-119 iter: 0
2019-02-15 13:51:18,047 INFO [sge:removeHost] Removing ip-172-31-128-119
[email protected] removed "ip-172-31-128-119.us-west-2.compute.internal" from administrative host list
[email protected] removed "ip-172-31-128-119.us-west-2.compute.internal" from execution host list
[email protected] removed "ip-172-31-128-119.us-west-2.compute.internal" from submit host list

normally the job would not have even restarted, and instead sit forever in the running state on a host that doesn't exist anymore, while qconf -de on the host would've failed because of the job still in the queue as we've previously shown in #334; we have had to build our own rescheduler to deal with this

I don't have any logs from the host that was brought up and subsequently brought down - this issue isn't very easily reproducible so it's hard to catch it on the fly

[lukeseawalker]

Hi @keien
while we investigate, can you send us the configuration of the cluster, the full /var/log/sqswatcher and /var/log/jobwatcher?

[keien]

Cluster config:

[global]
update_check = true
sanity_check = true
cluster_template = m5-4xlarge-ami-02860d917774b37b8-spot

[cluster m5-4xlarge-ami-spot]
custom_ami = XXXXXX
# below is inserted from config/m5-4xlarge-spot
compute_instance_type = m5.4xlarge
cluster_type = spot
spot_price = 1.00
master_instance_type = t2.medium
master_root_volume_size = 100
compute_root_volume_size = 100
initial_queue_size = 0
max_queue_size = 16
maintain_initial_size = false
base_os=centos7
key_name = ec2-admin
pre_install = s3://XXXXXX/pre_install.sh
post_install = s3://XXXXXX/post_install.sh
extra_json = { "cluster" : { "cfn_scheduler_slots" : "cores" } }
vpc_settings = default
scaling_settings = default
# below is inserted from config/vpc-default
[vpc default]
vpc_id = XXXXXX
master_subnet_id = XXXXXX
vpc_security_group_id = XXXXXX
use_public_ips = false
# below is inserted from config/scaling-profiles
[scaling default]
# Threshold for triggering CloudWatch ScaleUp action
# (defaults to 1 for default template)
scaling_threshold = 1
# Number of instances to add when called CloudWatch ScaleUp action
# (defaults to 1 for default template)
scaling_adjustment = 1
# Threshold for triggering CloudWatch ScaleUp2 action
# (defaults to 200 for default template)
#scaling_threshold2 = 200
# Number of instances to add when called CloudWatch ScaleUp2 action
# (defaults to 20 for default template)
#scaling_adjustment2 = 20
# Period to measure ScalingThreshold
# (defaults to 60 for default template)
scaling_period = 30
# Period to measure ScalingThreshold
# (defaults to 2 for default template)
scaling_evaluation_periods = 2
# Amount of time in seconds to wait before attempting further scaling actions
# (defaults to 300 for the default template
scaling_cooldown = 300

# scaling config for aggressive one-job-one-instance burst usage
[scaling one-to-one]
scaling_threshold = 1
scaling_adjustment = 1
scaling_threshold2 = 20
scaling_adjustment2 = 10

sqswatcher and jobwatcher: https://gist.github.com/keien/ed121f5e678b2b7788f339783d9fdff5

FYI after some investigation, we may have a clue about what's causing this: it seems that our AMI takes quite a bit of time to start (for unknown reasons) and it looks like the ASG itself is terminating the instance shortly after it comes up once it gets past the health check grace period. We manually increased the health check grace period and we're now monitoring to see if it fixes the issue.

Along those lines, I couldn't find any information about adding additional configuration to the CloudFormation template to do things like set the health check grace period for the ASG - is there a way to do that through pcluster?

[lukeseawalker]

Since version 1.6.0 the scaling logic changed and the new logic is described here.

The scaling parameters in your current config (scaling_threshold, scaling_adjustment, etc.) are no longer used.

The new (and only) scaling parameter is now scaledown_idletime, which is 10 minutes by default.

If your instance is taking more time to be ready (because of the custom ami or the post install scripts) it's likely that it's being terminated by this timeout.

Try to increase the scaledown_idletime value.

[keien]

Thanks @lukeseawalker

we fixed our AMI startup time and it seems to have fixed this particular issue

will try the scaledown_idletime if we see similar issues again

thanks for the info