Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Nodes come up slower then expected #1639

Closed
mmclane opened this issue Apr 7, 2022 · 25 comments
Closed

Nodes come up slower then expected #1639

mmclane opened this issue Apr 7, 2022 · 25 comments
Assignees
@dewjam
Labels
bug Something isn't working roadmap We're thinking about next steps

Comments

@mmclane
Copy link

mmclane commented Apr 7, 2022

Version

Karpenter: v0.8.1

Kubernetes: v1.21.1

Expected Behavior

Brandon (on slack) suggested that my nodes should be coming up a little faster and asked me to post an issue so the team could look into it.

Actual Behavior

I have an EKS cluster running with the latest CNI plugin (v.1.10.2) and I am using the latest version of Karpenter to scale nodes out dynamically. That works great but I am seeing some slowness when a new nodes is added that I can't explain and I am trying to understand and if possible improve. The following are my observations. I have found these times to be fairly consistent over multiple tests.

Core cluster nodes support 6 pods of our application running. When I added a new pod to our cluster and it gets scheduled on an existing node, the pods are ready and available in ~40s.

Adding two pods so that karpenter creates a new node creates a t3.medium.

  • Without linkerd-proxy
    • node is ready in ~ 80-90s
    • pods sit at CreatingContainer for 3m, waiting on the CNI
    • pods ready and available at ~ 3m45s
  • With linkerd-proxy
    • node is ready in ~ 80-90s
    • init container executes almost immediately.
    • pods sit at podInitializing for ~3m10 (When proxy is ready)
    • pods fully ready in ~ 4m

Adding eight new pods, karpenter creates a t3.2xlarge

  • With linkerd-proxy
    • node is ready in ~ 80-90s
    • aws-node pod takes 30s to start
    • init continers executes ~2m20s
    • pods sit at podInitializing for ~ 6m40s (When proxy is ready)
    • pods fully ready in ~ 7m30s

During this time the pods report that they are waiting on the CNI to be available but that only takes 30s after the node is ready. It also doesn't explain why it takes so much longer for a larger node then a smaller one. I suspect that this might be related: aws/amazon-vpc-cni-k8s#1943 but I don't know when that will make it into a release.

I have also created an issue on the aws/amazon-vpc-cni-k8s repo: aws/amazon-vpc-cni-k8s#1956

Steps to Reproduce the Problem

Use karpenter to create a small node (t3.small) and node the times, then have it create a large node (t3.xlarge) and node the difference in how long it takes for your pods to be available.

Resource Specs and Logs

Provisioner spec

---
apiVersion: karpenter.sh/v1alpha5
kind: Provisioner
metadata:
  name: docnetwork-app

spec:
  ttlSecondsUntilExpired: 21600 # 6 Hours = 60 * 60 * 6 Seconds
  ttlSecondsAfterEmpty: 30

  taints:
    - key: dedicated
      value: dn-prod
      effect: NoSchedule

  # Labels are arbitrary key-values that are applied to all nodes
  labels:
    app: dn
    dedicated: dn-prod
    group: app-dedicated
    ManagedBy: karpenter
    # node-role.kubernetes.io/karpenter: app-dedicated

  requirements:
  # - key: node.kubernetes.io/instance-type
  #   operator: In
  #   values: ["c5.xlarge"]
  - key: karpenter.sh/capacity-type
    operator: In
    values: ["spot", "on-demand"]
  - key: kubernetes.io/arch
    operator: In
    values:
    - amd64

  provider:
    instanceProfile: dn-main-eks-karpenter-instance-profile
    blockDeviceMappings:
      - deviceName: /dev/xvda
        ebs:
          volumeSize: 50Gi
          volumeType: gp2
          encrypted: false
          deleteOnTermination: true

    securityGroupSelector:
      aws:eks:cluster-name: dn-main-eks
    subnetSelector:
      Name: dn-main-private-*
    tags:
      Name: dn-main-eks-node
      datadog: "yes"
      ManagedBy: karpenter

Deployment Spec:

apiVersion: apps/v1
kind: Deployment
metadata:
  name: app
  namespace: prod
  annotations:
    ignore-check.kube-linter.io/no-read-only-root-fs: "PM2 needs access to write to
      root fs"
    ignore-check.kube-linter.io/run-as-non-root: "PM2 needs access to write to root
      fs"
    ignore-check.kube-linter.io/no-anti-affinity: "Not supported by karpenter"
  labels:
    app: dn
