Open FernandoMiguel opened 5 years ago
here is docker-compose second run
docker-compose -f .jenkins/docker-compose.images-base.1.yml build flask-core
Building flask-core
Step 1/5 : FROM python:3.6-alpine AS ms-python-wheel
---> f00bde8f9c15
Step 2/5 : COPY . /src/
---> Using cache
---> a78f716cc093
Step 3/5 : RUN apk add --no-cache --virtual build-dependencies gcc build-base libffi-dev libressl-dev postgresql-dev
---> Using cache
---> e53e0370ed67
Step 4/5 : RUN cd /src && pip wheel -e .
---> Using cache
---> 68ea54a7cf49
Step 5/5 : WORKDIR /src
---> Using cache
---> 925337004af3
Successfully built 925337004af3
in this screenshot you can see 4 runs. from the bottom up: buildx 1st run buildx 2nd run (should have cached but actually took even longer) docker-compose 1st build with no cache docker-compose 2nd run (everything was cached from the 1st build, so was very quick)
root@ip-10-50-0-8:~# journalctl -fu docker.service
-- Logs begin at Sun 2019-07-28 11:42:29 UTC. --
Jul 28 13:47:28 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T13:47:28.607056390Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc01d801ec0, READY" module=grpc
Jul 28 13:49:51 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T13:49:51.321901451Z" level=warning msg="grpc: addrConn.createTransport failed to connect to { 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing only one connection allowed\". Reconnecting..." module=grpc
Jul 28 14:09:42 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:09:42.050784099Z" level=info msg="parsed scheme: \"\"" module=grpc
Jul 28 14:09:42 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:09:42.051186102Z" level=info msg="scheme \"\" not registered, fallback to default scheme" module=grpc
Jul 28 14:09:42 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:09:42.051217375Z" level=info msg="ccResolverWrapper: sending update to cc: {[{ 0 <nil>}] }" module=grpc
Jul 28 14:09:42 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:09:42.051227436Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Jul 28 14:09:42 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:09:42.051335775Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0049ae630, CONNECTING" module=grpc
Jul 28 14:09:42 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:09:42.051481428Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0049ae630, READY" module=grpc
Jul 28 14:12:16 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:12:16.987863612Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0049ae630, TRANSIENT_FAILURE" module=grpc
Jul 28 14:12:16 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:12:16.987886888Z" level=warning msg="grpc: addrConn.createTransport failed to connect to { 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing only one connection allowed\". Reconnecting..." module=grpc
Jul 28 14:18:17 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:18:17.962045963Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Jul 28 14:18:18 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:18:18.040995668Z" level=warning msg="5fa0d898c7160c8ab15e044c09dac750a58189f2a826c04c84454de86f8f7779 cleanup: failed to unmount IPC: umount /mnt/nvme/docker/containers/5fa0d898c7160c8ab15e044c09dac750a58189f2a826c04c84454de86f8f7779/mounts/shm, flags: 0x2: no such file or directory"
Jul 28 14:20:53 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:20:53.738637381Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Jul 28 14:20:53 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:20:53.840989639Z" level=warning msg="0f45a625e93f0d986a26954e0daf3ebee9ff888f25d720c0ae37c06dca822ec1 cleanup: failed to unmount IPC: umount /mnt/nvme/docker/containers/0f45a625e93f0d986a26954e0daf3ebee9ff888f25d720c0ae37c06dca822ec1/mounts/shm, flags: 0x2: no such file or directory"
Jul 28 14:20:54 ip-10-50-0-8 dockerd[9697]: time="2019-07-28T14:20:54.441387293Z" level=info msg="Layer sha256:0cd43e560d4f95f90e9aeec0a4a0c67aee0824a192a2a6d7d39b1b4b1ddda03d cleaned up"
Am I right to assume that these builds happen from different checkouts? A common thing that is not guaranteed to be deterministic is the .git
folder. You can filter the COPY
command to only include the files that you need or use add .git
to .dockerignore
. If you are not sure what gets changed you can print the shasum of all fo the files before the job.
@tonistiigi the build setup checkout the same commit id And in this case I even disabled all the checkouts so it would use the same files on disk All repos have a .dockerignore with .git and Dockerfile/buildx listed inside
This is just one example, and I have have several more services doing the same.
@FernandoMiguel Can you post an example that is reproducible?
@tonistiigi since I'm running this against our organisation code base, I can't share that code. But I'll try to mimic the build behaviour with an hello world example. I'll algo get the file hashes just to double check the build context is the same. Is there a way to see from the Docker agent if the context hasn't change?
As this seems to be the last layer that loses the cache it might also be that is gets cleaned up by gc. You can try to turn it off of set a bigger limit. If you run with debug logs you can see the gc invocations from the logs.
@tonistiigi I've seen it happen with intermediary layers too.
How can I increase the cache? We are talking of about 17GB of data (looking at system prune output). These builders come with 150GB of ephemeral SSD, so it ain't a problem
@FernandoMiguel --oci-worker-gc=false
to turn off --oci-worker-gc-keepstorage=
to control it (more detailed control with the config file). BuildKit is conservative by default and doesn't want to eat away your whole disk. Also, I can't see that driver/exporter you are using. If you export to the docker image store than this data is not released automatically and it can't be the issue then. If you use docker driver then gc is not enabled by default.
cheers @tonistiigi
I can't see that driver/exporter you are using. If you export to the docker image store than this data is not released automatically and it can't be the issue then. If you use docker driver then gc is not enabled by default.
it exports to the local docker registry on the host.
docker-compose push
is used later to push all images of the build
i spent a while on this, but can't find a way to enable debug or gc=false, when using buildx bake
some guidance would be appreciated
@tonistiigi thanks. I tried that, but buildx inspect doesn't show that flag And docker logs of the buildkit id is very quiet too
I don't know what you mean by inspect, the flag is for create
. This PR is not in a release build, you would need to build it yourself.
@tonistiigi I see. Thanks. I'll give it another go tomorrow
/usr/libexec/docker/cli-plugins/docker-buildx build --platform=local -o . git://github.com/docker/buildx
/usr/libexec/docker/cli-plugins/docker-buildx create --use --buildkitd-flags '--debug --oci-worker-gc=false'
/usr/libexec/docker/cli-plugins/docker-buildx inspect quirky_merkle
Name: quirky_merkle
Driver: docker-container
Nodes:
Name: quirky_merkle0
Endpoint: unix:///var/run/docker.sock
Status: running
Flags: --debug --oci-worker-gc=false
Platforms: linux/amd64
Client: Docker Engine - Community
Version: 19.03.1
API version: 1.40
Go version: go1.12.5
Git commit: 74b1e89
Built: Thu Jul 25 21:21:22 2019
OS/Arch: linux/amd64
Experimental: false
Server: Docker Engine - Community
Engine:
Version: 19.03.1
API version: 1.40 (minimum version 1.12)
Go version: go1.12.5
Git commit: 74b1e89
Built: Thu Jul 25 21:19:53 2019
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: 1.2.6
GitCommit: 894b81a4b802e4eb2a91d1ce216b8817763c29fb
runc:
Version: 1.0.0-rc8
GitCommit: 425e105d5a03fabd737a126ad93d62a9eeede87f
docker-init:
Version: 0.18.0
GitCommit: fec3683
Client:
Debug Mode: false
Plugins:
buildx: Build with BuildKit (Docker Inc.)
Server:
Containers: 1
Running: 1
Paused: 0
Stopped: 0
Images: 7
Server Version: 19.03.1
Storage Driver: overlay2
Backing Filesystem: extfs
Supports d_type: true
Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
Volume: local
Network: bridge host ipvlan macvlan null overlay
Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 894b81a4b802e4eb2a91d1ce216b8817763c29fb
runc version: 425e105d5a03fabd737a126ad93d62a9eeede87f
init version: fec3683
Security Options:
apparmor
seccomp
Profile: default
Kernel Version: 5.0.0-1010-aws
Operating System: Ubuntu 19.04
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 30.96GiB
Name: ip-10-50-0-9
ID: FWMR:6PLO:IWGI:LHTL:KQXD:2IO2:XCUP:PAYZ:USP7:ZFAN:P575:CIEH
Docker Root Dir: /mnt/nvme/docker
Debug Mode: false
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
127.0.0.0/8
Live Restore Enabled: false
WARNING: No swap limit support
/usr/libexec/docker/cli-plugins/docker-buildx bake --progress plain -f .jenkins/docker-compose.images-base.1.yml -f .jenkins/buildx.images-base.1.yml flask
time="2019-07-31T18:55:55Z" level=debug msg="session started"
time="2019-07-31T18:55:55Z" level=debug msg="reusing ref for local: 0tow3mjblxanl0jerwyu3gaqq"
time="2019-07-31T18:55:55Z" level=debug msg="reusing ref for local: 1qk8dru7hiwl0xmzjr4fkn43z"
time="2019-07-31T18:55:55Z" level=debug msg="diffcopy took: 2.642166ms"
time="2019-07-31T18:55:55Z" level=debug msg="diffcopy took: 3.103725ms"
time="2019-07-31T18:55:55Z" level=debug msg="saved 1qk8dru7hiwl0xmzjr4fkn43z as local.sharedKey:context:context-.dockerignore:"
time="2019-07-31T18:55:55Z" level=debug msg="saved 0tow3mjblxanl0jerwyu3gaqq as local.sharedKey:dockerfile:dockerfile:"
time="2019-07-31T18:55:55Z" level=debug msg=resolving
time="2019-07-31T18:55:55Z" level=debug msg="do request" request.headers="map[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, *] User-Agent:[containerd/1.2.0+unknown]]" request.method=HEAD url="https://registry-1.docker.io/v2/docker/dockerfile/manifests/experimental"
time="2019-07-31T18:55:55Z" level=debug msg="fetch response received" response.headers="map[Content-Length:[160] Content-Type:[application/json; charset=utf-8] Date:[Wed, 31 Jul 2019 18:55:55 GMT] Docker-Distribution-Api-Version:[registry/2.0] Strict-Transport-Security:[max-age=31536000] Www-Authenticate:[Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:docker/dockerfile:pull\"]]" status="401 Unauthorized" url="https://registry-1.docker.io/v2/docker/dockerfile/manifests/experimental"
time="2019-07-31T18:55:55Z" level=debug msg=Unauthorized header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:docker/dockerfile:pull\""
time="2019-07-31T18:55:55Z" level=debug msg="do request" request.headers="map[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, *] User-Agent:[containerd/1.2.0+unknown]]" request.method=HEAD url="https://registry-1.docker.io/v2/docker/dockerfile/manifests/experimental"
time="2019-07-31T18:55:55Z" level=debug msg="fetch response received" response.headers="map[Content-Length:[2029] Content-Type:[application/vnd.docker.distribution.manifest.list.v2+json] Date:[Wed, 31 Jul 2019 18:55:55 GMT] Docker-Content-Digest:[sha256:9022e911101f01b2854c7a4b2c77f524b998891941da55208e71c0335e6e82c3] Docker-Distribution-Api-Version:[registry/2.0] Etag:[\"sha256:9022e911101f01b2854c7a4b2c77f524b998891941da55208e71c0335e6e82c3\"] Strict-Transport-Security:[max-age=31536000]]" status="200 OK" url="https://registry-1.docker.io/v2/docker/dockerfile/manifests/experimental"
time="2019-07-31T18:55:55Z" level=debug msg=resolved desc.digest="sha256:9022e911101f01b2854c7a4b2c77f524b998891941da55208e71c0335e6e82c3"
time="2019-07-31T18:55:55Z" level=debug msg=fetch digest="sha256:9022e911101f01b2854c7a4b2c77f524b998891941da55208e71c0335e6e82c3" mediatype=application/vnd.docker.distribution.manifest.list.v2+json size=2029
time="2019-07-31T18:55:55Z" level=debug msg=fetch digest="sha256:962337bd2c94ed20329caf3201963fd81d2892544c4502f1b237f5063e0fe27f" mediatype=application/vnd.docker.distribution.manifest.v2+json size=527
time="2019-07-31T18:55:55Z" level=debug msg=fetch digest="sha256:8bf79a4e725097175c47f89c7b1efffe300bb4fd4e9ac45eea9daba66f81e904" mediatype=application/vnd.docker.container.image.v1+json size=897
time="2019-07-31T18:55:55Z" level=debug msg="load cache for docker-image://docker.io/docker/dockerfile:experimental@sha256:9022e911101f01b2854c7a4b2c77f524b998891941da55208e71c0335e6e82c3 with 9ys7i6me1k7hns19i191htcky::sha256:d469e8fdff2f0208fb8c23b518279d9d73e5efc9e10be65e71942fc72c38e31a"
time="2019-07-31T18:55:55Z" level=debug msg="serving grpc connection"
time="2019-07-31T18:55:55Z" level=debug msg="> creating ja4kewo4za8zm8824biees2ld [/bin/dockerfile-frontend]"
time="2019-07-31T18:55:56Z" level=debug msg=resolving
time="2019-07-31T18:55:56Z" level=debug msg="do request" request.headers="map[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, *] User-Agent:[containerd/1.2.0+unknown]]" request.method=HEAD url="https://registry-1.docker.io/v2/library/python/manifests/3.6-alpine"
time="2019-07-31T18:55:56Z" level=debug msg="fetch response received" response.headers="map[Content-Length:[157] Content-Type:[application/json; charset=utf-8] Date:[Wed, 31 Jul 2019 18:55:56 GMT] Docker-Distribution-Api-Version:[registry/2.0] Strict-Transport-Security:[max-age=31536000] Www-Authenticate:[Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/python:pull\"]]" status="401 Unauthorized" url="https://registry-1.docker.io/v2/library/python/manifests/3.6-alpine"
time="2019-07-31T18:55:56Z" level=debug msg=Unauthorized header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/python:pull\""
time="2019-07-31T18:55:56Z" level=debug msg="do request" request.headers="map[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, *] User-Agent:[containerd/1.2.0+unknown]]" request.method=HEAD url="https://registry-1.docker.io/v2/library/python/manifests/3.6-alpine"
time="2019-07-31T18:55:56Z" level=debug msg="fetch response received" response.headers="map[Content-Length:[1645] Content-Type:[application/vnd.docker.distribution.manifest.list.v2+json] Date:[Wed, 31 Jul 2019 18:55:56 GMT] Docker-Content-Digest:[sha256:cea913d3f439c10cd67f274b7cb09bb76c8b167113c8339a5c201ee491716d55] Docker-Distribution-Api-Version:[registry/2.0] Etag:[\"sha256:cea913d3f439c10cd67f274b7cb09bb76c8b167113c8339a5c201ee491716d55\"] Strict-Transport-Security:[max-age=31536000]]" status="200 OK" url="https://registry-1.docker.io/v2/library/python/manifests/3.6-alpine"
time="2019-07-31T18:55:56Z" level=debug msg=resolved desc.digest="sha256:cea913d3f439c10cd67f274b7cb09bb76c8b167113c8339a5c201ee491716d55"
time="2019-07-31T18:55:56Z" level=debug msg=fetch digest="sha256:cea913d3f439c10cd67f274b7cb09bb76c8b167113c8339a5c201ee491716d55" mediatype=application/vnd.docker.distribution.manifest.list.v2+json size=1645
time="2019-07-31T18:55:56Z" level=debug msg=fetch digest="sha256:869690514dc569fbda884f6ee74fef8f602ac17d0dd369f661936a87747593f5" mediatype=application/vnd.docker.distribution.manifest.v2+json size=1368
time="2019-07-31T18:55:56Z" level=debug msg=fetch digest="sha256:dd987e41d7d970c82d5df98bd8914fcb620368aac8edfcb1ea7902dfe79d2419" mediatype=application/vnd.docker.container.image.v1+json size=7620
time="2019-07-31T18:55:56Z" level=debug msg="reusing ref for local: 4che3w9k9w56ltrti5mp4wl2j"
time="2019-07-31T18:55:56Z" level=debug msg="diffcopy took: 10.868491ms"
time="2019-07-31T18:55:56Z" level=debug msg="saved 4che3w9k9w56ltrti5mp4wl2j as local.sharedKey:context:context:"
time="2019-07-31T18:55:56Z" level=debug msg="load cache for [3/5] RUN --mount=type=cache,id=apk,sharing=locked,target=/var/cache/apk ln -vs /var/cache/apk /etc/apk/cache && \tapk add --update --virtual build-dependencies \tgcc \tbuild-base \tlibffi-dev \tlibressl-dev \tpostgresql-dev with 9ys7i6me1k7hns19i191htcky::1jb667nqcb5stxrdhz7ij42av"
time="2019-07-31T18:55:56Z" level=debug msg="reusing ref for cache dir: ga3mk0fht5ywu4omjqfhxfs1t"
time="2019-07-31T18:55:56Z" level=debug msg="> creating axgr1ai8l77m6usy1xwegp8ah [/bin/sh -c pip wheel -e .]"
time="2019-07-31T18:58:20Z" level=debug msg="session finished: <nil>"
time="2019-07-31T18:58:21Z" level=debug msg="remove snapshot" key=84r0ia7z8euguohd9tufpc3kp snapshotter=overlayfs
time="2019-07-31T18:58:21Z" level=debug msg="schedule snapshotter cleanup" snapshotter=overlayfs
time="2019-07-31T18:58:21Z" level=debug msg="removed snapshot" key=buildkit/1329/84r0ia7z8euguohd9tufpc3kp snapshotter=overlayfs
time="2019-07-31T18:58:21Z" level=debug msg="snapshot garbage collected" d=5.255037ms snapshotter=overlayfs
/usr/libexec/docker/cli-plugins/docker-buildx bake --progress plain -f .jenkins/docker-compose.images-base.1.yml -f .jenkins/buildx.images-base.1.yml
time="2019-07-31T18:55:55Z" level=warning msg="No output specified for docker-container driver. Build result will only remain in the build cache. To push result image into registry use --push or to load image into docker use --load"
#1 [internal] load .dockerignore
#1 transferring context: 71B done
#1 DONE 0.0s
#2 [internal] load build definition from buildx
#2 transferring dockerfile: 449B done
#2 DONE 0.0s
#3 resolve image config for docker.io/docker/dockerfile:experimental
time="2019-07-31T18:55:55Z" level=error msg="Error parsing the serverURL" error="docker-credential-ecr-login can only be used with Amazon Elastic Container Registry." serverURL="https://index.docker.io/v1/"
#3 DONE 0.7s
time="2019-07-31T18:55:56Z" level=error msg="Error parsing the serverURL" error="docker-credential-ecr-login can only be used with Amazon Elastic Container Registry." serverURL="https://index.docker.io/v1/"
#4 docker-image://docker.io/docker/dockerfile:experimental@sha256:9022e9111...
#4 resolve docker.io/docker/dockerfile:experimental@sha256:9022e911101f01b2854c7a4b2c77f524b998891941da55208e71c0335e6e82c3 done
#4 CACHED
#5 [internal] load metadata for docker.io/library/python:3.6-alpine
#5 DONE 0.3s
#6 [1/5] FROM docker.io/library/python:3.6-alpine@sha256:cea913d3f439c10cd6...
#6 resolve docker.io/library/python:3.6-alpine@sha256:cea913d3f439c10cd67f274b7cb09bb76c8b167113c8339a5c201ee491716d55 done
#6 DONE 0.0s
#9 [internal] load build context
#9 transferring context: 91.37kB 0.0s done
#9 DONE 0.0s
#7 [2/5] WORKDIR /src
#7 CACHED
#8 [3/5] RUN --mount=type=cache,id=apk,sharing=locked,target=/var/cache/apk...
#8 CACHED
#10 [4/5] COPY . /src/
#10 DONE 0.0s
#11 [5/5] RUN --mount=type=cache,id=wheel,sharing=locked,target=/root pip w...
#11 1.054 Obtaining file:///src
this is a docker-compose 1st run, no cache
this is a docker-compose 2nd run, fully cached
this is buildx/BuildKit 1st and 2nd run there is a lot of cache bust on the 2nd run
# syntax=docker/dockerfile:experimental
FROM python:3.6-alpine AS ms-python-wheel
WORKDIR /src
RUN --mount=type=cache,id=apk,sharing=locked,target=/var/cache/apk ln -vs /var/cache/apk /etc/apk/cache && \
apk add --update --virtual build-dependencies \
gcc \
build-base \
libffi-dev \
libressl-dev \
postgresql-dev
COPY . /src/
RUN --mount=type=cache,id=wheel,sharing=locked,target=/root \
pip wheel -e .
@FernandoMiguel from the output, you can see that COPY .
step is not cached. So something has changed in your build context. Keep in mind that hidden files/directories are part of the cache. If you can, it is better to specify the files to copy in.
@tiborvass yes I'm aware of the risks of using dot, and when possible avoid it. Sadly some applications are too complex to identify all required resources.
These are consequentive runs of the same commit id.
When using docker compose with a similar Dockerfile (minus the buildkit cache stuff) this very same build will be fully cached. Not only this, but the entire set of images and code base.
I would love to dig deeper and understand what is making a cache miss.
If you have any ideas, I would love to see BuildKit beat docker-compose 😊
@FernandoMiguel this still an issue?
@thaJeztah i no longer have access to the underlying code base to try to reproduce
.jenkins/buildx.images-base.1.yml
.jenkins/docker-compose.images-base.1.yml
this is the 2nd run, after cache has been created from a previous successful build