Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Multiple parallel docker build runs leak disk space that can't be recovered (with reproduction) #46136

Closed
intgr opened this issue Aug 1, 2023 · 18 comments · Fixed by #47523
Closed
Labels
area/builder/buildkit Issues affecting buildkit area/builder area/storage/overlay area/storage kind/bug Bugs are bugs. The cause may or may not be known at triage time so debugging may be needed. status/confirmed version/24.0

Comments

@intgr
Copy link

intgr commented Aug 1, 2023

Description

My CI machines, that run lots of docker build and docker run commands, often in parallel, keep running out of disk space.

I have figured out that when running multiple docker build commands in parallel, Docker loses track of some directories and files it creates under the /var/lib/docker/overlay2 directory. This issue does not occur when the "build" commands are run in sequence (e.g. remove the trailing & in repro.sh).

After the build, despite running docker system prune -af --volumes to delete all build cache/artifacts and using docker system df to verify that there should be no disk space in use, the size of Docker's overlay2 directory grows every time with no limit.

Reproduce

I have published a shell script and Dockerfile that systematically reproduces this issue at https://github.com/intgr/bug-reports/tree/main/docker-build-disk-space-leak

Run the ./repro.sh shell script multiple times and notice overlay2 directory increasing in size.

The script needs to run docker commands and uses sudo to monitor the size of the overlay2 directory.

It can be tested in the public playground https://labs.play-with-docker.com/ for example.

git clone https://github.com/intgr/bug-reports
cd bug-reports/docker-build-disk-space-leak
./repro.sh

Example output when running the script

Notice that the ACTUAL number of items and disk space keeps growing every time when running ./repro.sh, despite Docker reporting 0 bytes used.

$ ./repro.sh
BUILDING...
build done!

pruned everything. Docker THINKS this much disk space is in use:
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

ACTUAL disk space used: 7.4M	/var/lib/docker/overlay2            <-- !!!
ACTUAL number of items in /var/lib/docker/overlay2: 12              <-- !!!

$ ./repro.sh
BUILDING...
build done!

pruned everything. Docker THINKS this much disk space is in use:
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

ACTUAL disk space used: 7.5M	/var/lib/docker/overlay2            <-- !!!
ACTUAL number of items in /var/lib/docker/overlay2: 21              <-- !!!

$ ./repro.sh
BUILDING...
build done!

pruned everything. Docker THINKS this much disk space is in use:
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

ACTUAL disk space used: 7.6M	/var/lib/docker/overlay2            <-- !!!
ACTUAL number of items in /var/lib/docker/overlay2: 30              <-- !!!

Expected behavior

When I delete all containers, all images, volumes, caches, everything, then Docker disk usage should return back near to what it uses after a clean installation.

docker version

Client:
 Version:           24.0.2
 API version:       1.43
 Go version:        go1.20.4
 Git commit:        cb74dfc
 Built:             Thu May 25 21:50:49 2023
 OS/Arch:           linux/amd64
 Context:           default

Server: Docker Engine - Community
 Engine:
  Version:          24.0.2
  API version:      1.43 (minimum version 1.12)
  Go version:       go1.20.4
  Git commit:       659604f
  Built:            Thu May 25 21:35:04 2023
  OS/Arch:          linux/amd64
  Experimental:     true
 containerd:
  Version:          v1.7.1
  GitCommit:        1677a17964311325ed1c31e2c0a3589ce6d5c30d
 runc:
  Version:          1.1.7
  GitCommit:        v1.1.7-0-g860f061
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

docker info

Client:
 Version:    24.0.2
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  v0.10.5
    Path:     /usr/local/libexec/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  v2.18.1
    Path:     /usr/local/libexec/docker/cli-plugins/docker-compose

Server:
 Containers: 0
  Running: 0
  Paused: 0
  Stopped: 0
 Images: 0
 Server Version: 24.0.2
 Storage Driver: overlay2
  Backing Filesystem: xfs
  Supports d_type: true
  Using metacopy: false
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 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 io.containerd.runc.v2
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 1677a17964311325ed1c31e2c0a3589ce6d5c30d
 runc version: v1.1.7-0-g860f061
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: builtin
 Kernel Version: 4.4.0-210-generic
 Operating System: Alpine Linux v3.18 (containerized)
 OSType: linux
 Architecture: x86_64
 CPUs: 8
 Total Memory: 31.42GiB
 Name: node2
 ID: 39aba340-eb4a-4ddf-b7bf-f2a4d3a52192
 Docker Root Dir: /var/lib/docker
 Debug Mode: true
  File Descriptors: 27
  Goroutines: 43
  System Time: 2023-08-01T15:48:58.988555479Z
  EventsListeners: 0
 Experimental: true
 Insecure Registries:
  127.0.0.1
  127.0.0.0/8
 Live Restore Enabled: false
 Product License: Community Engine

WARNING: API is accessible on http://0.0.0.0:2375 without encryption.
         Access to the remote API is equivalent to root access on the host. Refer
         to the 'Docker daemon attack surface' section in the documentation for
         more information: https://docs.docker.com/go/attack-surface/
WARNING: No swap limit support
WARNING: bridge-nf-call-iptables is disabled
WARNING: bridge-nf-call-ip6tables is disabled

Additional Info

No response

@intgr intgr added kind/bug Bugs are bugs. The cause may or may not be known at triage time so debugging may be needed. status/0-triage labels Aug 1, 2023
@thaJeztah
Copy link
Member

Thanks for reporting; I'm indeed not sure if all would be directly related.

For some extra context; these builds are running with BuildKit enabled (so not the classic builder?)

@intgr
Copy link
Author

intgr commented Aug 2, 2023

For some extra context; these builds are running with BuildKit enabled (so not the classic builder?)

Yes, using BuildKit.

@thaJeztah thaJeztah added the area/builder/buildkit Issues affecting buildkit label Aug 2, 2023
@tonistiigi
Copy link
Member

I've confirmed this is the case. Reproduces in all recent Moby versions.

Does not reproduce with buildx+container driver.

@intgr
Copy link
Author

intgr commented Aug 18, 2023

As a workaround, I configured all affected machines to only run 1 CI job with no concurrency. Since then I have not experienced "leaking" disk space any more. A "docker system prune" cron job always cleans up everything.

@vvoland
Copy link
Contributor

vvoland commented Aug 21, 2023

I did play around with this one and noticed multiple of these in log:

DEBU[2023-08-21T10:40:11.613782880Z] not reusing ref xj6szckuxiojacjhkjym8tbdg for local: xj6szckuxiojacjhkjym8tbdg is locked: locked  span="[internal] load build context" spanID=9d17dfc87b325405 traceID=d628a28fb035fc265155e003304dedf9
DEBU[2023-08-21T10:40:11.613943255Z] not reusing ref xj6szckuxiojacjhkjym8tbdg for local: xj6szckuxiojacjhkjym8tbdg is locked: locked  span="[internal] load build context" spanID=a121d92e7b470196 traceID=fe0d8b72ec091c10a9cd0bbb2bd43dde

I tracked where this message comes from and did a dirty workaround with retry mechanism:

diff --git a/vendor/github.com/moby/buildkit/source/local/local.go b/vendor/github.com/moby/buildkit/source/local/local.go
index d2cd9d989c..f6a855d053 100644
--- a/vendor/github.com/moby/buildkit/source/local/local.go
+++ b/vendor/github.com/moby/buildkit/source/local/local.go
@@ -133,7 +133,13 @@ func (ls *localSourceHandler) snapshot(ctx context.Context, caller session.Calle
                return nil, err
        }
        for _, si := range sis {
-               if m, err := ls.cm.GetMutable(ctx, si.ID()); err == nil {
+               m, err := ls.cm.GetMutable(ctx, si.ID())
+               for err != nil && errors.Is(err, cache.ErrLocked) {
+                       m, err = ls.cm.GetMutable(ctx, si.ID())
+                       time.Sleep(time.Millisecond * 1)
+               }
+
+               if err == nil {
                        bklog.G(ctx).Debugf("reusing ref for local: %s", m.ID())
                        mutable = m
                        break

and it seems to resolve the issue. It's not a solution though because it seems to causes deadlock in subsequent ./repro.sh executions (but first one always finishes and doesn't leak any space).

Maybe the cache created here is not properly cleaned up later?
https://github.com/moby/buildkit/blob/832fdb5039b73992ee7e883e1322972373aeb5c1/source/local/local.go#L145-L152

I'm not very familiar with buildkit code, but maybe this can point @tonistiigi in the right direction?

@tonistiigi
Copy link
Member

@vvoland No, this shouldn't be related. Destination for local being locked is expected in parallel requests as it makes sure that one build does not overwrite the context files for another. The strategy is to just use a new directory when this happens instead of sleeping until the older build completes and releases its references.

@tonistiigi
Copy link
Member

I debugged this and the reason data leaks seems to be in incorrect reference count in the code path

_, err := s.opt.LayerStore.Release(l)
->
l.referenceCount--
where the referenceCount does not go to zero in moby layerstore.

It's not entirely clear to me yet why this is the case or why parallel builds affect this but after switching to #45966 to make sure I don't make changes in old version the issue does not reproduce anymore and I can track the referenceCount going zero as expected.

So #45966 fixes this issue. If there is a desire to understand the case in other versions better I can look more into it. My best guess is that it is related to the namespace changes in v0.12.

cc @neersighted

@flozzone
Copy link

Could it be that buildkitd when building multiple layers in parallel that have common layers like in the repro from @intgr, layers will be rebuilt because of

DEBU[2023-08-21T10:40:11.613782880Z] not reusing ref xj6szckuxiojacjhkjym8tbdg for local: xj6szckuxiojacjhkjym8tbdg is locked: locked  span="[internal] load build context" spanID=9d17dfc87b325405 traceID=d628a28fb035fc265155e003304dedf9
DEBU[2023-08-21T10:40:11.613943255Z] not reusing ref xj6szckuxiojacjhkjym8tbdg for local: xj6szckuxiojacjhkjym8tbdg is locked: locked  span="[internal] load build context" spanID=a121d92e7b470196 traceID=fe0d8b72ec091c10a9cd0bbb2bd43dde

which are then not reference counted and thus leaking storage?

I am asking because I am experiencing the issue that common layers get rebuilt "randomly", even though everything is cached using registry and seeing a lot of not reusing ref XX for local: XX.

@tonistiigi When common layers are locked, is it supposed to just rebuild that layer instead of waiting for it to get unlocked?

@tonistiigi
Copy link
Member

When common layers are locked, is it supposed to just rebuild that layer instead of waiting for it to get unlocked?

Yes. Also this is not a layer but a destination directory for context upload. If you are debugging this issue then try #45966 per #46136 (comment)

@thaJeztah
Copy link
Member

@tonistiigi fix is part of buildkit v0.12, so will be in moby v25.0, correct? Or is there a fix that can be backported to v0.11 that you know of?

@tonistiigi
Copy link
Member

Only v0.12 afaik

@darintay
Copy link

darintay commented Mar 7, 2024

I'm still seeing this exact issue with docker 25 / buildkit 0.12, using the repro script from the original post.

Docker thinks everything is pruned, but overlay2 keeps growing almost every time I run the script. Only occurs if builds are run in parallel.

Docker version

$ docker --version
Docker version 25.0.3, build 4debf41
$ docker builder version
github.com/docker/buildx v0.12.1 30feaa1

Initial State:

docker system df
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

$ du -hs /var/lib/docker/overlay2
4.0K     /var/lib/docker/overlay2

After several runs of the script, with parallel disabled:

pruned everything. Docker THINKS this much disk space is in use:
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

ACTUAL disk space used: 8.0K    /var/lib/docker/overlay2
ACTUAL number of items in /var/lib/docker/overlay2: 1

After several runs of the script, with parallel enabled:

pruned everything. Docker THINKS this much disk space is in use:
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

ACTUAL disk space used: 14M     /var/lib/docker/overlay2
ACTUAL number of items in /var/lib/docker/overlay2: 155

Not sure about etiquette here, if I'm supposed to open a new issue or just post to this one, but it doesn't seem like it is actually fixed in docker 25 / buildkit 0.12.

@intgr
Copy link
Author

intgr commented Mar 7, 2024

Looks like another fix was applied for this issue and will be part of the next release.

@tonistiigi
Copy link
Member

@darintay Please test again with 26.0.0-rc.2

@mirekphd
Copy link

mirekphd commented Apr 9, 2024

@darintay Please test again with 26.0.0-rc.2

Did not seem to help. I'm using Docker version 26.0.0, build 2ae903e, and have to purge /var/lib/docker/ every 3 days, because it exhausts 3 TB storage on the build server building containers for the latestml namespace on Docker Hub... there are roughly 40 Jenkins pipelines building / updating ML containers every 4 hours (allowing for parallel builds at the entire Jenkins level, but not at each pipeline level), and Docker leaves 10-20 GB in hundreds of thousands of files per hour in the diff subfolders of /var/lib/docker/overlay2/<hash>/diff/* You can purge all images using various docker commands down to zero usage reported by docker system df and still the actual space usage (as shown by df) of /var/lib/docker/overlay2/ would be 3.3 TB (leaving zero free space on the partition).

This change is a recent one: I've doubled the images build frequency to every 4 hours as a first naive workaround on March 23. Prior to that I've been running these builds without problems (with two weeks, not just two days retention) for a few years.

@darintay
Copy link

darintay commented Apr 9, 2024

I reran @intgr's script from the original post with Docker 25.0.5, which contained the fix (https://github.com/moby/moby/releases/tag/v25.0.5)

The issue no longer reproduced.

As for a more real-world repro, my parallel builder machine is much happier since the upgrade - I haven't had a chance to prune to 0 recently to inspect it, but if it is still leaking, it is an order of magnitude less than previously.

@intgr
Copy link
Author

intgr commented Apr 9, 2024

@mirekphd Can you reproduce the leak in your setup with the script provided in the original issue post? If not, you're probably hitting a different bug that also leaks disk space. In which case I can only suggest to try to boil down your Docker build into a minimal reproduction, like I did, and report it as a new issue.

Without a repro, unfortunately probably nothing will be done, like all the other non-specific issues listed here: #46136 (comment)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/builder/buildkit Issues affecting buildkit area/builder area/storage/overlay area/storage kind/bug Bugs are bugs. The cause may or may not be known at triage time so debugging may be needed. status/confirmed version/24.0
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants