very slow Karpenter consolidation

[shay-ul]

Version

Karpenter Version: v0.27.2

Kubernetes Version: v1.25.0

Expected Behavior

1. We have peak hours where hundreds of nodes are being provisioned.
2. In a matter of hours, most of the workload (deployments) is scaled down or deleted.
3. We expect rapid decrease in node count using the consolidation method.

Actual Behavior

We see very slow consolidation. When we restart the Karpenter pods, we see Karpenter immediately starts working as expected.

We first witnessed this issue on April 17th, we did not understand what is going on so we restarted Karpenter at around 7am, and then we saw a decrease in node count. After investigating, we came across #3576 which suggested we should upgrade to 0.27.2 to avoid this issue, and so we did.
April 18th looked fantastic, Karpenter started consolidation at 4am and by the time we started working at 7am the node count was great and we declared this issue as resolved.
On April 19th and today (April 20th) we woke up to see we have many nodes, we restarted Karpenter and again the consolidation started working again.

All of this can be witnessed here:

In comparison to the overall number of pods in the cluster, we can see that the peak starts at 1:30am (UTC+3). We have 15k pods running at peak. by 5am we have less than 5k pods, which means that by 5:30am we should have much less nodes on the cluster:

Steps to Reproduce the Problem

I have the full log of the Karpenter controller before we restarted the deployments. While it does look like the controller.deprovision is doing some work, it is very slow to initiate the process and we expect many more nodes to be already gone by this point:

2023-04-20T04:42:37.773Z	INFO	controller.deprovisioning	deprovisioning via consolidation delete, terminating 8 machines ip-192-168-1-180.us-east-2.compute.internal/c5a.xlarge/spot, ip-192-168-1-48.us-east-2.compute.internal/c5a.xlarge/spot, ip-192-168-1-240.us-east-2.compute.internal/c5a.xlarge/spot, ip-192-168-2-74.us-east-2.compute.internal/c6a.2xlarge/spot, ip-192-168-1-74.us-east-2.compute.internal/c5a.xlarge/spot, ip-192-168-1-39.us-east-2.compute.internal/c5a.xlarge/spot, ip-192-168-1-173.us-east-2.compute.internal/c5a.xlarge/spot, ip-192-168-1-69.us-east-2.compute.internal/c5a.xlarge/spot	{"commit": "d01ea11-dirty"}
2023-04-20T04:42:37.785Z	INFO	controller.termination	cordoned node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-180.us-east-2.compute.internal"}
2023-04-20T04:42:37.795Z	INFO	controller.termination	cordoned node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-48.us-east-2.compute.internal"}
2023-04-20T04:42:37.804Z	INFO	controller.termination	cordoned node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-240.us-east-2.compute.internal"}
2023-04-20T04:42:37.834Z	INFO	controller.termination	cordoned node	{"commit": "d01ea11-dirty", "node": "ip-192-168-2-74.us-east-2.compute.internal"}
2023-04-20T04:42:37.874Z	INFO	controller.termination	cordoned node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-74.us-east-2.compute.internal"}
2023-04-20T04:42:37.914Z	INFO	controller.termination	cordoned node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-39.us-east-2.compute.internal"}
2023-04-20T04:42:37.922Z	INFO	controller.termination	cordoned node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-173.us-east-2.compute.internal"}
2023-04-20T04:42:37.968Z	INFO	controller.termination	cordoned node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-69.us-east-2.compute.internal"}
2023-04-20T04:42:38.599Z	INFO	controller.termination	deleted node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-69.us-east-2.compute.internal"}
2023-04-20T04:42:38.602Z	INFO	controller.termination	deleted node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-173.us-east-2.compute.internal"}
2023-04-20T04:42:38.606Z	INFO	controller.termination	deleted node	{"commit": "d01ea11-dirty", "node": "ip-192-168-2-74.us-east-2.compute.internal"}
2023-04-20T04:42:38.608Z	INFO	controller.termination	deleted node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-180.us-east-2.compute.internal"}
2023-04-20T04:42:38.611Z	INFO	controller.termination	deleted node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-48.us-east-2.compute.internal"}
2023-04-20T04:42:44.040Z	INFO	controller.termination	deleted node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-39.us-east-2.compute.internal"}
2023-04-20T04:42:44.371Z	INFO	controller.termination	deleted node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-240.us-east-2.compute.internal"}
2023-04-20T04:42:50.385Z	INFO	controller.termination	deleted node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-74.us-east-2.compute.internal"}
2023-04-20T04:43:07.684Z	INFO	controller.deprovisioning	deprovisioning via consolidation delete, terminating 3 machines ip-192-168-1-132.us-east-2.compute.internal/c6a.2xlarge/spot, ip-192-168-1-19.us-east-2.compute.internal/c5a.xlarge/spot, ip-192-168-1-30.us-east-2.compute.internal/c5a.xlarge/spot	{"commit": "d01ea11-dirty"}
2023-04-20T04:43:07.696Z	INFO	controller.termination	cordoned node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-132.us-east-2.compute.internal"}
2023-04-20T04:43:07.707Z	INFO	controller.termination	cordoned node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-19.us-east-2.compute.internal"}
2023-04-20T04:43:07.718Z	INFO	controller.termination	cordoned node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-30.us-east-2.compute.internal"}
2023-04-20T04:43:08.099Z	INFO	controller.termination	deleted node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-19.us-east-2.compute.internal"}
2023-04-20T04:43:08.101Z	INFO	controller.termination	deleted node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-132.us-east-2.compute.internal"}
2023-04-20T04:43:20.260Z	INFO	controller.termination	deleted node	{"commit": "d01ea11-dirty", "node": "ip-192-168-1-30.us-east-2.compute.internal"}
2023-04-20T04:43:39.233Z	INFO	controller.deprovisioning	deprovisioning via consolidation delete, terminating 1 machines ip-192-168-1-239.us-east-2.compute.internal/c5a.xlarge/spot	{"commit": "d01ea11-dirty"}

Resource Specs and Logs

apiVersion: karpenter.sh/v1alpha5
kind: Provisioner
metadata:
  annotations:
    kubectl.kubernetes.io/last-applied-configuration: |
      {"apiVersion":"karpenter.sh/v1alpha5","kind":"Provisioner","metadata":{"annotations":{},"labels":{"app.kubernetes.io/instance":"prod"},"name":"scan-pipeline-node-provisioner"},"spec":{"consolidation":{"enabled":true},"kubeletConfiguration":{"maxPods":110},"labels":{"scan-pipeline-node":"true"},"limits":{"resources":{"cpu":"2400","memory":"4800Gi"}},"providerRef":{"name":"deafult-nodes-template"},"requirements":[{"key":"karpenter.sh/capacity-type","operator":"In","values":["spot"]},{"key":"node.kubernetes.io/instance-type","operator":"In","values":["c6a.2xlarge","c5a.2xlarge","c5.2xlarge","c6a.xlarge","c5a.xlarge","c5.xlarge"]},{"key":"topology.kubernetes.io/zone","operator":"In","values":["us-east-2a","us-east-2b"]},{"key":"kubernetes.io/arch","operator":"In","values":["arm64","amd64"]},{"key":"kubernetes.io/os","operator":"In","values":["linux"]}],"taints":[{"effect":"NoSchedule","key":"scan-pipeline-node"}]}}
  creationTimestamp: "2023-01-08T08:57:34Z"
  generation: 17
  labels:
    app.kubernetes.io/instance: prod
  name: scan-pipeline-node-provisioner
  resourceVersion: "188490435"
  uid: fce0308f-5ef9-4e6a-8885-a547e7b3ce83
spec:
  consolidation:
    enabled: true
  kubeletConfiguration:
    maxPods: 110
  labels:
    scan-pipeline-node: "true"
  limits:
    resources:
      cpu: "2400"
      memory: 4800Gi
  providerRef:
    name: deafult-nodes-template
  requirements:
  - key: karpenter.sh/capacity-type
    operator: In
    values:
    - spot
  - key: node.kubernetes.io/instance-type
    operator: In
    values:
    - c6a.2xlarge
    - c5a.2xlarge
    - c5.2xlarge
    - c6a.xlarge
    - c5a.xlarge
    - c5.xlarge
  - key: topology.kubernetes.io/zone
    operator: In
    values:
    - us-east-2a
    - us-east-2b
  - key: kubernetes.io/arch
    operator: In
    values:
    - arm64
    - amd64
  - key: kubernetes.io/os
    operator: In
    values:
    - linux
  taints:
  - effect: NoSchedule
    key: scan-pipeline-node
status:
  resources:
    attachable-volumes-aws-ebs: "64"
    cpu: "12"
    ephemeral-storage: 123808920Ki
    memory: 24015712Ki
    pods: "220"

apiVersion: karpenter.k8s.aws/v1alpha1
kind: AWSNodeTemplate
metadata:
  annotations:
    kubectl.kubernetes.io/last-applied-configuration: |
      {"apiVersion":"karpenter.k8s.aws/v1alpha1","kind":"AWSNodeTemplate","metadata":{"annotations":{},"labels":{"app.kubernetes.io/instance":"prod"},"name":"deafult-nodes-template"},"spec":{"amiFamily":"Bottlerocket","blockDeviceMappings":[{"deviceName":"/dev/xvdb","ebs":{"deleteOnTermination":true,"encrypted":true,"volumeSize":"60Gi","volumeType":"gp3"}}],"instanceProfile":"eks-58c2b634-62f4-55dc-8638-f888aff9c840","securityGroupSelector":{"karpenter.sh/discovery":"prod"},"subnetSelector":{"karpenter.sh/discovery":"prod"},"userData":"[settings]\n[settings.kubernetes]\nallowed-unsafe-sysctls = [\"net.core.somaxconn\"]\nregistry-qps = 20\n"}}
  creationTimestamp: "2023-04-03T04:29:38Z"
  generation: 5
  labels:
    app.kubernetes.io/instance: prod
  name: deafult-nodes-template
  resourceVersion: "188516647"
  uid: f67f682c-0663-4fa2-b04f-4785fe2df2a3
spec:
  amiFamily: Bottlerocket
  blockDeviceMappings:
  - deviceName: /dev/xvdb
    ebs:
      deleteOnTermination: true
      encrypted: true
      volumeSize: 60Gi
      volumeType: gp3
  instanceProfile: eks-58c2b634-62f4-55dc-8638-f888aff9c840
  securityGroupSelector:
    karpenter.sh/discovery: prod
  subnetSelector:
    karpenter.sh/discovery: prod
  userData: |
    [settings]
    [settings.kubernetes]
    allowed-unsafe-sysctls = ["net.core.somaxconn"]
    registry-qps = 20

Community Note

• Please vote on this issue by adding a 👍 reaction to the original issue to help the community and maintainers prioritize this request
• Please do not leave "+1" or "me too" comments, they generate extra noise for issue followers and do not help prioritize the request
• If you are interested in working on this issue or have submitted a pull request, please leave a comment

[shay-ul]

Until we find a solution, we created a cronjob to rollout restart the Karpenter deployment every 3 hours. We hope to see different numbers tomorrow morning.

[tzneal]

Can we get the full Karpenter logs that show this slowdown occurring? You can create an AWS support ticket and attach the information there if you want the data to remain private.

[shay-ul]

Thanks @tzneal, I have created a ticket - 12553960191
The full log was attached there.
Thanks

[shay-ul]

I have also checked performance for the Karpenter Deployment. The node that the deployment resides on in dedicated to management workload which is not affected by the load increase during peak hours, so no CPU thottling or memory pressure occured.
We can also observe CPU and Memory for the Karpenter deployment itself:

Right after the deployment restarts, we can see that it works pretty hard and consumes up to 3CPU and 1.55GiB of memory. This peak lasts six minutes.

[tzneal]

During those six minutes, is consolidation occurring? Also if you can attach other logs to the ticket from other Karpenter runs (i.e. the run just before and just after the attached logs), that would help as well.

[tzneal]

When this occurs, can you see if there are events registered on the node?

[shay-ul]

We suspended the cronjob so we can replicate this issue again and have more logs for you.
Karpenter was last restarted yesterday evening, and this morning it looks like Karpenter is working fine so far (Just like it did right after we upgraded to 0.27.2). See how it is working this morning, compared to yesterday (where the steep drop in node count happened only when we restarted the deployment)

we will update tomorrow morning and attach more logs. We expect consolidation delay to occur again tomorrow or on the day after that.

[tzneal]

Sounds good, before you manually restart check for events on the nodes as well.

[jonathan-innis]

