cri_dockerd as included in rke-tools has extremely bad performance

[chfrank-cgn]

RKE version:
1.3.11 - v1.23.6

Docker version: (docker version, docker info preferred)
20.10

Operating system and kernel: (cat /etc/os-release, uname -r preferred)
Ubuntu 20.04 LTS

Type/provider of hosts: (VirtualBox/Bare-metal/AWS/GCE/DO)
Azure

cluster.yml file:

  rke_config {
    kubernetes_version = var.k8version
    ignore_docker_version = false
    enable_cri_dockerd = true
    }
    network {
      plugin = "flannel"
    }

Steps to Reproduce:
Set enable_cri_dockerd will lead to constant, near 100% CPU consumption from an empty cluster on a 4vCPU VM (Standard_D4s_v3)

Results:
With 1.24 approaching fast, we should provide a working option for the installed base that wants to continue with RKE1 and Docker.

[tsde]

I'm seeing the same behavior in a simple setup involving one node with 2 CPUs. Here's my spec for reference :

RKE / Kubernetes version:
1.3.11 - v1.23.6

Docker version: (docker version, docker info preferred)
20.10.12

Operating system and kernel: (cat /etc/os-release, uname -r preferred)
Flatcar Linux 3139.2.1

Type/provider of hosts: (VirtualBox/Bare-metal/AWS/GCE/DO)
VMWare workstation (using Flatcar Linux OVA)

With enable_cri_dockerd set to false, there's no issue. Setting it to true when creating a cluster results in the behavior described.
Stracing the dockerd process including its threads shown a very huge amount of constant overlay scanning using newfstatat and lgetxattr syscalls that hog the CPU (1 to 1,5 core constantly). This "scanning" involves overlays from running containers as well as already exited containers.

Small excerpt from strace:

