docker buildx build hangs when using some cached layers

[ojab]

buildx-0.5.1, moby/buildkit:buildx-stable-1 (be8e8392f56c), Docker version 20.10.5, build 55c4c88 on linux x86_64.

Unfortunately cannot provide a reproducer since it's an internal project.

docker buildx build --cache-from … --cache-to type=inline --pull . hangs on various steps indefinitely (or for a very long time, in GH Actions there was 6 hour timeout). buildkit container is started with docker buildx create --name builder-builder --driver docker-container --driver-opt image=moby/buildkit:buildx-stable-1 --buildkitd-flags --debug --use (setup is stolen from docker/setup-buildx-action@v1 GH action), logs after sending SIGQUIT is here. This time the hang was on

 => CACHED [… 11/13] RUN bundle exec bootsnap precompile --gemfile config/ app/ lib/                                  282.6s

[ojab]

buildkitd burning some cpu during this and perf top looks like

  12,10%  buildkitd        [.] cmpbody
  10,33%  buildkitd        [.] runtime.scanobject
  10,14%  buildkitd        [.] go.etcd.io/bbolt.(*Cursor).search
   7,89%  buildkitd        [.] runtime.findObject
   6,58%  buildkitd        [.] runtime.heapBitsSetType
   6,32%  buildkitd        [.] runtime.mallocgc
   3,45%  buildkitd        [.] sort.Search
   3,32%  buildkitd        [.] runtime.memmove
   2,38%  [kernel]         [k] read_hpet.part.0
   2,02%  buildkitd        [.] runtime.greyobject
   1,63%  buildkitd        [.] sync.(*RWMutex).Unlock
   1,54%  buildkitd        [.] go.etcd.io/bbolt.(*Cursor).searchPage.func1
   1,48%  buildkitd        [.] runtime.memclrNoHeapPointers
   1,38%  buildkitd        [.] runtime.growslice
   1,37%  buildkitd        [.] runtime.mapaccess2_fast64
   1,34%  buildkitd        [.] hash/fnv.(*sum64a).Write
   1,30%  buildkitd        [.] encoding/json.(*encodeState).string
   1,11%  buildkitd        [.] go.etcd.io/bbolt.(*Bucket).openBucket
   1,05%  buildkitd        [.] runtime.(*mspan).sweep
   1,03%  buildkitd        [.] go.etcd.io/bbolt.(*Cursor).nsearch.func2
   0,99%  buildkitd        [.] sync.(*RWMutex).Lock
   0,87%  buildkitd        [.] runtime.mapaccess2
   0,82%  buildkitd        [.] runtime.wbBufFlush1
   0,72%  buildkitd        [.] encoding/json.structEncoder.encode
   0,70%  buildkitd        [.] bytes.(*Buffer).WriteString
   0,68%  buildkitd        [.] github.com/moby/buildkit/solver.(*cacheManager).getID

[ojab]

And perf top -g, if that helps

  Children      Self  Shared Object     Symbol
+   75,62%     0,39%  buildkitd         [.] github.com/moby/buildkit/solver.(*cacheManager).ensurePersistentKey
+   68,22%     0,08%  buildkitd         [.] github.com/moby/buildkit/solver/bboltcachestorage.(*Store).HasLink
+   67,33%     0,28%  buildkitd         [.] go.etcd.io/bbolt.(*DB).View
+   59,37%     0,34%  buildkitd         [.] github.com/moby/buildkit/solver/bboltcachestorage.(*Store).HasLink.func1
+   39,27%     0,44%  buildkitd         [.] go.etcd.io/bbolt.(*Cursor).seek
+   38,38%     9,83%  buildkitd         [.] go.etcd.io/bbolt.(*Cursor).search
+   29,51%     0,52%  buildkitd         [.] go.etcd.io/bbolt.(*Cursor).searchPage
+   24,31%     0,33%  buildkitd         [.] go.etcd.io/bbolt.(*Bucket).Bucket
+   22,37%     0,07%  buildkitd         [.] runtime.systemstack
+   21,22%     0,17%  buildkitd         [.] runtime.gcDrain
+   21,22%     0,24%  buildkitd         [.] go.etcd.io/bbolt.(*Bucket).Get
+   19,76%    10,83%  buildkitd         [.] runtime.scanobject
+   17,86%     2,92%  buildkitd         [.] sort.Search
+   15,52%     7,50%  buildkitd         [.] runtime.mallocgc
+   11,83%    11,26%  buildkitd         [.] cmpbody
+    9,81%     0,00%  buildkitd         [.] runtime.goexit
+    9,51%     0,00%  buildkitd         [.] github.com/moby/buildkit/solver/internal/pipe.NewWithFunction.func2
+    9,51%     0,00%  buildkitd         [.] github.com/moby/buildkit/solver.(*edge).loadCache-fm
+    9,51%     0,00%  buildkitd         [.] github.com/moby/buildkit/solver.(*edge).loadCache
+    9,51%     0,00%  buildkitd         [.] github.com/moby/buildkit/solver.(*sharedOp).LoadCache
+    9,51%     0,00%  buildkitd         [.] github.com/moby/buildkit/solver.(*combinedCacheManager).Load
+    9,51%     0,00%  buildkitd         [.] github.com/moby/buildkit/solver.(*cacheManager).Save
+    9,00%     1,36%  buildkitd         [.] runtime.growslice
+    8,40%     0,46%  buildkitd         [.] encoding/json.Marshal
+    8,24%     0,32%  buildkitd         [.] go.etcd.io/bbolt.(*Cursor).nsearch
+    7,29%     6,73%  buildkitd         [.] runtime.findObject
+    6,21%     0,79%  buildkitd         [.] go.etcd.io/bbolt.(*DB).beginTx
+    6,16%     0,02%  buildkitd         [.] go.etcd.io/bbolt.(*DB).Begin
+    5,88%     0,09%  buildkitd         [.] encoding/json.(*encodeState).marshal
+    5,69%     0,31%  buildkitd         [.] runtime.newobject
+    5,42%     0,24%  buildkitd         [.] encoding/json.(*encodeState).reflectValue
+    4,98%     1,01%  buildkitd         [.] go.etcd.io/bbolt.(*Bucket).openBucket
+    4,68%     4,52%  buildkitd         [.] runtime.heapBitsSetType
+    3,98%     0,01%  buildkitd         [.] encoding/json.structEncoder.encode-fm
+    3,84%     0,67%  buildkitd         [.] encoding/json.structEncoder.encode
+    3,46%     0,49%  buildkitd         [.] go.etcd.io/bbolt.(*Tx).init

[ojab]

And I suppose this issue should be transferred to the https://github.com/moby/buildkit repo, hopefully you can do this. Will create an issue there otherwise.

[ojab]

Created moby/buildkit#2009