@shay-ul We have a snapshot karpenter release helm chart that contains additional logs and eventing in the key places in deprovisioning. If you're willing to install the release in your environment, it would help us debug the issue quicker as well (v0-c3d4e738b6ea4cd0f60092e698a77a535a31574e)

export KARPENTER_VERSION=v0-c3d4e738b6ea4cd0f60092e698a77a535a31574e
helm upgrade --install karpenter oci://public.ecr.aws/karpenter/karpenter --version ${KARPENTER_VERSION} --namespace karpenter --create-namespace \
  --set serviceAccount.annotations."eks\.amazonaws\.com/role-arn"=${KARPENTER_IAM_ROLE_ARN} \
  --set settings.aws.clusterName=${CLUSTER_NAME} \
  --set settings.aws.defaultInstanceProfile=KarpenterNodeInstanceProfile-${CLUSTER_NAME} \
  --set settings.aws.interruptionQueueName=${CLUSTER_NAME} \
  --set controller.resources.requests.cpu=1 \
  --set controller.resources.requests.memory=1Gi \
  --set controller.resources.limits.cpu=1 \
  --set controller.resources.limits.memory=1Gi \
  --wait

[shay-ul]

As promised, we have an update for this morning as well.
This morning we let Karpenter handle things on its own terms - meaning, we did not restart the deployment. We do see that eventually Karpenter consolidates nodes, but it does so very late. This how this morning's peak looks like:

We expect consolidation to start at around 3:50am (UTC+3), just like what happened on the provious day:

I have attached the full logs for the Karpenter controller on support ticket 12553960191.

When it comes to events on nodes, here is an example of a node that we expect to be consolidated:

  Resource                    Requests     Limits
  --------                    --------     ------
  cpu                         365m (9%)    550m (14%)
  memory                      695Mi (11%)  3368Mi (53%)
  ephemeral-storage           0 (0%)       0 (0%)
  hugepages-1Gi               0 (0%)       0 (0%)
  hugepages-2Mi               0 (0%)       0 (0%)
  attachable-volumes-aws-ebs  0            0
Events:
  Type    Reason                 Age                   From       Message
  ----    ------                 ----                  ----       -------
  Normal  DeprovisioningBlocked  27m (x11 over 48m)    karpenter  Cannot deprovision node due to pod tenant-a/a-59dbed56-redis-0 has do not evict annotation
  Normal  Unconsolidatable       7m51s (x8 over 175m)  karpenter  not all pods would schedule

As we can see, the node previously had a pod with do not evict annotation. The pod was quickly deleted from the node, but the node persisted.

Here is another example:

  Resource                    Requests     Limits
  --------                    --------     ------
  cpu                         275m (7%)    550m (14%)
  memory                      645Mi (10%)  3368Mi (53%)
  ephemeral-storage           0 (0%)       0 (0%)
  hugepages-1Gi               0 (0%)       0 (0%)
  hugepages-2Mi               0 (0%)       0 (0%)
  attachable-volumes-aws-ebs  0            0
Events:
  Type    Reason                 Age                    From       Message
  ----    ------                 ----                   ----       -------
  Normal  DeprovisioningBlocked  23m (x13 over 48m)     karpenter  Cannot deprovision node due to pod tenant-a/a-da580772-redis-0 has do not evict annotation
  Normal  Unconsolidatable       4m29s (x9 over 5h22m)  karpenter  not all pods would schedule

At some point during the peak hours, most of the nodes appear to be near empty but they emit the same events and do not consolidate until the very end of the peak hours.

[shay-ul]

@jonathan-innis I have installed the requested Karpenter version with requests, but without limits since I'm afraid it will be OOMKilled and be restarted during peak hours.
Logs will be attached when we face this issue again, hopefully tomorrow morning.
Thanks

[jonathan-innis]

As we can see, the node previously had a pod with do not evict annotation. The pod was quickly deleted from the node, but the node persisted

When the pod with the do-not-evict annotation was removed, was the node completely empty? It might be useful to share the cluster utilization across nodes after the scale-down of the deployment. In general, is cluster utilization of these nodes around 20%/30% or are the nodes completely empty when consolidation is considering them? Were the only pods that were scheduled to these nodes the workload pods of the deployment that was scaled up and subsequently scaled down or were there other workload pods on these nodes?