spec:
  replicas: 2 # Prod value is 16
  strategy:
    type: RollingUpdate
    rollingUpdate:
      maxSurge: 25%
      maxUnavailable: 25%
  selector:
    matchLabels:
      app: dn
  template:
    metadata:
      annotations:
        config.alpha.linkerd.io/proxy-wait-before-exit-seconds: "30"
        linkerd.io/inject: enabled
        # The following configures our custom metrics picked up by datadog's openmetrics integration.
        ad.datadoghq.com/app.check_names: |
          ["openmetrics"]
        ad.datadoghq.com/app.init_configs: |
          [{}]
        ad.datadoghq.com/app.instances: |
          [
            {
              "prometheus_url": "http://%%host%%:3001/cluster_metrics",
              "namespace": "prom",
              "metrics": [
                {
                  "docnetwork_api_http_requests_total": "docnetwork_api_http_requests_total",
                  "docnetwork_read_replica_choice_count": "docnetwork_read_replica_choice_count",
                  "docnetwork_application_query_time_milliseconds": "docnetwork_application_query_time_milliseconds",
                  "docnetwork_notifications_created_count": "docnetwork_notifications_created_count",
                  "docnetwork_app_transaction_success_total": "docnetwork_app_transaction_success_total",
                  "docnetwork_app_transaction_failure_total": "docnetwork_app_transaction_failure_total",
                  "docnetwork_app_transaction_absolute_amount_cents": "docnetwork_app_transaction_absolute_amount_cents",
                  "docnetwork_get_access_time_milliseconds": "docnetwork_get_access_time_milliseconds",
                  "docnetwork_slow_time_seconds": "docnetwork_slow_time_seconds",
                  "docnetwork_pending_query_pressure_primary": "docnetwork_pending_query_pressure_primary",
                  "docnetwork_pending_query_pressure_replicas": "docnetwork_pending_query_pressure_replicas",
                  "docnetwork_app_memory_rss_bytes": "docnetwork_app_memory_rss_bytes",
                  "docnetwork_app_memory_heap_total_bytes": "docnetwork_app_memory_heap_total_bytes",
                  "docnetwork_app_memory_heap_used_bytes": "docnetwork_app_memory_heap_used_bytes",
                  "docnetwork_app_memory_external_bytes": "docnetwork_app_memory_external_bytes",
                  "docnetwork_http_requests_total": "docnetwork_http_requests_total",
                  "docnetwork_http_request_time_nanoseconds": "docnetwork_http_request_time_nanoseconds",
                  "docnetwork_api_http_requests_total": "docnetwork_api_http_requests_total",
                  "docnetwork_api_http_request_time_nanoseconds": "docnetwork_api_http_request_time_nanoseconds",
                  "docnetwork_api_http_request_error_total": "docnetwork_api_http_request_error_total",
                  "docnetwork_authentication_failed_total": "docnetwork_authentication_failed_total",
                  "docnetwork_authentication_success_total": "docnetwork_authentication_success_total",
                  "docnetwork_app_oauth2_successful_authentication_count": "docnetwork_app_oauth2_successful_authentication_count",
                  "docnetwork_app_oauth2_failed_authentication_count": "docnetwork_app_oauth2_failed_authentication_count",
                  "docnetwork_app_oauth_refresh_token_success_total": "docnetwork_app_oauth_refresh_token_success_total",
                  "docnetwork_app_oauth_refresh_token_failed_total": "docnetwork_app_oauth_refresh_token_failed_total",
                  "docnetwork_app_csv_parse_time_milliseconds": "docnetwork_app_csv_parse_time_milliseconds",
                  "docnetwork_app_xlsx_parse_time_milliseconds": "docnetwork_app_xlsx_parse_time_milliseconds",
                  "docnetwork_imported_registration_successful": "docnetwork_imported_registration_successful",
                  "docnetwork_patient_imported_rows_total": "docnetwork_patient_imported_rows_total",
                  "docnetwork_health_log_route_time_milliseconds": "docnetwork_health_log_route_time_milliseconds",
                  "docnetwork_app_custom_reports_profiles_count": "docnetwork_app_custom_reports_profiles_count",
                  "docnetwork_app_custom_reports_questions_count": "docnetwork_app_custom_reports_questions_count",
                  "docnetwork_app_custom_reports_pdf_count": "docnetwork_app_custom_reports_pdf_count",
                  "docnetwork_app_custom_reports_csv_count": "docnetwork_app_custom_reports_csv_count",
                  "docnetwork_app_custom_reports_include_images_count": "docnetwork_app_custom_reports_include_images_count",
                  "docnetwork_app_custom_reports_include_expired_count": "docnetwork_app_custom_reports_include_expired_count",
                  "docnetwork_profiles_register_failed": "docnetwork_profiles_register_failed",
                  "docnetwork_profiles_register_successful": "docnetwork_profiles_register_successful",
                  "docnetwork_provider_registration_success": "docnetwork_provider_registration_success"
                }
              ],
              "password": "%%env_APP_METRICS_ENDPOINT_PASSWORD%%",
              "username": "user-prometheus",
              "use_legacy_auth_encoding": "true",
              "auth_type": "basic",
              "tags": ["env:prod"]
            }
          ]
      labels:
        app: dn
    spec:
      containers:
      - name: app
        image: 878788551012.dkr.ecr.us-east-1.amazonaws.com/dn-testing-app:2022.0329.0715 # {"$imagescan": "app"}
        imagePullPolicy: "Always"
        env:
        - name: DN_ENVIRONMENT
          value: "development"
        ports:
        - containerPort: 3000
          name: dn-app
        - containerPort: 3001
          name: metrics
        resources:
          requests:
            memory: "1G"
            cpu: ".5"
          limits:
            memory: "4G"
            cpu: "2"
        livenessProbe:
          httpGet:
            path: /healthz
            port: 3000
          initialDelaySeconds: 5
          periodSeconds: 5
          timeoutSeconds: 2
          successThreshold: 1
          failureThreshold: 3
        readinessProbe:
          httpGet:
            scheme: HTTP
            path: /healthz
            port: 3000
          initialDelaySeconds: 10
          periodSeconds: 2
          timeoutSeconds: 2
          successThreshold: 3
          failureThreshold: 1
      serviceAccountName: app
      terminationGracePeriodSeconds: 60 # 1Min - Default is 30 Seconds
      priorityClassName: docnetwork-application
      tolerations:
      - key: "dedicated"
        operator: "Equal"
        value: "dn-prod"
        effect: "NoSchedule"
      affinity:
        nodeAffinity:
          requiredDuringSchedulingIgnoredDuringExecution:
            nodeSelectorTerms:
            - matchExpressions:
              - key: group
                operator: In
                values:
                - app-dedicated

Controller Logs for small batch:

2022-04-07T15:33:26.788Z	INFO	Successfully created the logger.
2022-04-07T15:33:26.788Z	INFO	Logging level set to: debug
{"level":"info","ts":1649345606.8944435,"logger":"fallback","caller":"injection/injection.go:61","msg":"Starting informers..."}
2022-04-07T15:33:26.894Z	INFO	controller	Initializing with version v0.8.1	{"commit": "8280611"}
2022-04-07T15:33:26.894Z	DEBUG	controller.aws	Using AWS region us-east-1	{"commit": "8280611"}
2022-04-07T15:33:26.894Z	DEBUG	controller.aws	Discovered caBundle, length 1066	{"commit": "8280611"}
2022-04-07T15:33:26.894Z	DEBUG	controller.aws.launchtemplate	Hydrating the launch template cache with names matching "Karpenter-dn-main-eks-*"	{"commit": "8280611"}
2022-04-07T15:33:27.184Z	DEBUG	controller.aws.launchtemplate	Finished hydrating the launch template cache with 1 items	{"commit": "8280611"}
I0407 15:33:27.204351       1 leaderelection.go:243] attempting to acquire leader lease karpenter/karpenter-leader-election...
2022-04-07T15:33:27.204Z	INFO	controller	starting metrics server	{"commit": "8280611", "path": "/metrics"}
I0407 15:33:42.786013       1 leaderelection.go:253] successfully acquired lease karpenter/karpenter-leader-election
2022-04-07T15:33:42.786Z	DEBUG	controller.events	Normal	{"commit": "8280611", "object": {"kind":"ConfigMap","namespace":"karpenter","name":"karpenter-leader-election","uid":"73244275-6dfb-416b-8f82-b45e9297c73b","apiVersion":"v1","resourceVersion":"14121116"}, "reason": "LeaderElection", "message": "karpenter-546cf59795-zzcgd_35301933-d7c6-40df-bb5d-51516c8361e8 became leader"}
2022-04-07T15:33:42.786Z	DEBUG	controller.events	Normal	{"commit": "8280611", "object": {"kind":"Lease","namespace":"karpenter","name":"karpenter-leader-election","uid":"6650b7aa-5a39-4696-8162-a5e9f3752a7b","apiVersion":"coordination.k8s.io/v1","resourceVersion":"14121117"}, "reason": "LeaderElection", "message": "karpenter-546cf59795-zzcgd_35301933-d7c6-40df-bb5d-51516c8361e8 became leader"}
2022-04-07T15:33:42.786Z	INFO	controller.controller.counter	Starting EventSource	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.786Z	INFO	controller.controller.counter	Starting EventSource	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.786Z	INFO	controller.controller.counter	Starting Controller	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner"}
2022-04-07T15:33:42.786Z	INFO	controller.controller.provisioning	Starting EventSource	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.786Z	INFO	controller.controller.provisioning	Starting Controller	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner"}
2022-04-07T15:33:42.787Z	INFO	controller.controller.volume	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "PersistentVolumeClaim", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.787Z	INFO	controller.controller.volume	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "PersistentVolumeClaim", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.787Z	INFO	controller.controller.volume	Starting Controller	{"commit": "8280611", "reconciler group": "", "reconciler kind": "PersistentVolumeClaim"}
2022-04-07T15:33:42.787Z	INFO	controller.controller.termination	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.787Z	INFO	controller.controller.termination	Starting Controller	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node"}
2022-04-07T15:33:42.787Z	INFO	controller.controller.node	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.787Z	INFO	controller.controller.node	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.787Z	INFO	controller.controller.node	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.787Z	INFO	controller.controller.node	Starting Controller	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node"}
2022-04-07T15:33:42.787Z	INFO	controller.controller.podmetrics	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Pod", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.787Z	INFO	controller.controller.podmetrics	Starting Controller	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Pod"}
2022-04-07T15:33:42.787Z	INFO	controller.controller.nodemetrics	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.787Z	INFO	controller.controller.nodemetrics	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.787Z	INFO	controller.controller.nodemetrics	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:33:42.787Z	INFO	controller.controller.nodemetrics	Starting Controller	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node"}
2022-04-07T15:33:42.887Z	INFO	controller.controller.counter	Starting workers	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner", "worker count": 10}
2022-04-07T15:33:42.887Z	INFO	controller.controller.provisioning	Starting workers	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner", "worker count": 10}
2022-04-07T15:33:42.907Z	INFO	controller.controller.volume	Starting workers	{"commit": "8280611", "reconciler group": "", "reconciler kind": "PersistentVolumeClaim", "worker count": 1}
2022-04-07T15:33:42.907Z	INFO	controller.controller.termination	Starting workers	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "worker count": 10}
2022-04-07T15:33:42.907Z	INFO	controller.controller.node	Starting workers	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "worker count": 10}
2022-04-07T15:33:42.907Z	INFO	controller.controller.podmetrics	Starting workers	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Pod", "worker count": 1}
2022-04-07T15:33:42.910Z	INFO	controller.controller.nodemetrics	Starting workers	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "worker count": 1}
2022-04-07T15:33:43.683Z	DEBUG	controller.provisioning	Discovered 402 EC2 instance types	{"commit": "8280611", "provisioner": "default"}
2022-04-07T15:33:43.979Z	DEBUG	controller.provisioning	Discovered subnets: [subnet-0537bf15c0a12d36c (us-east-1d) subnet-077a499ddde3c6a0a (us-east-1c) subnet-090dee37fba35334f (us-east-1a)]	{"commit": "8280611", "provisioner": "default"}
2022-04-07T15:33:44.171Z	DEBUG	controller.provisioning	Discovered EC2 instance types zonal offerings	{"commit": "8280611", "provisioner": "default"}
2022-04-07T15:33:44.178Z	INFO	controller.provisioning	Waiting for unschedulable pods	{"commit": "8280611", "provisioner": "default"}
2022-04-07T15:33:44.178Z	INFO	controller.provisioning	Waiting for unschedulable pods	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:34:46.369Z	INFO	controller.provisioning	Batched 2 pods in 1.055290345s	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:34:46.421Z	DEBUG	controller.provisioning	Discovered subnets: [subnet-0537bf15c0a12d36c (us-east-1d) subnet-077a499ddde3c6a0a (us-east-1c) subnet-090dee37fba35334f (us-east-1a)]	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:34:46.882Z	DEBUG	controller.provisioning	Discovered security groups: [sg-031f9ae733fb95e0b]	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:34:46.883Z	DEBUG	controller.provisioning	Discovered kubernetes version 1.21	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:34:46.992Z	DEBUG	controller.provisioning	Discovered ami-0319c884da18af515 for query /aws/service/eks/optimized-ami/1.21/amazon-linux-2/recommended/image_id	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:34:47.036Z	DEBUG	controller.provisioning	Discovered launch template Karpenter-dn-main-eks-10790469361113335367	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:34:50.165Z	INFO	controller.provisioning	Launched instance: i-0b9bdd13281a2bc94, hostname: ip-10-4-80-129.ec2.internal, type: t3.medium, zone: us-east-1a, capacityType: spot	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:34:50.174Z	INFO	controller.provisioning	Created node with 2 pods requesting {"cpu":"1410m","memory":"2086245Ki","pods":"7"} from types c3.large, c4.large, c5a.large, t3.medium, t3a.medium and 306 other(s)	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:34:50.194Z	INFO	controller.provisioning	Waiting for unschedulable pods	{"commit": "8280611", "provisioner": "docnetwork-app"}
@mmclane mmclane added the bug Something isn't working label Apr 7, 2022
@mmclane
Copy link
Author

mmclane commented Apr 7, 2022

Controller log from large batch

2022-04-07T15:46:24.413Z	INFO	Successfully created the logger.
2022-04-07T15:46:24.413Z	INFO	Logging level set to: debug
{"level":"info","ts":1649346384.5195777,"logger":"fallback","caller":"injection/injection.go:61","msg":"Starting informers..."}
2022-04-07T15:46:24.519Z	INFO	controller	Initializing with version v0.8.1	{"commit": "8280611"}
2022-04-07T15:46:24.519Z	DEBUG	controller.aws	Using AWS region us-east-1	{"commit": "8280611"}
2022-04-07T15:46:24.519Z	DEBUG	controller.aws	Discovered caBundle, length 1066	{"commit": "8280611"}
2022-04-07T15:46:24.519Z	DEBUG	controller.aws.launchtemplate	Hydrating the launch template cache with names matching "Karpenter-dn-main-eks-*"	{"commit": "8280611"}
2022-04-07T15:46:24.867Z	DEBUG	controller.aws.launchtemplate	Finished hydrating the launch template cache with 0 items	{"commit": "8280611"}
2022-04-07T15:46:24.889Z	INFO	controller	starting metrics server	{"commit": "8280611", "path": "/metrics"}
I0407 15:46:24.989486       1 leaderelection.go:243] attempting to acquire leader lease karpenter/karpenter-leader-election...
I0407 15:46:40.659191       1 leaderelection.go:253] successfully acquired lease karpenter/karpenter-leader-election
2022-04-07T15:46:40.659Z	DEBUG	controller.events	Normal	{"commit": "8280611", "object": {"kind":"ConfigMap","namespace":"karpenter","name":"karpenter-leader-election","uid":"73244275-6dfb-416b-8f82-b45e9297c73b","apiVersion":"v1","resourceVersion":"14127112"}, "reason": "LeaderElection", "message": "karpenter-546cf59795-ppglk_24529b08-28fd-4096-8159-b39045134f28 became leader"}
2022-04-07T15:46:40.659Z	DEBUG	controller.events	Normal	{"commit": "8280611", "object": {"kind":"Lease","namespace":"karpenter","name":"karpenter-leader-election","uid":"6650b7aa-5a39-4696-8162-a5e9f3752a7b","apiVersion":"coordination.k8s.io/v1","resourceVersion":"14127113"}, "reason": "LeaderElection", "message": "karpenter-546cf59795-ppglk_24529b08-28fd-4096-8159-b39045134f28 became leader"}
2022-04-07T15:46:40.659Z	INFO	controller.controller.counter	Starting EventSource	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.659Z	INFO	controller.controller.counter	Starting EventSource	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.659Z	INFO	controller.controller.counter	Starting Controller	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner"}
2022-04-07T15:46:40.659Z	INFO	controller.controller.provisioning	Starting EventSource	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.659Z	INFO	controller.controller.provisioning	Starting Controller	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner"}
2022-04-07T15:46:40.660Z	INFO	controller.controller.volume	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "PersistentVolumeClaim", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.660Z	INFO	controller.controller.volume	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "PersistentVolumeClaim", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.660Z	INFO	controller.controller.volume	Starting Controller	{"commit": "8280611", "reconciler group": "", "reconciler kind": "PersistentVolumeClaim"}
2022-04-07T15:46:40.660Z	INFO	controller.controller.termination	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.660Z	INFO	controller.controller.termination	Starting Controller	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node"}
2022-04-07T15:46:40.660Z	INFO	controller.controller.node	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.660Z	INFO	controller.controller.node	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.660Z	INFO	controller.controller.node	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.660Z	INFO	controller.controller.node	Starting Controller	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node"}
2022-04-07T15:46:40.660Z	INFO	controller.controller.podmetrics	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Pod", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.660Z	INFO	controller.controller.podmetrics	Starting Controller	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Pod"}
2022-04-07T15:46:40.660Z	INFO	controller.controller.nodemetrics	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.660Z	INFO	controller.controller.nodemetrics	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.660Z	INFO	controller.controller.nodemetrics	Starting EventSource	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "source": "kind source: /, Kind="}
2022-04-07T15:46:40.660Z	INFO	controller.controller.nodemetrics	Starting Controller	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node"}
2022-04-07T15:46:40.760Z	INFO	controller.controller.provisioning	Starting workers	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner", "worker count": 10}
2022-04-07T15:46:40.782Z	INFO	controller.controller.counter	Starting workers	{"commit": "8280611", "reconciler group": "karpenter.sh", "reconciler kind": "Provisioner", "worker count": 10}
2022-04-07T15:46:40.782Z	INFO	controller.controller.termination	Starting workers	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "worker count": 10}
2022-04-07T15:46:40.782Z	INFO	controller.controller.volume	Starting workers	{"commit": "8280611", "reconciler group": "", "reconciler kind": "PersistentVolumeClaim", "worker count": 1}
2022-04-07T15:46:40.782Z	INFO	controller.controller.node	Starting workers	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "worker count": 10}
2022-04-07T15:46:40.783Z	INFO	controller.controller.podmetrics	Starting workers	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Pod", "worker count": 1}
2022-04-07T15:46:40.786Z	INFO	controller.controller.nodemetrics	Starting workers	{"commit": "8280611", "reconciler group": "", "reconciler kind": "Node", "worker count": 1}
2022-04-07T15:46:41.569Z	DEBUG	controller.provisioning	Discovered 402 EC2 instance types	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:46:41.681Z	DEBUG	controller.provisioning	Discovered subnets: [subnet-0537bf15c0a12d36c (us-east-1d) subnet-077a499ddde3c6a0a (us-east-1c) subnet-090dee37fba35334f (us-east-1a)]	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:46:41.889Z	DEBUG	controller.provisioning	Discovered EC2 instance types zonal offerings	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:46:41.894Z	INFO	controller.provisioning	Waiting for unschedulable pods	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:46:41.894Z	INFO	controller.provisioning	Waiting for unschedulable pods	{"commit": "8280611", "provisioner": "default"}
2022-04-07T15:48:03.072Z	INFO	controller.provisioning	Batched 8 pods in 1.321965397s	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:48:03.160Z	DEBUG	controller.provisioning	Discovered subnets: [subnet-0537bf15c0a12d36c (us-east-1d) subnet-077a499ddde3c6a0a (us-east-1c) subnet-090dee37fba35334f (us-east-1a)]	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:48:03.584Z	DEBUG	controller.provisioning	Discovered security groups: [sg-031f9ae733fb95e0b]	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:48:03.586Z	DEBUG	controller.provisioning	Discovered kubernetes version 1.21	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:48:03.650Z	DEBUG	controller.provisioning	Discovered ami-0319c884da18af515 for query /aws/service/eks/optimized-ami/1.21/amazon-linux-2/recommended/image_id	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:48:03.843Z	DEBUG	controller.provisioning	Created launch template, Karpenter-dn-main-eks-10790469361113335367	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:48:07.823Z	INFO	controller.provisioning	Launched instance: i-0c6f420d3d1375f03, hostname: ip-10-4-249-128.ec2.internal, type: t3.2xlarge, zone: us-east-1d, capacityType: spot	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:48:07.834Z	INFO	controller.provisioning	Created node with 8 pods requesting {"cpu":"5010m","memory":"8068500Ki","pods":"13"} from types c3.2xlarge, c4.2xlarge, c6i.2xlarge, c5d.2xlarge, c5a.2xlarge and 224 other(s)	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:48:07.857Z	INFO	controller.provisioning	Waiting for unschedulable pods	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:51:42.634Z	DEBUG	controller.provisioning	Discovered 402 EC2 instance types	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:51:42.775Z	DEBUG	controller.provisioning	Discovered subnets: [subnet-0537bf15c0a12d36c (us-east-1d) subnet-077a499ddde3c6a0a (us-east-1c) subnet-090dee37fba35334f (us-east-1a)]	{"commit": "8280611", "provisioner": "docnetwork-app"}
2022-04-07T15:51:42.949Z	DEBUG	controller.provisioning	Discovered EC2 instance types zonal offerings	{"commit": "8280611", "provisioner": "docnetwork-app"}

@dewjam
Copy link
Contributor

dewjam commented Apr 13, 2022

Hello @mmclane !
My apologies for the delay. I'm working on reproducing this issue locally. I'll give an update once I've given it a try.

@mmclane
Copy link
Author

mmclane commented Apr 13, 2022

Great to hear that someone is looking into it. Let me know if I can help. I am also available on the Kubernetes slack

@dewjam
Copy link
Contributor

dewjam commented Apr 13, 2022

So far I've been unable to reproduce this problem. Can you clarify your timings from above? Does it seem that in each test you're waiting for the CNI plugin to start?

Would you be willing to share the "events" output for a pod that is taking a long time to start?

kubectl get event -n <namespace> --field-selector involvedObject.name=<pod_name>

@dewjam
Copy link
Contributor

dewjam commented Apr 13, 2022

Does it seem that in each test you're waiting for the CNI plugin to start?

You can disregard this question. I guess I missed your comment from above: "During this time the pods report that they are waiting on the CNI to be available but that only takes 30s after the node is ready."

Events would still be helpful to look at, though.

@dewjam
Copy link
Contributor

dewjam commented Apr 13, 2022

Could you also share logs from the aws-node pod on an impacted node?

@dewjam dewjam self-assigned this Apr 15, 2022
@mmclane
Copy link
Author

mmclane commented Apr 15, 2022 •
edited
Loading

Node took 87s to be ready. Logs from aws-node pod on new node. This is up and running right away.

{"level":"info","ts":"2022-04-11T14:18:55.479Z","caller":"entrypoint.sh","msg":"Validating env variables ..."}
{"level":"info","ts":"2022-04-11T14:18:55.480Z","caller":"entrypoint.sh","msg":"Install CNI binaries.."}
{"level":"info","ts":"2022-04-11T14:18:55.492Z","caller":"entrypoint.sh","msg":"Starting IPAM daemon in the background ... "}
{"level":"info","ts":"2022-04-11T14:18:55.496Z","caller":"entrypoint.sh","msg":"Checking for IPAM connectivity ... "}
I0411 14:18:56.575837      13 request.go:621] Throttling request took 1.046489702s, request: GET:https://172.20.0.1:443/apis/flowcontrol.apiserver.k8s.io/v1beta1?timeout=32s
{"level":"info","ts":"2022-04-11T14:18:57.506Z","caller":"entrypoint.sh","msg":"Retrying waiting for IPAM-D"}
{"level":"info","ts":"2022-04-11T14:18:59.513Z","caller":"entrypoint.sh","msg":"Retrying waiting for IPAM-D"}
{"level":"info","ts":"2022-04-11T14:19:01.519Z","caller":"entrypoint.sh","msg":"Retrying waiting for IPAM-D"}
{"level":"info","ts":"2022-04-11T14:19:01.535Z","caller":"entrypoint.sh","msg":"Copying config file ... "}
{"level":"info","ts":"2022-04-11T14:19:01.538Z","caller":"entrypoint.sh","msg":"Successfully copied CNI plugin binary and config file."}
{"level":"info","ts":"2022-04-11T14:19:01.539Z","caller":"entrypoint.sh","msg":"Foregrounding IPAM daemon ..."}

@mmclane
Copy link
Author

mmclane commented Apr 15, 2022

Pods took ~ 8m30s

Events:

LAST SEEN   TYPE      REASON                 OBJECT                    MESSAGE
8m54s       Warning   FailedScheduling       pod/app-9c97974f6-2cxqt   0/3 nodes are available: 1 Insufficient cpu, 1 Insufficient memory, 2 node(s) didn't match Pod's node affinity/selector.
8m51s       Warning   FailedScheduling       pod/app-9c97974f6-2cxqt   0/4 nodes are available: 1 Insufficient cpu, 1 Insufficient memory, 1 node(s) had taint {karpenter.sh/not-ready: }, that the pod didn't tolerate, 2 node(s) didn't match Pod's node affinity/selector.
7m28s       Warning   NetworkNotReady        pod/app-9c97974f6-2cxqt   network is not ready: container runtime network not ready: NetworkReady=false reason:NetworkPluginNotReady message:Network plugin returns error: cni plugin not initialized
7m26s       Normal    Pulling                pod/app-9c97974f6-2cxqt   Pulling image "cr.l5d.io/linkerd/proxy-init:v1.4.0"
7m25s       Normal    TaintManagerEviction   pod/app-9c97974f6-2cxqt   Cancelling deletion of Pod prod/app-9c97974f6-2cxqt
6m55s       Normal    Pulled                 pod/app-9c97974f6-2cxqt   Successfully pulled image "cr.l5d.io/linkerd/proxy-init:v1.4.0" in 30.593531448s
6m53s       Normal    Created                pod/app-9c97974f6-2cxqt   Created container linkerd-init
6m52s       Normal    Started                pod/app-9c97974f6-2cxqt   Started container linkerd-init
6m51s       Normal    Pulling                pod/app-9c97974f6-2cxqt   Pulling image "cr.l5d.io/linkerd/proxy:stable-2.11.1"
5m59s       Normal    Pulled                 pod/app-9c97974f6-2cxqt   Successfully pulled image "cr.l5d.io/linkerd/proxy:stable-2.11.1" in 52.462248603s
5m59s       Normal    Created                pod/app-9c97974f6-2cxqt   Created container linkerd-proxy
5m58s       Normal    Started                pod/app-9c97974f6-2cxqt   Started container linkerd-proxy
5m58s       Normal    Pulling                pod/app-9c97974f6-2cxqt   Pulling image "878788551012.dkr.ecr.us-east-1.amazonaws.com/dn-testing-app:2022.0329.0715"
115s        Normal    Pulled                 pod/app-9c97974f6-2cxqt   Successfully pulled image "878788551012.dkr.ecr.us-east-1.amazonaws.com/dn-testing-app:2022.0329.0715" in 4m3.47123835s
68s         Normal    Created                pod/app-9c97974f6-2cxqt   Created container app

@tzneal
Copy link
Contributor

tzneal commented Apr 15, 2022

Does that image normally take 4m to pull?

115s        Normal    Pulled                 pod/app-9c97974f6-2cxqt   Successfully pulled image "878788551012.dkr.ecr.us-east-1.amazonaws.com/dn-testing-app:2022.0329.0715" in 4m3.47123835s

@mmclane
Copy link
Author

mmclane commented Apr 18, 2022

So this morning I ran tested this. I had 6 pods running on my cluster (the number that can fit on my existing node and then added 1 more so that it would spin up a new node with only one pod. Here is the time it took to pull the image

Successfully pulled image "878788551012.dkr.ecr.us-east-1.amazonaws.com/dn-testing-app:2
022.0329.0715" in 48.377005281s

So... my question is this. Is k8s trying to pull the same image multiple times when a new node comes up and thus running into issues or something?

@mmclane
Copy link
Author

mmclane commented Apr 18, 2022

Here is the full event listing

AST SEEN   TYPE      REASON                 OBJECT                    MESSAGE
8m8s        Warning   FailedScheduling       pod/app-9c97974f6-7tf78   0/3 nodes are available: 1 Insufficient cpu, 1 Insufficient memory, 2 node(s) didn't mat
ch Pod's node affinity/selector.
8m5s        Warning   FailedScheduling       pod/app-9c97974f6-7tf78   0/4 nodes are available: 1 Insufficient cpu, 1 Insufficient memory, 1 node(s) had taint
{karpenter.sh/not-ready: }, that the pod didn't tolerate, 2 node(s) didn't match Pod's node affinity/selector.
6m43s       Warning   NetworkNotReady        pod/app-9c97974f6-7tf78   network is not ready: container runtime network not ready: NetworkReady=false reason:Net
workPluginNotReady message:Network plugin returns error: cni plugin not initialized
6m40s       Normal    Pulling                pod/app-9c97974f6-7tf78   Pulling image "cr.l5d.io/linkerd/proxy-init:v1.4.0"
6m38s       Normal    Pulled                 pod/app-9c97974f6-7tf78   Successfully pulled image "cr.l5d.io/linkerd/proxy-init:v1.4.0" in 1.936802978s
6m38s       Normal    Created                pod/app-9c97974f6-7tf78   Created container linkerd-init
6m38s       Normal    Started                pod/app-9c97974f6-7tf78   Started container linkerd-init
6m37s       Normal    Pulling                pod/app-9c97974f6-7tf78   Pulling image "cr.l5d.io/linkerd/proxy:stable-2.11.1"
6m37s       Normal    TaintManagerEviction   pod/app-9c97974f6-7tf78   Cancelling deletion of Pod prod/app-9c97974f6-7tf78
6m33s       Normal    Pulled                 pod/app-9c97974f6-7tf78   Successfully pulled image "cr.l5d.io/linkerd/proxy:stable-2.11.1" in 3.899836124s
6m28s       Normal    Created                pod/app-9c97974f6-7tf78   Created container linkerd-proxy
6m28s       Normal    Started                pod/app-9c97974f6-7tf78   Started container linkerd-proxy
6m28s       Normal    Pulling                pod/app-9c97974f6-7tf78   Pulling image "878788551012.dkr.ecr.us-east-1.amazonaws.com/dn-testing-app:2022.0329.071
5"
5m40s       Normal    Pulled                 pod/app-9c97974f6-7tf78   Successfully pulled image "878788551012.dkr.ecr.us-east-1.amazonaws.com/dn-testing-app:2
022.0329.0715" in 48.377005281s

Its worth noting that it took a LOT less time for the linkerd images to get pulled too.

@dewjam
Copy link
Contributor

dewjam commented Apr 18, 2022

Hey @mmclane . The image pull policy for your "app" container is set to Always. My understanding is this will still use images cached on the node if the digest matches. But maybe you want to test with IfNotPresent to see if you see a different behavior.

- name: app
        image: 878788551012.dkr.ecr.us-east-1.amazonaws.com/dn-testing-app:2022.0329.0715 # {"$imagescan": "app"}
        imagePullPolicy: "Always"

@mmclane
Copy link
Author

mmclane commented Apr 18, 2022

I thought of that and changed it but it didn't seem to make a difference.

@dewjam
Copy link
Contributor

dewjam commented Apr 18, 2022

Out of curiosity, I noticed this in your image line: # {"$imagescan": "app"}. Are you using something like Fleet by chance? (https://fleet.rancher.io/imagescan/)

I'm not familiar with imagescan, but could this be a contributing factor?

@mmclane
Copy link
Author

mmclane commented Apr 18, 2022

Yep, that is exactly what that is for.

@dewjam
Copy link
Contributor

dewjam commented Apr 18, 2022

OK, just reading about Imagescan a bit more and it seems this is just a method to populate manifests with most recent image:tag. Shouldn't be related to pull performance.

@mmclane
Copy link
Author

mmclane commented Apr 18, 2022

It shouldn't be related. It just updates the manifest in git for us.

@dewjam
Copy link
Contributor

dewjam commented Apr 19, 2022

Hey @mmclane . Updating the issue per our findings while working together through Slack.

It seems the container-runtime in use is related to this problem. When we force new Karpenter nodes to use dockerd instead of containerd via Launch Template, it seems image pull performance is back to what is expected.

Going to try to reproduce this directly through containerd to see if there is a difference.

@mmclane
Copy link
Author

mmclane commented Apr 19, 2022 •
edited
Loading

Events for node on karpenter provisioned node that is running docker instead of containerd. Not that 5 other pods were launching at the same time. This is in contrast to the 4 minutes it takes to pull the images with containerd.

Every 2.0s: kubectl get event -n prod --field-selector involvedObject.name=app-9c97974f6-whsst                                                                                       pop-os: Tue Apr 19 13:31:48 2022

LAST SEEN   TYPE      REASON                 OBJECT                    MESSAGE
16m         Warning   FailedScheduling       pod/app-9c97974f6-whsst   0/3 nodes are available: 1 Insufficient cpu, 1 Insufficient memory, 2 node(s) didn't match Pod's node affinity/selector.
14m         Warning   NetworkNotReady        pod/app-9c97974f6-whsst   network is not ready: container runtime network not ready: NetworkReady=false reason:NetworkPluginNotReady message:docker: network plugin is n
ot ready: cni config uninitialized
14m         Normal    Pulling                pod/app-9c97974f6-whsst   Pulling image "cr.l5d.io/linkerd/proxy-init:v1.4.0"
14m         Normal    Pulled                 pod/app-9c97974f6-whsst   Successfully pulled image "cr.l5d.io/linkerd/proxy-init:v1.4.0" in 4.141231616s
14m         Normal    Created                pod/app-9c97974f6-whsst   Created container linkerd-init
14m         Normal    Started                pod/app-9c97974f6-whsst   Started container linkerd-init
14m         Normal    TaintManagerEviction   pod/app-9c97974f6-whsst   Cancelling deletion of Pod prod/app-9c97974f6-whsst
14m         Normal    Pulling                pod/app-9c97974f6-whsst   Pulling image "cr.l5d.io/linkerd/proxy:stable-2.11.1"
14m         Normal    Pulled                 pod/app-9c97974f6-whsst   Successfully pulled image "cr.l5d.io/linkerd/proxy:stable-2.11.1" in 6.489569176s
14m         Normal    Created                pod/app-9c97974f6-whsst   Created container linkerd-proxy
14m         Normal    Started                pod/app-9c97974f6-whsst   Started container linkerd-proxy
14m         Normal    Pulling                pod/app-9c97974f6-whsst   Pulling image "878788551012.dkr.ecr.us-east-1.amazonaws.com/dn-testing-app:2022.0329.0715"
13m         Normal    Pulled                 pod/app-9c97974f6-whsst   Successfully pulled image "878788551012.dkr.ecr.us-east-1.amazonaws.com/dn-testing-app:2022.0329.0715" in 39.391891667s
13m         Normal    Created                pod/app-9c97974f6-whsst   Created container app

Nodes:

NAME                          STATUS   ROLES    AGE    VERSION               INTERNAL-IP   EXTERNAL-IP   OS-IMAGE         KERNEL-VERSION                CONTAINER-RUNTIME
ip-10-4-147-11.ec2.internal   Ready    <none>   8d     v1.21.5-eks-9017834   10.4.147.11   <none>        Amazon Linux 2   5.4.181-99.354.amzn2.x86_64   docker://20.10.13
ip-10-4-217-60.ec2.internal   Ready    <none>   8d     v1.21.5-eks-9017834   10.4.217.60   <none>        Amazon Linux 2   5.4.181-99.354.amzn2.x86_64   docker://20.10.13
ip-10-4-78-27.ec2.internal    Ready    <none>   133m   v1.21.5-eks-9017834   10.4.78.27    <none>        Amazon Linux 2   5.4.181-99.354.amzn2.x86_64   docker://20.10.13
ip-10-4-94-187.ec2.internal   Ready    <none>   18m    v1.21.5-eks-9017834   10.4.94.187   <none>        Amazon Linux 2   5.4.181-99.354.amzn2.x86_64   docker://20.10.13

@dewjam
Copy link
Contributor

dewjam commented Apr 19, 2022

Seems like this PR is related to our problem with containerd: containerd/containerd#6702

@dewjam
Copy link
Contributor

dewjam commented Apr 22, 2022

I did some testing and found that the PR mentioned above improves containerd image pull performance considerably when merged into the release/1.5 branch. As such, I'm planning to cut a PR to back-port the fix to containerd-1.5.x.

The issue manifests when many pods are scheduled on a single node at one time which all use the same image. In my testing I was able to reproduce the problem with containerd-1.4.13 and containerd-1.5.11 by launching 20 pods that all used the same 250MB image (golang:latest). I then patched 1.5.11 with the code in containerd/containerd#6702 and found image pull times reduced from ~3 minutes to under 30 seconds in most cases.

Below is an example of the difference in image pull times from the versions tested.

containerd-1.4.13 (3 minutes and 12 seconds)

Events:
  Type     Reason            Age                     From               Message
  ----     ------            ----                    ----               -------
  Warning  FailedScheduling  5m35s (x2 over 5m37s)   default-scheduler  0/21 nodes are available: 1 Insufficient cpu, 20 node(s) were unschedulable.
  Warning  NetworkNotReady   4m39s (x10 over 4m56s)  kubelet            network is not ready: container runtime network not ready: NetworkReady=false reason:NetworkPluginNotReady message:Network plugin returns error: cni plugin not initialized
  Normal   Pulling           4m36s                   kubelet            Pulling image "golang:latest"
  Normal   Pulled            83s                     kubelet            Successfully pulled image "golang:latest" in 3m12.933600501s

containerd-1.5.11 (3 minutes and 26 seconds)

Events:
  Type     Reason            Age                    From               Message
  ----     ------            ----                   ----               -------
  Warning  FailedScheduling  6m12s                  default-scheduler  0/22 nodes are available: 1 Insufficient cpu, 21 node(s) were unschedulable.
  Warning  FailedScheduling  6m10s                  default-scheduler  0/21 nodes are available: 1 Insufficient cpu, 20 node(s) were unschedulable.
  Warning  NetworkNotReady   5m35s                  kubelet            network is not ready: container runtime network not ready: NetworkReady=false reason:NetworkPluginNotReady message:Network plugin returns error: cni plugin not initialized
  Warning  NetworkNotReady   5m9s (x10 over 5m27s)  kubelet            network is not ready: container runtime network not ready: NetworkReady=false reason:NetworkPluginNotReady message:Network plugin returns error: cni plugin not initialized
  Normal   Pulling           5m5s                   kubelet            Pulling image "golang:latest"
  Normal   Pulled            99s                    kubelet            Successfully pulled image "golang:latest" in 3m26.167261141s

containerd-1.5.11-patched (17 seconds)

Events:
  Type     Reason            Age                    From               Message
  ----     ------            ----                   ----               -------
  Warning  FailedScheduling  4m7s                   default-scheduler  0/22 nodes are available: 1 Insufficient cpu, 21 node(s) were unschedulable.
  Warning  FailedScheduling  4m6s                   default-scheduler  0/21 nodes are available: 1 Insufficient cpu, 20 node(s) were unschedulable.
  Warning  NetworkNotReady   3m31s                  kubelet            network is not ready: container runtime network not ready: NetworkReady=false reason:NetworkPluginNotReady message:Network plugin returns error: cni plugin not initialized
  Warning  NetworkNotReady   3m2s (x10 over 3m21s)  kubelet            network is not ready: container runtime network not ready: NetworkReady=false reason:NetworkPluginNotReady message:Network plugin returns error: cni plugin not initialized
  Normal   Pulling           2m59s                  kubelet            Pulling image "golang:latest"
  Normal   Pulled            2m42s                  kubelet            Successfully pulled image "golang:latest" in 17.294089574s

@dewjam dewjam mentioned this issue Apr 22, 2022
Closed
@dewjam
Copy link
Contributor

dewjam commented May 10, 2022

The PR to back port the image pull performance fix to containerd-1.5.x was denied. The fix was included in containerd-1.6.4, however, which I've briefly tested alongside k8s 1.21+. I do not have a timeline for when containerd-1.6.x will built into the EKS Optimized AL2 image.

There are a few possible workarounds to the improve image pull performance in the meantime:

  1. Revert to Docker
    The Docker container-runtime seems to be immune to the image pull performance issue. Docker is the default container-runtime used by the EKS optimized image and is well tested as a result. Karpenter defaults to using containerd when launching nodes, but it's possible to create a custom launch template and remove the --container-runtime containerd flag, which will revert back to docker.

  2. Supply the --serialize-image-pulls=true' flag to Kubelet
    This flag is set to "true" by default by Kubelet, but is set to "false" in the EKS Optimized image. You can override the kubelet config by supplying the --serialize-image-pulls=true' flag in a custom launch template.
    Note: Setting the value to "true" could degrade image pull performance in the case where many pods are launched from many different images.

  3. Install containerd-1.6.4 in place of containerd-1.4.13
    Containerd 1.6.4 contains the fix which improves image pull performance. It's certainly possible to install 1.6.4 on nodes through a custom launch template, or by building a custom AMI. I highly recommend that this configuration be tested thoroughly before being used for production workloads.

@github-actions
Copy link
Contributor

Labeled for closure due to inactivity in 10 days.

@tzneal tzneal added the roadmap We're thinking about next steps label Jun 15, 2022
@universam1
Copy link

@tzneal could the flag serialize-image-pulls be added to say kubeletConfig.serializeImagePulls to make that configurable? Sounds like 1.6 release of containerd will not be available in AL2 for mid term.

@dewjam
Copy link
Contributor

dewjam commented Sep 12, 2022

The most recent version of the EKS Optimized AL2 image upgraded to Containerd 1.6.6 (https://github.com/awslabs/amazon-eks-ami/releases/tag/v20220824). Issues with slow pod startup times should now be resolved.

I'm going to go ahead and close out this issue. Feel free to reopen if need be. Thanks!

@dewjam dewjam closed this as completed Sep 12, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dewjam dewjam

Labels
bug Something isn't working roadmap We're thinking about next steps
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@tzneal @dewjam @universam1 @mmclane