Skip to content

Image pull speed is throttled by unknown source #8160

Open
Bug
Open
Image pull speed is throttled by unknown source#8160
Bug
Labels
kind/performancestatus/needs-validation
@howespt

Description

@howespt
howespt
opened on Feb 24, 2023

Description

I have set up a cache between my kubernetes cluster and the registries it pulls from. I've set it up using the HTTPS_PROXY environment variable, so all fetch requests for images are proxied through the cache. The caching layer is designed for high throughput as I've seen that various registries are quite slow to pull from (eg ECR). The problem is that containerd image fetching appears to throttle layer downloads on a max-bandwidth-per-layer level. Through fetching multiple layers concurrently I can see that it is not (on aggregate) network bound, and disk io tests suggest it is neither that. Some numbers for comparison:

  • Fetching from a registry and missing the cache: ~25MB/s per layer (limited by registry bandwidth)
  • Fetching from a registry and hitting the cache: ~130MB/s
  • curling the cache from the same node: ~2400MB/s
  • simple go http Client fetch (trying to emulate containerd's fetching) ~2000MB/s

I should note that the page caches are cleared between these calls (sudo sysctl vm.drop_caches=3)

Steps to reproduce the issue

Somewhat difficult as it requires setting up a proxy caching server

  1. Set up cluster (mine is EKS but can't see how it is related in this case)
  2. Set up proxy cache server (in my case using nginx)
  3. Pull images through proxy to populate the cache, eg HTTPS_PROXY=proxy-host ctr --debug -n k8s.io i pull example.com/test-image:image-tag
  4. Delete images.content and re-pull, time the fetches from debug logs or otherwise
  5. use curl or a attached go module to fetch from cache, note much larger speedup: eg time curl https://proxy-host/v2/test-image/blobs/sha256:<layer_hash> or time ./fetch below.

Describe the results you received and expected

Received results

In the below, the layer with sha256:3ad6e87f8575e89056a7679aa09fc1f7842098633816fce6209e2a3cc008267d is roughly 4GB.

# time HTTPS_PROXY=proxy-host ctr --debug -n k8s.io i pull XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com/test-image:image-tag
DEBU[0000] fetching                                      image="XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com/test-image:image-tag"
DEBU[0000] resolving                                     host=XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com
DEBU[0000] do request                                    host=XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent=containerd/1.6.6 request.method=HEAD url="https://XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com/v2/test-image/manifests/image-tag"
DEBU[0000] fetch response received                       host=XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com response.header.accept-ranges=bytes response.header.connection=keep-alive response.header.content-length=3681 response.header.content-type=application/vnd.docker.distribution.manifest.v2+json response.header.date="Fri, 24 Feb 2023 03:58:50 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.server=nginx/1.18.0 response.header.sizes= response.header.x-proxy-cache-status=MISS response.status="200 OK" url="https://XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com/v2/test-image/manifests/image-tag"
DEBU[0000] no Docker-Content-Digest header, fetching manifest instead  host=XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com
DEBU[0000] do request                                    host=XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent=containerd/1.6.6 request.method=GET url="https://XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com/v2/test-image/manifests/image-tag"
DEBU[0000] fetch response received                       host=XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com response.header.accept-ranges=bytes response.header.connection=keep-alive response.header.content-length=3681 response.header.content-type=application/vnd.docker.distribution.manifest.v2+json response.header.date="Fri, 24 Feb 2023 03:58:50 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.server=nginx/1.18.0 response.header.sizes= response.header.x-proxy-cache-status=MISS response.status="200 OK" url="https://XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com/v2/test-image/manifests/image-tag"
DEBU[0000] resolved                                      desc.digest="sha256:2ecd342040766f880cfc8a6e087f1112f7231b5df2a96a5565781d5e1b59a0ed" host=XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com
DEBU[0000] fetch                                         digest="sha256:3ad6e87f8575e89056a7679aa09fc1f7842098633816fce6209e2a3cc008267d" mediatype=application/vnd.docker.image.rootfs.diff.tar.gzip size=4019514690
DEBU[0000] do request                                    digest="sha256:3ad6e87f8575e89056a7679aa09fc1f7842098633816fce6209e2a3cc008267d" mediatype=application/vnd.docker.image.rootfs.diff.tar.gzip request.header.accept="application/vnd.docker.image.rootfs.diff.tar.gzip, */*" request.header.user-agent=containerd/1.6.6 request.method=GET size=4019514690 url="https://XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com/v2/test-image/blobs/sha256:3ad6e87f8575e89056a7679aa09fc1f7842098633816fce6209e2a3cc008267d"
DEBU[0000] fetch response received                       digest="sha256:3ad6e87f8575e89056a7679aa09fc1f7842098633816fce6209e2a3cc008267d" mediatype=application/vnd.docker.image.rootfs.diff.tar.gzip response.header.accept-ranges=bytes response.header.connection=keep-alive response.header.content-length=4019514690 response.header.content-type=application/octet-stream response.header.date="Fri, 24 Feb 2023 03:58:50 GMT" response.header.etag="\"07a14bbfe73c04ee576ddbd5372b6500-767\"" response.header.last-modified="Tue, 14 Feb 2023 19:48:32 GMT" response.header.server=nginx/1.18.0 response.header.x-amz-id-2="DPZrqEb46n+/olVHCUckMdbbcL9FXpG8CAzx7A5Y3aOu+9+a61hitefeL4rHPexpQjAp/r5lcPw=" response.header.x-amz-request-id=Y2EZ1XRYVJ69NK1Y response.header.x-amz-server-side-encryption=AES256 response.header.x-amz-version-id=9oX5ZUQd2Sr28yb1WqCbF1ruI4NPkawa response.header.x-proxy-cache-status=HIT response.status="200 OK" size=4019514690 url="https://XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com/v2/test-image/blobs/sha256:3ad6e87f8575e89056a7679aa09fc1f7842098633816fce6209e2a3cc008267d"
DEBU[0048] unpacking                                     image="XXXXXXXXXXX.dkr.ecr.us-west-2.amazonaws.com/test-image:image-tag"
unpacking linux/amd64 sha256:2ecd342040766f880cfc8a6e087f1112f7231b5df2a96a5565781d5e1b59a0ed...
done: 8.174509ms

real	0m48.676s
user	0m6.289s
sys	0m2.821s

# note the response.header.x-proxy-cache-status=HIT, we are pulling from the cache, not the upstream

# time curl https://proxy-host/v2/test-image/blobs/sha256:3ad6e87f8575e89056a7679aa09fc1f7842098633816fce6209e2a3cc008267d -o blob.tar.gz
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 3833M  100 3833M    0     0  2411M      0  0:00:01  0:00:01 --:--:-- 2412M

real	0m1.594s
user	0m0.056s
sys	0m1.537s


# time ./fetch
File successfully fetched and saved

real	0m2.964s
user	0m0.953s
sys	0m2.071s

fetch is defined by

package main

import (
	"crypto/tls"
	"fmt"
	"io"
	"net/http"
	"os"
)

func main() {

	tr := &http.Transport{
		TLSClientConfig: &tls.Config{InsecureSkipVerify: true},
	}
	client := &http.Client{Transport: tr}

	url := "https://proxy-host/v2/test-image/blobs/sha256:3ad6e87f8575e89056a7679aa09fc1f7842098633816fce6209e2a3cc008267d"

	resp, err := client.Get(url)
	if err != nil {
		fmt.Println("Error:", err)
		return
	}
	defer resp.Body.Close()

	file, err := os.Create("blob.tar.gz")
	if err != nil {
		fmt.Println("Error:", err)
		return
	}
	defer file.Close()

	_, err = io.Copy(file, resp.Body)
	if err != nil {
		fmt.Println("Error:", err)
		return
	}

	fmt.Println("File successfully fetched and saved")
}

Expected results

Given that the go program attached is in essence what containerd is doing in func (r dockerFetcher) Fetch (though much simpler and I may very well has missed something as I attempted to sift through the code path), I would expect that the layer download would be approximately the same speed (ie ~2GB/s).

Extra info

I've tested with various other scenarios: different node types, local and non-local to the caching node, different pulling clients (crictl and nerdctl), as well as creating pods and watching the pull via k8s events. I've tried different storage for containerd root (node-local nvme, different AWS storage classes).

What version of containerd are you using?

1.6.6 10c1295

Any other relevant information

{
  "status": {
    "conditions": [
      {
        "type": "RuntimeReady",
        "status": true,
        "reason": "",
        "message": ""
      },
      {
        "type": "NetworkReady",
        "status": true,
        "reason": "",
        "message": ""
      }
    ]
  },
  "cniconfig": {
    "PluginDirs": [
      "/opt/cni/bin"
    ],
    "PluginConfDir": "/etc/cni/net.d",
    "PluginMaxConfNum": 1,
    "Prefix": "eth",
    "Networks": [
      {
        "Config": {
          "Name": "cni-loopback",
          "CNIVersion": "0.3.1",
          "Plugins": [
            {
              "Network": {
                "type": "loopback",
                "ipam": {},
                "dns": {}
              },
              "Source": "{\"type\":\"loopback\"}"
            }
          ],
          "Source": "{\n\"cniVersion\": \"0.3.1\",\n\"name\": \"cni-loopback\",\n\"plugins\": [{\n  \"type\": \"loopback\"\n}]\n}"
        },
        "IFName": "lo"
      },
      {
        "Config": {
          "Name": "aws-cni",
          "CNIVersion": "0.3.1",
          "Plugins": [
            {
              "Network": {
                "name": "aws-cni",
                "type": "aws-cni",
                "ipam": {},
                "dns": {}
              },
              "Source": "{\"mtu\":\"9001\",\"name\":\"aws-cni\",\"pluginLogFile\":\"/var/log/aws-routed-eni/plugin.log\",\"pluginLogLevel\":\"DEBUG\",\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"}"
            },
            {
              "Network": {
                "name": "egress-v4-cni",
                "type": "egress-v4-cni",
                "ipam": {
                  "type": "host-local"
                },
                "dns": {}
              },
              "Source": "{\"enabled\":\"false\",\"ipam\":{\"dataDir\":\"/run/cni/v6pd/egress-v4-ipam\",\"ranges\":[[{\"subnet\":\"169.254.172.0/22\"}]],\"routes\":[{\"dst\":\"0.0.0.0/0\"}],\"type\":\"host-local\"},\"mtu\":9001,\"name\":\"egress-v4-cni\",\"nodeIP\":\"192.168.74.5\",\"pluginLogFile\":\"/var/log/aws-routed-eni/egress-v4-plugin.log\",\"pluginLogLevel\":\"DEBUG\",\"type\":\"egress-v4-cni\"}"
            },
            {
              "Network": {
                "type": "portmap",
                "capabilities": {
                  "portMappings": true
                },
                "ipam": {},
                "dns": {}
              },
              "Source": "{\"capabilities\":{\"portMappings\":true},\"snat\":true,\"type\":\"portmap\"}"
            },
            {
              "Network": {
                "name": "istio-cni",
                "type": "istio-cni",
                "ipam": {},
                "dns": {}
              },
              "Source": "{\"kubernetes\":{\"cni_bin_dir\":\"/opt/cni/bin\",\"exclude_namespaces\":[\"istio-system\",\"kube-system\"],\"kubeconfig\":\"/etc/cni/net.d/ZZZ-istio-cni-kubeconfig\"},\"log_level\":\"debug\",\"log_uds_address\":\"/var/run/istio-cni/log.sock\",\"name\":\"istio-cni\",\"type\":\"istio-cni\"}"
            }
          ],
          "Source": "{\n  \"cniVersion\": \"0.3.1\",\n  \"name\": \"aws-cni\",\n  \"plugins\": [\n    {\n      \"mtu\": \"9001\",\n      \"name\": \"aws-cni\",\n      \"pluginLogFile\": \"/var/log/aws-routed-eni/plugin.log\",\n      \"pluginLogLevel\": \"DEBUG\",\n      \"type\": \"aws-cni\",\n      \"vethPrefix\": \"eni\"\n    },\n    {\n      \"enabled\": \"false\",\n      \"ipam\": {\n        \"dataDir\": \"/run/cni/v6pd/egress-v4-ipam\",\n        \"ranges\": [\n          [\n            {\n              \"subnet\": \"169.254.172.0/22\"\n            }\n          ]\n        ],\n        \"routes\": [\n          {\n            \"dst\": \"0.0.0.0/0\"\n          }\n        ],\n        \"type\": \"host-local\"\n      },\n      \"mtu\": 9001,\n      \"name\": \"egress-v4-cni\",\n      \"nodeIP\": \"192.168.74.5\",\n      \"pluginLogFile\": \"/var/log/aws-routed-eni/egress-v4-plugin.log\",\n      \"pluginLogLevel\": \"DEBUG\",\n      \"type\": \"egress-v4-cni\"\n    },\n    {\n      \"capabilities\": {\n        \"portMappings\": true\n      },\n      \"snat\": true,\n      \"type\": \"portmap\"\n    },\n    {\n      \"kubernetes\": {\n        \"cni_bin_dir\": \"/opt/cni/bin\",\n        \"exclude_namespaces\": [\n          \"istio-system\",\n          \"kube-system\"\n        ],\n        \"kubeconfig\": \"/etc/cni/net.d/ZZZ-istio-cni-kubeconfig\"\n      },\n      \"log_level\": \"debug\",\n      \"log_uds_address\": \"/var/run/istio-cni/log.sock\",\n      \"name\": \"istio-cni\",\n      \"type\": \"istio-cni\"\n    }\n  ]\n}\n"
        },
        "IFName": "eth0"
      }
    ]
  },
  "config": {
    "containerd": {
      "snapshotter": "overlayfs",
      "defaultRuntimeName": "runc",
      "defaultRuntime": {
        "runtimeType": "",
        "runtimePath": "",
        "runtimeEngine": "",
        "PodAnnotations": null,
        "ContainerAnnotations": null,
        "runtimeRoot": "",
        "options": null,
        "privileged_without_host_devices": false,
        "baseRuntimeSpec": "",
        "cniConfDir": "",
        "cniMaxConfNum": 0
      },
      "untrustedWorkloadRuntime": {
        "runtimeType": "",
        "runtimePath": "",
        "runtimeEngine": "",
        "PodAnnotations": null,
        "ContainerAnnotations": null,
        "runtimeRoot": "",
        "options": null,
        "privileged_without_host_devices": false,
        "baseRuntimeSpec": "",
        "cniConfDir": "",
        "cniMaxConfNum": 0
      },
      "runtimes": {
        "runc": {
          "runtimeType": "io.containerd.runc.v2",
          "runtimePath": "",
          "runtimeEngine": "",
          "PodAnnotations": null,
          "ContainerAnnotations": null,
          "runtimeRoot": "",
          "options": {
            "SystemdCgroup": true
          },
          "privileged_without_host_devices": false,
          "baseRuntimeSpec": "",
          "cniConfDir": "",
          "cniMaxConfNum": 0
        }
      },
      "noPivot": false,
      "disableSnapshotAnnotations": true,
      "discardUnpackedLayers": false,
      "ignoreRdtNotEnabledErrors": false
    },
    "cni": {
      "binDir": "/opt/cni/bin",
      "confDir": "/etc/cni/net.d",
      "maxConfNum": 1,
      "confTemplate": "",
      "ipPref": ""
    },
    "registry": {
      "configPath": "/etc/containerd/certs.d:/etc/docker/certs.d",
      "mirrors": null,
      "configs": null,
      "auths": null,
      "headers": null
    },
    "imageDecryption": {
      "keyModel": "node"
    },
    "disableTCPService": true,
    "streamServerAddress": "127.0.0.1",
    "streamServerPort": "0",
    "streamIdleTimeout": "4h0m0s",
    "enableSelinux": false,
    "selinuxCategoryRange": 1024,
    "sandboxImage": "602401143452.dkr.ecr.us-west-2.amazonaws.com/eks/pause:3.5",
    "statsCollectPeriod": 10,
    "systemdCgroup": false,
    "enableTLSStreaming": false,
    "x509KeyPairStreaming": {
      "tlsCertFile": "",
      "tlsKeyFile": ""
    },
    "maxContainerLogSize": 16384,
    "disableCgroup": false,
    "disableApparmor": false,
    "restrictOOMScoreAdj": false,
    "maxConcurrentDownloads": 3,
    "disableProcMount": false,
    "unsetSeccompProfile": "",
    "tolerateMissingHugetlbController": true,
    "disableHugetlbController": true,
    "device_ownership_from_security_context": false,
    "ignoreImageDefinedVolumes": false,
    "netnsMountsUnderStateDir": false,
    "enableUnprivilegedPorts": false,
    "enableUnprivilegedICMP": false,
    "containerdRootDir": "/mnt/cache/containerd",
    "containerdEndpoint": "/run/containerd/containerd.sock",
    "rootDir": "/mnt/cache/containerd/io.containerd.grpc.v1.cri",
    "stateDir": "/run/containerd/io.containerd.grpc.v1.cri"
  },
  "golang": "go1.18.6",
  "lastCNILoadStatus": "OK",
  "lastCNILoadStatus.default": "OK"
}

Show configuration if it is related to CRI plugin.

No response

Metadata

Metadata

Assignees

No one assigned

    Labels

    kind/performancestatus/needs-validation

    Type

    Bug

    Projects

    Issue Management

    Status

    In progress

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions