This page looks best with JavaScript enabled

Troubleshooting Slow IO When Building Images

 ·  ☕ 10 min read

1. The Problem

Project details:

  • File size 5.6 GB
  • File count 529352

Dockerfile

1
2
3
FROM golang:1.13

COPY ./ /go/src/code

The build command and its output are as follows:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
time DOCKER_BUILDKIT=1 docker build --no-cache -t test:v3 -f Dockerfile .  --progress=plain

#1 [internal] load build definition from Dockerfile
#1 sha256:2a154d4ad813d1ef3355d055345ad0e7c5e14923755cea703d980ecc1c576ce7
#1 transferring dockerfile: 37B done
#1 DONE 0.1s

#2 [internal] load .dockerignore
#2 sha256:9598c0ddacf682f2cac2be6caedf6786888ec68f009c197523f8b1c2b5257b34
#2 transferring context: 2B done
#2 DONE 0.2s

#3 [internal] load metadata for golang:1.13
#3 sha256:0c7952f0b4e5d57d371191fa036da65d51f4c4195e1f4e1b080eb561c3930497
#3 DONE 0.0s

#4 [1/2] FROM golang:1.13
#4 sha256:692ef5b58e708635d7cbe3bf133ba934336d80cde9e2fdf24f6d1af56d5469ed
#4 CACHED

#5 [internal] load build context
#5 sha256:f87f36fa1dc9c0557ebc53645f7ffe404ed3cfa3332535260e5a4a1d7285be3c
#5 transferring context: 18.73MB 4.8s
#5 transferring context: 38.21MB 9.8s done
#5 DONE 10.5s

#6 [2/2] COPY ./ /go/src/code
#6 sha256:2c63806741b84767def3d7cebea3872b91d7ef00bd3d524f48976077cce3849a
#6 DONE 26.8s

#7 exporting to image
#7 sha256:e8c613e07b0b7ff33893b694f7759a10d42e180f2b4dc349fb57dc6b71dcab00
#7 exporting layers
#7 exporting layers 67.5s done
#7 writing image sha256:03b278543ab0f920f5af0540d93c5e5340f5e1f0de2d389ec21a2dc82af96754 done
#7 naming to docker.io/library/test:v3 done
#7 DONE 67.6s

real    1m45.411s
user    0m18.374s
sys     0m7.344s

The time-consuming parts are:

  • 10s, load build context
  • 26s, executing the COPY operation
  • 67s, exporting the image, image size 5.79GB

The following sections follow this same line of thinking, checking each item one by one and validating with tests, in search of the IO bottleneck during builds.

2. A Custom Go Client Submitting Directly to Dockerd Performs Poorly

The project https://github.com/shaowenchen/demo/tree/master/buidl-cli implements exactly this: it submits the local Dockerfile and context to Dockerd for building, so as to test whether the Docker CLI has a bottleneck when submitting files.

2.1 Compile the Binary

1
GOOS=linux GOARCH=amd64 go build  -o build main.go

2.2 Submit a Build Job with the Custom Binary

1
2
3
4
5
time ./build ./ test:v3

real    5m12.758s
user    0m2.182s
sys     0m14.169s

Using the CLI written in Go to submit the build context to Dockerd for building, the duration increases sharply; meanwhile, the load on the build machine spikes.

There may be other optimization points that need slow debugging. And the Docker CLI actually also has relevant parameters that can be used to reduce IO time.

3. The compress and stream Build Parameters Have Little Optimizing Effect

compress compresses the context into gzip format for transmission, while stream transmits the context as a stream.

3.1 Optimizing with compress

1
2
3
4
5
time DOCKER_BUILDKIT=1 docker build --no-cache -t test:v3 -f Dockerfile . --compress

real    1m46.117s
user    0m18.551s
sys     0m7.803s

3.2 Optimizing with stream

