autoscaler: CA fails to scale-up or cancel in-progress scale down when there are un-schedulable pods

Which component are you using?: cluster-autoscaler

What version of the component are you using?: cluster-autoscaler

Component version: k8s.gcr.io/autoscaling/cluster-autoscaler:v1.20.0

What k8s version are you using (kubectl version)?: v1.20.10

$ kubectl version
Server Version: version.Info{Major:"1", Minor:"20", GitVersion:"v1.20.10", GitCommit:"8152330a2b6ca3621196e62966ef761b8f5a61bb", GitTreeState:"clean", BuildDate:"2021-08-11T18:00:37Z", GoVersion:"go1.15.15", Compiler:"gc", Platform:"linux/amd64"}

What environment is this in?:

KOPS (v1.20.2) based cluster deployed on AWS

CA is run with the following arguments

- ./cluster-autoscaler
- --v=2
- --stderrthreshold=info
- --cloud-provider=aws
- --skip-nodes-with-local-storage=false
- --skip-nodes-with-system-pods=false
- --node-group-auto-discovery=asg:tag=k8s.io/cluster-autoscaler/enabled,k8s.io/cluster-autoscaler/env-name
- --scale-down-utilization-threshold=0.6
- --balance-similar-node-groups
- --ignore-taint=node-upgrading
- --max-graceful-termination-sec=10800
- --scale-down-delay-after-delete=5m
- --max-empty-bulk-delete=2
- --scale-down-delay-after-add=5m

The nodes span multiple AZs, but we use separate ASGs for each AZ. Also there are several node groups with different taints so that we can place applications in dedicated node groups.

node-group-1-az1
node-group-1-az2
node-group-1-az3
node-group-2-az1
node-group-2-az2
node-group-2-az3
...
...
...

In the above case, all node-group-1-xx node groups have the same taints, instance types etc.

We use HPA for many of our applications, and can dynamically scale up and down the number of replicas. As can be seen below, the scale up happen every hour and then the load subsides, and the HPA scales down the number of replicas.

Due to the nature of our applications, some of them are configured with a termination grace period of up to 3 hours. Since we do not want CA to prematurely terminate a node, we have configured CA with --max-graceful-termination-sec=10800 which is the maximum termination grace period across all pods in the cluster.

What did you expect to happen?:

When an HPA scales up a deployment, CA should scale up the appropriate node group without any delay if there is no available capacity. The pods will fit any of the nodes coming under node-group-x-az1 or node-group-x-az2 or node-group-x-az3

What happened instead?:

We noticed that CA does not trigger a scale up always and the pod remains in a Pending state for 20-30 min or at times even more.

I1105 11:06:16.999039       1 event.go:291] "Event occurred" object="default/app-1-cf767bfc7" kind="ReplicaSet" apiVersion="apps/v1" type="Normal" reason="SuccessfulCreate" message="Created pod: app-1-cf767bfc7-jtcc4"
I1105 11:26:37.889440       1 scheduler.go:604] "Successfully bound pod to node" pod="default/app-1-cf767bfc7-jtcc4" node="ip-10-10-72-247.ec2.internal" evaluatedNodes=93 feasibleNodes=1

In the above case, the pod remained in Pending state for 20 minutes and CA was logging messages such as below repeatedly.

I1105 11:07:58.593642 1 filter_out_schedulable.go:157] Pod default.app-1-cf767bfc7-m5672 marked as unschedulable can be scheduled on node template-node-for-node-group-2-az2-6211936831103862438-0. Ignoring in scale up.
I1105 11:07:58.593798 1 filter_out_schedulable.go:157] Pod default.app-1-cf767bfc7-jtcc4 marked as unschedulable can be scheduled on node template-node-for-node-group-2-az2-6211936831103862438-0. Ignoring in scale up.
I1105 11:07:58.593818 1 filter_out_schedulable.go:170] 0 pods were kept as unschedulable based on caching
I1105 11:07:58.593825 1 filter_out_schedulable.go:171] 2 pods marked as unschedulable can be scheduled.

From a kube-scheduler perspective, the log said

I1105 11:06:17.027552 1 factory.go:322] "Unable to schedule pod; no fit; waiting" pod="default/app-1-cf767bfc7-jtcc4" err="
0/93 nodes are available: 
 1 node(s) had taint {ToBeDeletedByClusterAutoscaler: 1636105837}, that the pod didn't tolerate, 
 1 node(s) had taint {dedicated: app-group-2}, that the pod didn't tolerate, 
 1 node(s) had taint {dedicated: app-group-3}, that the pod didn't tolerate, 
 1 node(s) had taint {dedicated: app-group-4}, that the pod didn't tolerate, 
 1 node(s) had taint {dedicated: app-group-5}, that the pod didn't tolerate, 
 10 node(s) had taint {dedicated: app-group-6}, that the pod didn't tolerate, 
 17 Insufficient cpu, 
 2 node(s) had taint {dedicated: app-group-7}, that the pod didn't tolerate, 
 3 node(s) had taint {node-role.kubernetes.io/master: }, that the pod didn't tolerate, 
 33 node(s) had taint {dedicated: app-group-8}, that the pod didn't tolerate, 
 6 node(s) had taint {dedicated: app-group-9}, that the pod didn't tolerate, 
 8 node(s) didn't match Pod's node affinity, 
 9 node(s) had taint {dedicated: app-group-10}, that the pod didn't tolerate."

Investigating further on the 1 node(s) had taint {ToBeDeletedByClusterAutoscaler: 1636105837} message, we noticed there was a scale down in progress which had been initiated around 76 min prior to the new un-schedulable pod being created. The node in question was ip-10-10-77-101.ec2.internal which was the same node that had the ToBeDeletedByClusterAutoscaler 1636105837 taint. The node also belonged to one of the node-groups where the pod could have been scheduled.

I1105 09:50:37.035315       1 event_sink_logging_wrapper.go:48] Event(v1.ObjectReference{Kind:"ConfigMap", Namespace:"kube-system", Name:"cluster-autoscaler-status", UID:"3015546a-9c9e-4c53-b568-efba24823b6d", APIVersion:"v1", ResourceVersion:"1388297360", FieldPath:""}): type: 'Normal' reason: 'ScaleDown' Scale-down: removing node ip-10-10-77-101.ec2.internal, utilization: {0.33875 0.17038226983488522 0 cpu 0.33875}, pods to reschedule: default/app-2-848fdf7fcc-jmf4z,default/app-3-7768795d75-skgtk,default/app-4-66fc8d76dc-58vkv,default/app-5-7d95497c9c-8zzl4
I1105 09:50:37.047558       1 event_sink_logging_wrapper.go:48] Event(v1.ObjectReference{Kind:"Node", Namespace:"", Name:"ip-10-10-77-101.ec2.internal", UID:"da45409f-0ea3-4e5e-b63e-1c657d30e473", APIVersion:"v1", ResourceVersion:"1388297432", FieldPath:""}): type: 'Normal' reason: 'ScaleDown' marked the node as toBeDeleted/unschedulable
I1105 12:50:41.577858       1 scale_down.go:1266] All pods removed from ip-10-10-77-101.ec2.internal
I1105 12:50:43.216890       1 scale_down.go:1054] Scale-down: removing empty node ip-10-10-77-101.ec2.internal
I1105 12:50:43.216947       1 delete.go:111] ToBeDeletedByClusterAutoscaler already present on node ip-10-10-77-101.ec2.internal, taint: {ToBeDeletedByClusterAutoscaler 1636105837 NoSchedule <nil>}
I1105 12:50:43.217131       1 event_sink_logging_wrapper.go:48] Event(v1.ObjectReference{Kind:"ConfigMap", Namespace:"kube-system", Name:"cluster-autoscaler-status", UID:"3015546a-9c9e-4c53-b568-efba24823b6d", APIVersion:"v1", ResourceVersion:"1388523279", FieldPath:""}): type: 'Normal' reason: 'ScaleDownEmpty' Scale-down: removing empty node ip-10-10-77-101.ec2.internal

CA seem to be thinking that the above node can be used to schedule the un-schedulable pod but it is actually being deleted due to under-utilisation. Due to a max termination grace period of 3 hours (and cause the pods already running on the node failed to grace-fully terminate before that), CA had to wait 3 hours for all pods to be removed from the affected node. During this interval, there was no scale up triggered by CA even though there were pods that needed to be scheduled.

To summarise, it appears CA will not trigger a scale up in node groups where a scale down is in progress, even if there are Pending pods waiting to be scheduled. This may not be a real issue if termination grace period isn’t this long.

Anyway, the current behaviour doesn’t seem right as CA thinks that the pod is schedulable and does nothing, but there is no capacity and should have triggered a scale-up. I am not sure if that is efficient though, perhaps CA should just cancel the in-progress scale down by removing the ToBeDeletedByClusterAutoscaler taint allowing the Pending pod to be scheduled immediately? I would think this is more efficient than allowing a new node to launch.

We see this behaviour happen multiple times a day in our prod environments. At times, capacity is made available after couple of minutes without a scale up possibly due to reduction in number of replicas of other services/pods running on the same node groups. But the fundamental issue of CA failing to scale up or cancel the in-progress scale down is a problem.

How to reproduce it (as minimally and precisely as possible):

This should be re-produceable whenever there are Pending pods to be scheduled and there is a scale down in progress due to under-utilisation needing eviction of existing pods. If CA and the pods are configured with a high max termination grace period and the pods take a while to gracefully terminate, CA will not trigger a scale up or cancel the in-progress scale down.

Anything else we need to know?: