Image pull speed is throttled by unknown source #8160
Description
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
- Set up cluster (mine is EKS but can't see how it is related in this case)
- Set up proxy cache server (in my case using nginx)
- 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 - Delete images.content and re-pull, time the fetches from debug logs or otherwise
- use
curlor a attached go module to fetch from cache, note much larger speedup: egtime curl https://proxy-host/v2/test-image/blobs/sha256:<layer_hash>ortime ./fetchbelow.
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