search

moby / buildkit

concurrent, cache-efficient, and Dockerfile-agnostic builder toolkit
https://github.com/moby/moby/issues/34227
Apache License 2.0
8.2k stars 1.16k forks source link

archutil.check is being called too often #3120

Open sudo-bmitch opened 2 years ago

sudo-bmitch commented 2 years ago

For a simple build of an image without any RUN steps, I'm seeing delays of 30 seconds, sometimes over a minute, before the build starts sending the context. During that time, I'm seeing multiple calls to the check command:

# while true; do ps auxw | grep check | grep libexec; sleep 0.5; done
root     1999873  0.0  0.0 224108  4536 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     1999881  8.0  0.0 222684  3736 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     1999892  0.0  0.0 223492  3604 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     1999898 10.0  0.0 223500  3832 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     1999898 61.0  0.0 223500  3832 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     1999908 49.0  0.0 4409656 4608 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     1999940  0.0  0.0 224108  4536 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     1999947  0.0  0.0 222684  3740 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     1999953  0.0  0.0 223188  4268 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     1999959 21.0  0.0 222396  3444 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     1999959 72.0  0.0 222396  3444 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     1999970 33.0  0.0 223492  3604 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     1999976  0.0  0.0 223500  3832 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     1999976 60.0  0.0 223500  3832 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     1999986  0.0  0.0 4409656 4604 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     1999992  0.0  0.0 224108  4532 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000000  0.0  0.0 223188  4420 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000013 46.0  0.0 4409656 4604 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     2000019  0.0  0.0 224108  4532 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000025  0.0  0.0 222684  3736 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000031  0.0  0.0 223188  4412 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000037  0.0  0.0 222396  3444 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000044  0.0  0.0 223492  3776 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     2000050  0.0  0.0 223500  3664 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000056  0.0  0.0 4409656 4608 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     2000062  0.0  0.0 224108  4532 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000070  0.0  0.0 223188  4420 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000070 60.0  0.0 223188  4420 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000083  0.0  0.0 222396  3788 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000102  0.0  0.0 222684  3736 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000111  0.0  0.0 222396  3880 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000118  0.0  0.0 223492  3608 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     2000124  0.0  0.0 223500  3660 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000134 46.0  0.0 222684  3600 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000143  0.0  0.0 223188  4416 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000154 46.0  0.0 223500  3660 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000160  0.0  0.0 4409656 4608 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     2000166 47.0  0.0 224108  4368 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000178  0.0  0.0 222684  3600 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000184 45.0  0.0 223188  4272 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000193  0.0  0.0 223492  3776 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     2000199 44.0  0.0 223500  3664 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000205  0.0  0.0 4409656 4604 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     2000213  0.0  0.0 222684  3740 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000219  0.0  0.0 223188  4272 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000225 36.0  0.0 222396  3788 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000232  0.0  0.0 223492  3608 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     2000238 37.0  0.0 223500  3664 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000246  0.0  0.0 224108  4532 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000252 29.0  0.0 222684  3600 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000258  0.0  0.0 223188  4272 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000264  0.0  0.0 222396  3788 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000279  0.0  0.0 223492  3608 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     2000287  0.0  0.0 4409656 4608 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     2000422  0.0  0.0 223188  4272 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000428 32.0  0.0 222396  3444 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000435  0.0  0.0 223492  3776 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     2000441 27.0  0.0 223500  3836 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000447  0.0  0.0 4409656 4580 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     2000453  8.0  0.0 224108  4372 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000461  0.0  0.0 223188  4272 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000467  0.0  0.0 222396  3792 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000474  0.0  0.0 223492  3608 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     2000480 44.0  0.0 223500  3664 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000488  0.0  0.0 224108  4372 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000494 32.0  0.0 222684  3604 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000502  0.0  0.0 222396  3788 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000515 45.0  0.0 224108  4536 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000521  0.0  0.0 222684  3604 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000527 47.0  0.0 223188  4268 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000540  0.0  0.0 222396  3444 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000549  0.0  0.0 223500  3660 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000555  0.0  0.0 4409656 4612 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     2000564  0.0  0.0 224108  4372 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000564  0.0  0.0 224108  4372 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000564  107  0.0 224108  4372 ?        Rl   11:44   0:01 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000564  131  0.0 224108  4372 ?        Dl   11:44   0:01 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000564 65.5  0.0 224108  4372 ?        Dl   11:44   0:01 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000586  0.0  0.0 222684  3736 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000592  0.0  0.0 223188  4276 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000598  0.0  0.0 222396  3384 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000605  0.0  0.0 223492  3608 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     2000618  0.0  0.0 4409656 4608 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     2000624  0.0  0.0 224108  4532 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000631  0.0  0.0 222684  3600 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000639  0.0  0.0 222396  3788 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000648  0.0  0.0 223500  3660 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000654 48.0  0.0 4409656 4608 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     2000662  0.0  0.0 222684  3732 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000668 27.0  0.0 223188  4416 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000674  0.0  0.0 222396  3784 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000681 13.0  0.0 223492  3772 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     2000687  0.0  0.0 223500  3832 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000687 54.0  0.0 223500  3832 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000704 51.0  0.0 222684  3740 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000711  0.0  0.0 223188  4268 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000720  0.0  0.0 223492  3776 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     2000726  0.0  0.0 223500  3832 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check
root     2000732  0.0  0.0 4409656 4612 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/arm-binfmt-P /check /check
root     2000826 42.0  0.0 224108  4368 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/aarch64-binfmt-P /check /check
root     2000836  0.0  0.0 222684  3596 ?        Rl   11:44   0:00 /usr/libexec/qemu-binfmt/riscv64-binfmt-P /check /check
root     2000842  0.0  0.0 223188  4420 ?        Rl   11:45   0:00 /usr/libexec/qemu-binfmt/ppc64le-binfmt-P /check /check
root     2000848  0.0  0.0 222396  3444 ?        Rl   11:45   0:00 /usr/libexec/qemu-binfmt/s390x-binfmt-P /check /check
root     2000855 32.0  0.0 223492  3604 ?        Rl   11:45   0:00 /usr/libexec/qemu-binfmt/mips64el-binfmt-P /check /check
root     2000861  0.0  0.0 223500  3832 ?        Rl   11:45   0:00 /usr/libexec/qemu-binfmt/mips64-binfmt-P /check /check

The above was seen when building:

FROM scratch                                        
COPY base-a.txt /base.txt                           
LABEL base=a

With buildx:

docker buildx build --platform "linux/amd64,linux/arm64,linux/arm/v7,linux/arm/v6" ...

With a docker-container driver:

$ docker buildx ls
NAME/NODE    DRIVER/ENDPOINT             STATUS   PLATFORMS
container    docker-container                     
  container0 unix:///var/run/docker.sock inactive 
localhost *  docker-container                     
  localhost0 unix:///var/run/docker.sock running  linux/amd64, linux/arm64, linux/riscv64, linux/ppc64le, linux/s390x, linux/386, linux/mips64le, linux/mips64, linux/arm/v7, linux/arm/v6
default      docker                               
  default    default                     running  linux/amd64, linux/arm64, linux/riscv64, linux/ppc64le, linux/s390x, linux/386, linux/arm/v7, linux/arm/v6

Running on the 20.10.18 build of docker:

$ docker version
Client: Docker Engine - Community
 Version:           20.10.18
 API version:       1.41
 Go version:        go1.18.6
 Git commit:        b40c2f6
 Built:             Thu Sep  8 23:12:20 2022
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.18
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.18.6
  Git commit:       e42327a
  Built:            Thu Sep  8 23:10:02 2022
  OS/Arch:          linux/amd64
  Experimental:     true
 containerd:
  Version:          1.6.8
  GitCommit:        9cd3357b7fd7218e4aec3eae239db1f68a5a6ec6
 runc:
  Version:          1.1.4
  GitCommit:        v1.1.4-0-g5fd4c4d
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

$ docker buildx version
github.com/docker/buildx v0.8.2
sudo-bmitch commented 2 years ago

Since this involves creating a tempdir, writing a binary, and executing that binary with an interpreter, ideally this would only be called once, and only if needed for a user query or running a step that needs an interpreter (like a RUN step in a Dockerfile for a platform other than the local platform).

An example of a call that doesn't make sense to me is:

https://github.com/moby/buildkit/blob/61307b8f2e73d681721b51856c10cb8606e5ea70/cmd/buildkitd/main.go#L701

That gets run just after a cached call to w.Platforms. Either the Platforms call shouldn't be cached or we don't need the immediate follow up call to WarnIfUnsupported.

tonistiigi commented 2 years ago

The line you linked only gets called once on daemon boot.

But there are other places where this gets called. It needs to be called every time you do workers ls (equivalent buildx inspect) and also when starting a build with unknown platform. This is because any changes to emulators should be picked up automatically without requiring buildkitd restart.

There seems to be something in your system as well as these invocations should be very fast as they are binaries with literally 2 assembly instructions.

sudo-bmitch commented 2 years ago

The line you linked only gets called once on daemon boot.

Yup, but it did the same work on line 699 if it wasn't cached already (which it wouldn't be on startup), so it's 2x the calls.

There seems to be something in your system as well as these invocations should be very fast as they are binaries with literally 2 assembly instructions.

Entirely possible my system needs a replace/rebuild. I suspect it's more the fork/exec and qemu running the interpreter, than the assembly itself. An arm64 build takes 10x the time of the same amd64 build on my host, so there's definitely some qemu overhead on my system. The behavior also isn't consistent, sometimes it's only an extra second or two, other times it's hanging for 20 seconds, which I suspect has more to do with whether it's launching buildkitd or it was already running. But it's been noticeable since I tried out the 22.06 beta, and now with the 20.10.18 release.

tonistiigi commented 2 years ago

What timings do you see when invoking this check command manually? Have you been able to reproduce long times or high CPU? Have you tried if using some other binfmt installation makes a difference?

sudo-bmitch commented 2 years ago

Using the following check_test.go:

package archutil

import "testing"

func BenchmarkSupportedPlatforms(b *testing.B) {
    for n := 0; n < b.N; n++ {
        pl := SupportedPlatforms(true)
        if len(pl) < 5 {
            b.Errorf("not enough platforms: %v", pl)
        }
    }
}

And running the test as root (for the chroot), I'm getting:

BenchmarkSupportedPlatforms-8               1438          16034324 ns/op

So it's not taking the over 0.5 sec for some platforms that I'm seeing during the docker builds. The standalone binaries are similarly fast.

$ time for file in bin/*; do echo $file; ./$file; done
bin/386
bin/amd64
bin/arm
bin/arm64
bin/mips64
bin/mips64le
bin/ppc64le
bin/riscv64
bin/s390x

real    0m0.098s
user    0m0.026s
sys     0m0.073s

I'll keep digging to see if I can track down the long startup times.