1
2
3
4
5
time DOCKER_BUILDKIT=1 docker build --no-cache -t test:v3 -f Dockerfile . --stream

real    1m51.825s
user    0m19.399s
sys     0m7.657s

Neither of these two parameters has much effect on shortening the build time. But note that the test project’s files are large and numerous; if the test case changes, the effect may differ. Next, let us look together at how file count and file size affect Dockerd’s image building.

4. File Count Affects COPY Far Less Than File Size

4.1 Preparing Test Files

1
2
3
4
du -h --max-depth=1

119M    ./data
119M    .

A 119MB file was placed in the data directory, and the build context size was increased by copying that file repeatedly.

4.2 Test Dockerfile

1
2
3
FROM golang:1.13

COPY ./ /go/src/code

4.3 Build Command

1
DOCKER_BUILDKIT=1 docker build --no-cache -t test:v3 -f Dockerfile .

4.4 File Size Has a Clear Effect on COPY

File SizeBuild DurationFile Count
119M0.3s1
237M0.4s2
355M0.5s3
473M0.6s4
1.3G3.7s11
2.6G9.0s22

File size has a clear effect on COPY, growing nearly linearly.

4.5 File Count Has Almost No Effect on COPY

File SizeBuild DurationFile Count
2.9G13.8s264724
5.6G37.1s529341

File count has little effect on COPY. This is because when the Docker CLI sends the build context to Dockerd, it tars up the context rather than transferring files one at a time.

4.6 The Build Concurrency Bottleneck Is Disk IO

5.6G, 529341 files

ConcurrencyBuild Duration
137.1s
246s
381s

Using iotop you can observe the disk write speed in real time; it reaches 200MB/s at its fastest, closest to the file system’s 4K random write speed.

1
2
Rand_Write_Testing: (groupid=0, jobs=1): err= 0: pid=30436
  write: IOPS=37.9k, BW=148MiB/s (155MB/s)(3072MiB/20752msec); 0 zone resets

Because a single Dockerd is shared, the Dockerd throughput becomes a bottleneck under concurrency, and the system’s disk IO also becomes a bottleneck.

5. Not Cleaning the Buildkit Cache Has Almost No Effect on New Builds

If it reports that docker build cannot be found, then EXPERIMENTAL needs to be enabled, or there is no buildx and docker-buildx needs to be downloaded to the /usr/libexec/docker/cli-plugins/ directory.

  • View the build cache
1
docker system df  -v
  • Clean all build cache
1
DOCKER_BUILDKIT=1 docker builder prune -f

Build cache is only produced when BuildKit is enabled. In the production environment the cache size reached 1.408TB, but comparing before and after cleaning, no obvious change in build speed was found for new projects; for old projects, if nothing changed, hitting the cache is very fast. The likely reason is that although the cache is large, there are not many entries, so the cost of querying whether a cache exists is very small.

But cleaning the cache periodically helps prevent the risk of the disk filling up.

  • Periodically clean old build cache

Clean cache older than 72h

1
DOCKER_CLI_EXPERIMENTAL=enabled docker buildx prune --filter "until=72h" -f

6. Builds Do Not Limit CPU but IO Is Very Slow

6.1 Testing CPU Limits

Dockerfile

1
2
3
4
FROM ubuntu
RUN apt-get update -y
RUN apt-get install -y stress
RUN stress -c 40
1
DOCKER_BUILDKIT=1 docker build --no-cache -t test:v3 -f Dockerfile .

The build machine has 40C; during the build the machine’s CPU load reaches 95%, which shows that Dockerd does not limit CPU consumption by default during builds. In the production environment there have been cases where npm run build consumed more than a dozen GB of memory, so I judge that Dockerd does not limit memory consumption by default either.

6.2 Testing IO in the Dockerfile

Dockerfile

1
2
3
4
FROM ubuntu
RUN apt-get update -y
RUN apt-get install -y fio
RUN fio -direct=1 -iodepth=128 -rw=randwrite -ioengine=libaio -bs=4k -size=3G -numjobs=1 -runtime=1000 -group_reporting -filename=/tmp/test.file --allow_mounted_write=1 -name=Rand_Write_Testing
1
2
3
4
DOCKER_BUILDKIT=1 docker build --no-cache -t test:v3 -f Dockerfile .

Rand_Write_Testing: (groupid=0, jobs=1): err= 0
   write: IOPS=17.4k, BW=67.9MiB/s (71.2MB/s)(3072MiB/45241msec); 0 zone resets

6.3 Testing IO in a Container

1
docker run -it shaowenchen/demo:fio bash
1
2
Rand_Write_Testing: (groupid=0, jobs=1): err= 0
  write: IOPS=17.4k, BW=68.1MiB/s (71.4MB/s)(3072MiB/45091msec); 0 zone resets

6.4 Testing IO in a Container Storage Volume

1
docker run -v /tmp:/tmp -it shaowenchen/demo:fio bash
1
2
Rand_Write_Testing: (groupid=0, jobs=1): err= 0
  write: IOPS=39.0k, BW=152MiB/s (160MB/s)(3072MiB/20162msec); 0 zone resets

6.5 Testing IO on the Host

1
2
Rand_Write_Testing: (groupid=0, jobs=1): err= 0
  write: IOPS=38.6k, BW=151MiB/s (158MB/s)(3072MiB/20366msec); 0 zone resets

When Dockerd builds a Dockerfile and encounters a Run command, it starts a container to run it and then commits the image. From the test results, you can see that the IO speed in the Dockerfile is far from the host’s, matching the IO speed in a container; the IO speed of a host storage volume matches the host’s IO speed.

7. Building Directly with buildkitd Performs Poorly

Although BuildKit builds can be enabled with DOCKER_BUILDKIT=1, if using buildkitd directly worked well, it would be a good choice to replace Dockerd for building.

7.1 Installing buildkit

1
2
3
wget https://github.com/moby/buildkit/releases/download/v0.11.2/buildkit-v0.11.2.linux-amd64.tar.gz
tar xvf buildkit-v0.11.2.linux-amd64.tar.gz
mv bin/* /usr/local/bin/

7.2 Deploying buildkitd

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
cat > /usr/lib/systemd/system/buildkitd.service <<EOF
[Unit]
Description=/usr/local/bin/buildkitd
ConditionPathExists=/usr/local/bin/buildkitd
After=containerd.service

[Service]
Type=simple
ExecStart=/usr/local/bin/buildkitd
User=root
Restart=on-failure
RestartSec=1500ms

[Install]
WantedBy=multi-user.target
EOF
1
2
3
4
systemctl daemon-reload
systemctl restart buildkitd
systemctl enable buildkitd
systemctl status buildkitd

Just check that buildkitd is running normally.

7.3 Testing buildctl Build Submission

1
2
3
buildctl build --frontend=dockerfile.v0 --local context=. --local dockerfile=. --no-cache --output type=docker,name=test:v4 | docker load

[+] Building 240.8s (7/7) FINISHED

Submitting to buildkitd for building with buildctl takes more time, reaching 4min, double the previous figure.

8. There Is a Bottleneck in Reading and Writing Images Under the Current Storage Driver

8.1 Looking at Dockerd’s Processing Logic

The logic for handling Dockerfiles can be found in the code at https://github.com/moby/moby/blob/8d193d81af9cbbe800475d4bb8c529d67a6d8f14/builder/dockerfile/dispatchers.go.

1, Both Add and Copy call the performCopy function
2, performCopy calls NewRWLayer() to create a new layer, and calls exportImage to write the data

So the suspicion is that Dockerd is slow at writing image layers.

8.2 Testing Image Layer Write Speed

Prepare an image, 16GB in size, 18 layers in total.

  • Import the image
1
2
3
time docker load < /tmp/16GB.tar

real    2m43.288s
  • Save the image
1
2
3
time docker save 0d08de176b9f > /tmp/16GB.tar

real    2m48.497s

docker load and docker save are about the same speed, and the processing speed for image layers is roughly 100 MB/s. That is nearly 30% less than the disk’s 4K random write speed. In my view, if it is for personal use that is barely acceptable; if it is used in a platform product that provides build services externally, this disk is clearly unsuitable.

8.3 How to Choose a Storage Driver

Below is a comparison table compiled from https://docs.docker.com/storage/storagedriver/select-storage-driver/:

Storage DriverFilesystem RequirementsHigh-Frequency Write PerformanceStabilityNotes
overlay2xfs, ext4PoorGoodCurrent first choice
fuse-overlayfsUnrestricted--For rootless scenarios
btrfsbtrfsGood--
zfszfsGood--
vfsUnrestricted--Not recommended for production
aufsxfs, ext4-GoodFirst choice for Docker 18.06 and earlier, unmaintained
devicemapperdirect-lvmGoodGoodUnmaintained
overlayxfs, ext4Poor, but better than overlay2-Unmaintained

Excluding the unmaintained and non-production-suitable ones, there really are not many options left. It happens that there is a machine whose disk was formatted as Btrfs when it was initialized some time ago, which can be used for testing. The zfs storage driver is recommended for high-density PaaS systems.

8.4 Testing the Btrfs Storage Driver

  • On the host
1
2
Rand_Write_Testing: (groupid=0, jobs=1): err= 0
  write: IOPS=40.0k, BW=160MiB/s (168MB/s)(3072MiB/19191msec); 0 zone resets
  • Test command under the container

Run the container

1
docker run -it shaowenchen/demo:fio bash

Run the test

1
fio -direct=1 -iodepth=128 -rw=randwrite -ioengine=libaio -bs=4k -size=3G -numjobs=1 -runtime=1000 -group_reporting -filename=/data/test.file --allow_mounted_write=1 -name=Rand_Write_Testing
  • Testing the overlay2 storage driver
1
2
3
4
5
docker info

Server Version: 20.10.12
Storage Driver: overlay2
  Backing Filesystem: btrfs
1
2
Rand_Write_Testing: (groupid=0, jobs=1): err= 0: pid=78: Thu Feb  2 02:41:48 2023
  write: IOPS=21.5k, BW=84.1MiB/s (88.2MB/s)(3072MiB/36512msec); 0 zone resets
  • Testing the btrfs storage driver
1
2
3
4
5
docker info

Server Version: 20.10.12
Storage Driver: btrfs
  Build Version: Btrfs v5.4.1
1
2
Rand_Write_Testing: (groupid=0, jobs=1): err= 0
  write: IOPS=39.8k, BW=156MiB/s (163MB/s)(3072MiB/19750msec); 0 zone resets

You can clearly see that the btrfs storage driver is faster than overlay2.

9. Summary

This article mainly records the process of troubleshooting a slow Dockerfile build IO problem encountered in the production environment.

Designing various test cases to investigate the problem and validating each factor one by one requires a great deal of patience, and it is very easy to go in the wrong direction and reach a wrong conclusion.

The main points of this article are as follows:

  • The compress and stream parameters are not necessarily effective for build speed
  • Reducing the build context size helps relieve build IO pressure
  • Buildkit’s cache does not need to be cleaned frequently
  • When building a Dockerfile and executing commands, CPU and memory are not limited, but IO is slow
  • Building with buildkitd is slower than Dockerd with DOCKER_BUILDKIT enabled
  • Using Btrfs storage helps achieve better IO speed

But the simplest thing is still to use a disk with fast 4K random read/write. Before taking a new environment into production, be sure to test it first, and only proceed with subsequent plans when it meets the requirements.

10. References


微信公众号
WRITTEN BY
微信公众号