.../...
[pid  1175] newfstatat(AT_FDCWD, "/var/lib/docker/overlay2/272c043a758e089d76818fd1d41fbf611dc57fa51f4c9fb9284c82f500afffca/merged/opt/az/lib/python3.8/site-packages/azure/multiapi/storage/v2015_04_05/common/__pycache__/_error.cpython-38.pyc",  <unfinished ...>
[pid   867] lgetxattr("/var/lib/docker/overlay2/272c043a758e089d76818fd1d41fbf611dc57fa51f4c9fb9284c82f500afffca/merged/opt/az/lib/python3.8/site-packages/azure/mgmt/web/v2021_03_01/operations/_container_apps_revisions_operations.py", "security.capability",  <unfinished ...>
[pid  1175] <... newfstatat resumed>{st_mode=S_IFREG|0644, st_size=214, ...}, AT_SYMLINK_NOFOLLOW) = 0
[pid   867] <... lgetxattr resumed>0xc00d1c6300, 128) = -1 ENODATA (No data available)
[pid   862] <... nanosleep resumed>NULL) = 0
[pid  1175] lgetxattr("/var/lib/docker/overlay2/272c043a758e089d76818fd1d41fbf611dc57fa51f4c9fb9284c82f500afffca-init/merged/opt/az/lib/python3.8/site-packages/azure/multiapi/storage/v2015_04_05/common/__pycache__/_error.cpython-38.pyc", "security.capability",  <unfinished ...>
[pid   867] newfstatat(AT_FDCWD, "/var/lib/docker/overlay2/272c043a758e089d76818fd1d41fbf611dc57fa51f4c9fb9284c82f500afffca-init/merged/opt/az/lib/python3.8/site-packages/azure/mgmt/web/v2021_03_01/operations/_deleted_web_apps_operations.py",  <unfinished ...>
[pid  1175] <... lgetxattr resumed>0xc00cc76580, 128) = -1 ENODATA (No data available)
[pid   867] <... newfstatat resumed>{st_mode=S_IFREG|0644, st_size=13747, ...}, AT_SYMLINK_NOFOLLOW) = 0
[pid   862] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid  1175] lgetxattr("/var/lib/docker/overlay2/272c043a758e089d76818fd1d41fbf611dc57fa51f4c9fb9284c82f500afffca/merged/opt/az/lib/python3.8/site-packages/azure/multiapi/storage/v2015_04_05/common/__pycache__/_error.cpython-38.pyc", "security.capability",  <unfinished ...>
[pid   867] newfstatat(AT_FDCWD, "/var/lib/docker/overlay2/272c043a758e089d76818fd1d41fbf611dc57fa51f4c9fb9284c82f500afffca/merged/opt/az/lib/python3.8/site-packages/azure/mgmt/web/v2021_03_01/operations/_deleted_web_apps_operations.py",  <unfinished ...>
[pid  1175] <... lgetxattr resumed>0xc00cc76600, 128) = -1 ENODATA (No data available)
[pid   867] <... newfstatat resumed>{st_mode=S_IFREG|0644, st_size=13747, ...}, AT_SYMLINK_NOFOLLOW) = 0
[pid   862] <... nanosleep resumed>NULL) = 0
[pid  1175] newfstatat(AT_FDCWD, "/var/lib/docker/overlay2/272c043a758e089d76818fd1d41fbf611dc57fa51f4c9fb9284c82f500afffca-init/merged/opt/az/lib/python3.8/site-packages/azure/multiapi/storage/v2015_04_05/common/__pycache__/models.cpython-38.pyc",  <unfinished ...>
[pid   867] lgetxattr("/var/lib/docker/overlay2/272c043a758e089d76818fd1d41fbf611dc57fa51f4c9fb9284c82f500afffca-init/merged/opt/az/lib/python3.8/site-packages/azure/mgmt/web/v2021_03_01/operations/_deleted_web_apps_operations.py", "security.capability",  <unfinished ...>
[pid   862] futex(0xc00191ed50, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  1175] <... newfstatat resumed>{st_mode=S_IFREG|0644, st_size=214, ...}, AT_SYMLINK_NOFOLLOW) = 0
[pid   867] <... lgetxattr resumed>0xc00d1c6480, 128) = -1 ENODATA (No data available)
[pid  5047] <... futex resumed>)        = 0
[pid  1175] newfstatat(AT_FDCWD, "/var/lib/docker/overlay2/272c043a758e089d76818fd1d41fbf611dc57fa51f4c9fb9284c82f500afffca/merged/opt/az/lib/python3.8/site-packages/azure/multiapi/storage/v2015_04_05/common/__pycache__/models.cpython-38.pyc",  <unfinished ...>
[pid   867] futex(0xc000152950, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid   862] <... futex resumed>)        = 1
[pid  5047] newfstatat(AT_FDCWD, "/var/lib/docker/overlay2/ee034feea43ec49dacc8e91bf26552519544814874aff156a378a374b80e31c2-init/merged/opt/az/lib/python3.8/site-packages/invoke/__pycache__",  <unfinished ...>
[pid  1175] <... newfstatat resumed>{st_mode=S_IFREG|0644, st_size=214, ...}, AT_SYMLINK_NOFOLLOW) = 0
[pid  5047] <... newfstatat resumed>{st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_SYMLINK_NOFOLLOW) = 0
[pid  1175] lgetxattr("/var/lib/docker/overlay2/272c043a758e089d76818fd1d41fbf611dc57fa51f4c9fb9284c82f500afffca-init/merged/opt/az/lib/python3.8/site-packages/azure/multiapi/storage/v2015_04_05/common/__pycache__/models.cpython-38.pyc", "security.capability",  <unfinished ...>
[pid   862] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
.../...

I also noticed that metrics server does not seem to work properly when enabling this option

I0523 21:13:25.464651       1 server.go:187] "Failed probe" probe="metric-storage-ready" err="no metrics to serve"
E0523 21:13:31.248300       1 scraper.go:140] "Failed to scrape node" err="Get \"https://172.16.9.130:10250/metrics/resource\": context deadline exceeded" node="fc-test"

[jiaqiluo]

This PR in the upstream repo possibly fixes this issue.
So the plan, for now, is to bring the changes from the upstream into our fork and then release a new image.

[jiaqiluo]

rke-tools 0.1.81 is available, it contains the latest cri-dockerd 0.2.1

we will use this new image in the coming KDM release.

Update:
We will use rke-tools 0.1.82 and it incldues cri-dockerd 0.2.2

[Josh-Diamond]

Ticket #2938 - Test Results

Reproduced with rke v1.3.11 and k8s v1.23.6:

1. Create a single EC-2 instance of t3.medium
2. Using rke v1.3.11, run rke up on instance with cluster.yml ignore_docker_version = false and enable_cri_dockerd = true configurations set - [k8s v1.23.6-rancher1-1]
3. Once cluster successfully builds, ssh into the node and run top to view CPU performace
4. Reproduced - CPU consumption EXTREMELY high from empty cluster

Screenshot:

Step 4

[Raboo]

In my case on flatcar Linux on a couple of +48 core nodes it used all available CPU and caused very high load eventually crashing workloads in the cluster.

@jiaqiluo When will rke-tools 0.1.82 be used in Rancher provisioned RKE1 clusters?

[jiaqiluo]

@Raboo The plan is in Rancher 2.6.6 2.6.7

[jiaqiluo]

can be tested on v1.3.13-rc2 https://github.com/rancher/rke/releases/tag/v1.3.13-rc2

The validation steps should be the same as the reproduction steps #2938 (comment)

[Josh-Diamond]

Ticket #2938 - Test Results [pt. 2]

With rke v1.3.13-rc2 and k8s v1.23.6:

1. Create a single EC-2 instance of t3.medium
2. Using rke v1.3.13-rc2, run rke up on instance with cluster.yml ignore_docker_version = false and enable_cri_dockerd = true configurations set - [k8s v1.23.6-rancher1-1]
3. Once cluster successfully builds, ssh into the node and run top to view CPU performace
4. Verified - CPU consumption as expected from empty cluster

Screenshot:

Step 4

[Raboo]

It seems like this is not fixed in Rancher v2.6.6 if I read the release notes.

[jiaqiluo]

@Raboo You are right; the fix is not in rancher 2.6.6 but will be in 2.6.7 ( as the milestone indicates) which is planned to be released this week.

[cite]

We are still seeing massive performance problems when using enable_cri_dockerd - are we sure that the correct fixes are applied? I can see that the cri-dockerd from rancher/hyperkube:v1.24.4-rancher1 self-identifies as 0.2.4 (while the included docker client identifies as 1.12.3 from 2016), but we are still seeing really bad performance.

[jiaqiluo]

I can see that the cri-dockerd from rancher/hyperkube:v1.24.4-rancher1 self-identifies as 0.2.4

The correct fix is applied because the upsteam cri-dockerd has fixed the metrics performance issue in v0.2.1

[chfrank-cgn]

I can confirm - a fresh RKE installation 1.24.4 (from Rancher 2.6.8) shows the same behavior as before, with very high CPU usage and low performance.

Looking at the system itself, the process consuming all available CPU is dockerd.

[Raboo]

Well this makes me afraid of upgrading to k8s v1.24. Last time I enabled the enable_cri_dockerd it brought my cluster down to complete halt.

[rvdh]

Also confirmed here on Rancher 2.6.8, k8s v1.24.2 - dockerd using 100% cpu.

@jiaqiluo is it possible 2.6.8 reverted the fix in 2.6.7?

[jympetalmd]

same problem with 2.7.0 and v1.23.10-rancher1-1 with cri enabled
it's even worse with v1.24.8-rancher1-1

[immanuelfodor]

We should probably track rancher/rancher#38816 it seems to aggregate the abnormal CPU usage issues with the CRI