buildkit
buildkit copied to clipboard
moby
GitHub cache exporter (`type=gha`) hangs reletively low number of cache reads/writes, satirating api limits/triggering throttling.
Behaviour
Cache operations using type=gha will start hanging after a relavatively low number of cache reads/writes.
We are a small team (5 devs) and are hitting these limits constantly on our main repository. Not exactly high throughput.
I'm unsure if using docker/build-push-action with cache type=gha is even viable, even for small teams.
Steps to reproduce this issue
- Reproducing behaviour exibited here: https://github.com/bendavies/docker-build-cache-limits
- First build: https://github.com/bendavies/docker-build-cache-limits/actions/runs/2155495185/attempts/1
- Second build: https://github.com/bendavies/docker-build-cache-limits/actions/runs/2155495185/attempts/2
The second build should be lightening quick as the cache is fully primed, but takes forever because I think we have exhausted some limits of the GitHub Cache API, and are being throttled.
Cache reads and writes go towards saturating the limit, and both are affected by this throttling.
@dhadka mentions there is a limit of about "150 cache requests in 5 minutes", and seems about right: https://github.com/moby/buildkit/issues/2276#issuecomment-903970447
Expected behaviour
I don't know, but the current behaviour of hanging is not great. there is no feedback as to what is hanging resulting in the user just being confused.
Can cache reads/writes be batched or can they only read/write a single item at time?
If this is not solvable with more efficient caching, a user configured timeout might be better, as waiting 10+ minutes for the cache to start responding is far worse than having a 1 minute timeout.
Actual behaviour
Hangs for an undetermined amount of time.
Configuration
https://github.com/bendavies/docker-build-cache-limits/
Logs
build-1-logs.zip build-2-logs.zip
Related issues
https://github.com/moby/buildkit/issues/2276 https://github.com/moby/buildkit/issues/2492
@dhadka this may be relevant to you? can anything be done in the backend here?
Thanks for the ping. Adding in @vsvipul as the current maintainer for caching.
If I'm understanding the issue correctly, it sounds like the cache server is rate limiting on reads due to the large number of layers. This Docker action is then retrying and either takes a long time until the server starts allowing requests or reaches the timeout?
I think:
-
We can definitely look into increasing the read throttling limits on the server side. @vsvipul can you please look into this?
-
Even after increasing limits on the backend, it won't really "solve" this issue as a repo with more throughput (either more frequent Actions runs or more Docker layers) would just hit the new threshold. Assuming I'm right about retries causing the delays you're seeing, I wonder if there should be some configurable timeout or fail-fast option to give up and just build the layer?
@bendavies If you have time, could you please also enable step debug logging and re-run your test workflow? That will hopefully provide a bit more info on what's happening.
@dhadka thanks for the reply and attention. step debug logging enabled for (although it doesn't provide much more info here) run 3: https://github.com/bendavies/docker-build-cache-limits/actions/runs/2155495185/attempts/3 run 4: https://github.com/bendavies/docker-build-cache-limits/actions/runs/2155495185/attempts/4
run 3 was very slow - I haven't ran this since yesterday so that is surprising. Maybe hitting read limits already?
note that docker/setup-buildx-action was already configured with buildkitd-flags: --debug so the buildkit logs will be in the Post Install Build X step, where you can see the cache/read write requests.
Pinging @t-dedah as he recently worked on such limits. I'll also take a look over the read throttling limits on server side with @t-dedah.
Actually, looking at our telemetry, I'm not seeing any throttling for that repo. No 429 or 5xx-s that would indicate the server is failing or rejecting requests.
| Response Code | Count | Average Time (ms) |
|---|---|---|
| 200 | 2456 | 16.0 |
| 201 | 10 | 45.5 |
| 204 | 26 | 125.3 |
Basically, 200 are cache hits, 201 is creating a new cache, and I think 204 is a cache miss. That also shows the average time to process the requests, in milliseconds.
(Those times do not include the time to download the cache content. Unfortunately I don't have visibility into those numbers. I wonder how hard it would be to add some tracing in buildkit's output to show the time per request.)
Looking in the container logs (thanks for the tip where to find those in the output!), I see a few spots where there are large jumps in time:
time="2022-04-13T14:49:08Z" level=debug msg="load cache for [base 201/201] RUN echo \"200\" with sha256:54318f6f98ddd5ffe1360e59cd8b56025bd409de45b94ad75a82c5d1964f7a35"
time="2022-04-13T14:49:08Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/OYuy7ktCJCrKo7GrnZA7PHvQxGqaIisYcsp0ofZMuqXUjyWoyA/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-13T14:49:08Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/OYuy7ktCJCrKo7GrnZA7PHvQxGqaIisYcsp0ofZMuqXUjyWoyA/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ae0b25ef516347a097d75f8aea6bc0f42a4e8e70b057e84d85098d51f96d458f9&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-13T14:50:01Z" level=debug msg="remove snapshot" key=q2vrmytahiiqdaza868lelekl snapshotter=overlayfs
time="2022-04-13T14:50:01Z" level=debug msg="schedule snapshotter cleanup" snapshotter=overlayfs
time="2022-04-13T14:50:01Z" level=debug msg="removed snapshot" key=buildkit/5/q2vrmytahiiqdaza868lelekl snapshotter=overlayfs
time="2022-04-13T14:50:01Z" level=debug msg="snapshot garbage collected" d="868.312µs" snapshotter=overlayfs
time="2022-04-13T14:51:03Z" level=debug msg="remove snapshot" key=it6jwupezf54d78fyeukzkl2j snapshotter=overlayfs
time="2022-04-13T14:51:03Z" level=debug msg="schedule snapshotter cleanup" snapshotter=overlayfs
time="2022-04-13T14:51:03Z" level=debug msg="removed snapshot" key=buildkit/6/it6jwupezf54d78fyeukzkl2j snapshotter=overlayfs
time="2022-04-13T14:51:03Z" level=debug msg="snapshot garbage collected" d="941.014µs" snapshotter=overlayfs
time="2022-04-13T14:53:40Z" level=debug msg=push digest="sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1" mediatype=application/vnd.docker.image.rootfs.diff.tar.gzip size=32
time="2022-04-13T14:53:40Z" level=debug msg="checking and pushing to" digest="sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1" mediatype=application/vnd.docker.image.rootfs.diff.tar.gzip size=32 url="https://ghcr.io/v2/bendavies/docker-build-cache-limits
time="2022-04-13T14:53:41Z" level=debug msg="fetch response received" digest="sha256:ae406f3017a6d06fe2c15a4ef60df769b1f38cb40c4910f468cd08e7b5af6b32" mediatype=application/vnd.docker.distribution.manifest.v2+json response.header.content-length=83136 response.header.content-type=application/vnd.docker.distribution.manifest.v2+json response.header.date="Wed, 13 Apr 2022 14:53:41 GMT" response.header.docker-content-digest="sha256:ae406f3017a6d06fe2c15a4ef60df769b1f38cb40c4910f468cd08e7b5af6b32" response.header.docker-distribution-api-version=registry/2.0 response.header.etag="\"sha256:ae406f3017a6d06fe2c15a4ef60df769b1f38cb40c4910f468cd08e7b5af6b32\"" response.header.x-github-request-id="07C2:69E7:C4FE3:38670C:6256E3F4" response.status="200 OK" size=83136 url="https://ghcr.io/v2/bendavies/docker-build-cache-limits/manifests/prod"
time="2022-04-13T14:56:41Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/OYuy7ktCJCrKo7GrnZA7PHvQxGqaIisYcsp0ofZMuqXUjyWoyA/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
Given that only your first attempt was fast and the three subsequent ones were slow, that leads me to believe it's related to having cache hits. But unclear if it's caused by downloading the cache content, overhead in buildkit processing cache content, etc.
good spot @dhadka
the slow step in those runs is preparing build cache for export which correlates to the remove snapshot and following lines in the buildkit logs that you've posted.
could you specualte why this may be @tonistiigi ?
btw, just pushed a cache busting commit: https://github.com/bendavies/docker-build-cache-limits/actions/runs/2163336573
(the build was quicker, but still very slow.)
and there are some real long delays for:
- fetching manifest
- between 2 cache fetches (if i'm reading this correctly):
time="2022-04-13T19:31:53Z" level=debug msg="do request" digest="sha256:71f3e9d96a6db5e6de64b0b96fe8e2829f29ad4870caf30cf12565dd159e8695" mediatype=application/vnd.docker.distribution.manifest.v2+json request.header.content-type=application/vnd.docker.distribution.manifest.v2+json request.header.user-agent=buildkit/v0.10 request.method=PUT size=83342 url="https://ghcr.io/v2/bendavies/docker-build-cache-limits/manifests/prod"
time="2022-04-13T19:31:57Z" level=debug msg="fetch response received" digest="sha256:71f3e9d96a6db5e6de64b0b96fe8e2829f29ad4870caf30cf12565dd159e8695" mediatype=application/vnd.docker.distribution.manifest.v2+json response.header.content-length=0 response.header.content-type=application/json response.header.date="Wed, 13 Apr 2022 19:31:57 GMT" response.header.docker-content-digest="sha256:71f3e9d96a6db5e6de64b0b96fe8e2829f29ad4870caf30cf12565dd159e8695" response.header.docker-distribution-api-version=registry/2.0 response.header.location="/v2/bendavies/docker-build-cache-limits/manifests/sha256:71f3e9d96a6db5e6de64b0b96fe8e2829f29ad4870caf30cf12565dd159e8695" response.header.x-github-request-id="0781:780E:AA702:39C871:62572529" response.status="201 Created" size=83342 url="https://ghcr.io/v2/bendavies/docker-build-cache-limits/manifests/prod"
time="2022-04-13T19:32:07Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/OYuy7ktCJCrKo7GrnZA7PHvQxGqaIisYcsp0ofZMuqXUjyWoyA/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-13T19:32:07Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/OYuy7ktCJCrKo7GrnZA7PHvQxGqaIisYcsp0ofZMuqXUjyWoyA/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ae0b25ef516347a097d75f8aea6bc0f42a4e8e70b057e84d85098d51f96d458f9&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-13T19:33:38Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/OYuy7ktCJCrKo7GrnZA7PHvQxGqaIisYcsp0ofZMuqXUjyWoyA/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
It seems very difficult to actually determine what is actually slow, as you've noted
i should also note that, to work around this, we have currently commented out the cache-to option on all our image builds.
This "works", i.e. we don't get hangs any more, so it does seem something relating to cache writing.
Yeah, that seems to match what we're seeing. 2 calls at 19:32:07 and then a bunch a minute later:
Here's some more details of the individual requests happening in this window (I cut out 400 some identical records in the middle). There's actually no Cache Misses during that delay...it's not until the end when it creates a new index does it upload something.
| PreciseTimeStamp | Result | Key | CacheId | CacheCreated | CacheFileSize |
|---|---|---|---|---|---|
| 2022-04-13 19:32:07.3594991 | CacheHit | buildkit-blob-1-sha256:e0b25ef516347a097d75f8aea6bc0f42a4e8e70b057e84d85098d51f96d458f9 | 2 | 2022-04-12 14:08:52.4933333 | 28566292 |
| 2022-04-13 19:32:07.3611074 | CacheHit | buildkit-blob-1-sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1 | 1 | 2022-04-12 14:08:48.9533333 | 32 |
| 2022-04-13 19:33:38.1881719 | CacheHit | buildkit-blob-1-sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1 | 1 | 2022-04-12 14:08:48.9533333 | 32 |
| 2022-04-13 19:33:38.2132073 | CacheHit | buildkit-blob-1-sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1 | 1 | 2022-04-12 14:08:48.9533333 | 32 |
| 2022-04-13 19:33:38.2967912 | CacheHit | buildkit-blob-1-sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1 | 1 | 2022-04-12 14:08:48.9533333 | 32 |
| ... | ... | ... | ... | ... | ... |
| 2022-04-13 19:33:47.2588487 | CacheHit | buildkit-blob-1-sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1 | 1 | 2022-04-12 14:08:48.9533333 | 32 |
| 2022-04-13 19:33:47.2792441 | CacheHit | buildkit-blob-1-sha256:e0b25ef516347a097d75f8aea6bc0f42a4e8e70b057e84d85098d51f96d458f9 | 2 | 2022-04-12 14:08:52.4933333 | 28566292 |
| 2022-04-13 19:33:47.2994170 | CacheHit | index-prod-1-f921bd05# | 13 | 2022-04-13 19:30:53.2266667 | 191237 |
| 2022-04-13 19:33:47.3201577 | CacheHit | index-prod-1-f921bd05# | 13 | 2022-04-13 19:30:53.2266667 | 191237 |
| 2022-04-13 19:33:47.3480491 | CacheReserve | index-prod-1-f921bd05#6 | 14 | ||
| 2022-04-13 19:33:47.4077903 | CacheChunkUpload | 14 | |||
| 2022-04-13 19:33:47.5154529 | CacheSeal | 14 | 192279 |
I know there are some non-linear complexity issues on loading big layer chains that we have not prioritized because they should be impractical. I don't know if this is currently in effect as looks like the current problem might be on exporting side. Not sure if layers being identical in this case plays a role as well. 400 layers on top of each other definitely isn't normal (note, this does not mean size of the build graph where buildkit easily handles 1000s of build steps). The historical Docker limit was 127.
If it isn't related to GHA requests then it should show on type=local cache as well that might be easier to debug. All remote cache methods share 90% of the code. If it does then the question is if it shows in some more practical workloads as well.
@tonistiigi I did 400 layers as i was trying to reproduce the cache throttling behaviour that I thought we were seeing in our main private repo.
We are seeing the same behaviour that private repo with an image build with 96 layers (in docker history, docker inpect shows 40) (I can see some opportunity to reduce this).
here is an example build logs from that private repo:
docker/build-and-push logs:
Tue, 12 Apr 2022 11:37:32 GMT #73 exporting cache
Tue, 12 Apr 2022 11:37:32 GMT #73 preparing build cache for export
Tue, 12 Apr 2022 11:37:35 GMT #73 preparing build cache for export 2.6s done
Tue, 12 Apr 2022 11:42:45 GMT #73 writing layer sha256:f9191a2e65382f7ae88837aa687bce4f0e9d3ee44a4981dcfe4385846185fb02
Tue, 12 Apr 2022 11:42:47 GMT #73 writing layer sha256:f9191a2e65382f7ae88837aa687bce4f0e9d3ee44a4981dcfe4385846185fb02 2.0s done
Tue, 12 Apr 2022 11:42:48 GMT #73 DONE 315.8s
buildkit logs from the same time period with delays highlighted:
time="2022-04-12T11:37:35Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A1044a25c383c42707a9d19e10297c61bdaabefdfdf0a400597446b444dfe0b8c&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:37:35Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A59bf1c3509f33515622619af21ed55bbe26d24913cedbca106468a5fb37a50c3&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:37:35Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A7c7da25b2876b1c935b05d7e6efa3e8cd559d031cf30b246d7659ed438726acd&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
... 170 more load cache lines
time="2022-04-12T11:37:48Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Aa160f46fcb3d1d7bb00f7afa9ac4443399526171fba6c8c967e7a19c4ab9bb41&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
BIG DELAY HERE
time="2022-04-12T11:38:24Z" level=debug msg="remove snapshot" key=66sd5fqo8hyqjfu25mlc668ym snapshotter=overlayfs
time="2022-04-12T11:38:24Z" level=debug msg="schedule snapshotter cleanup" snapshotter=overlayfs
time="2022-04-12T11:38:24Z" level=debug msg="removed snapshot" key=buildkit/160/66sd5fqo8hyqjfu25mlc668ym snapshotter=overlayfs
time="2022-04-12T11:38:24Z" level=debug msg="snapshot garbage collected" d=2.956052ms snapshotter=overlayfs
time="2022-04-12T11:39:56Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Aa33d4fa436fd42f67efa89a3619806565b425044c6806c563d070887e1760241&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:39:59Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Aa35fb614082db35b154c2130de41d365b7c3a67821ca9795f07f864b55c16683&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:40:02Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Aa71634c55d292856f6a48a5984ff4aa7e244f2e82083e1279aa5af8a7da5819f&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:40:02Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ab24eae34319fd6f832b1c9692e68271405435ffb89981e888918b29d7ced9a12&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:40:02Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ab24eae34319fd6f832b1c9692e68271405435ffb89981e888918b29d7ced9a12&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:40:04Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Aba0cacf811e3083651bcd86de5b3e0401d5e8893d1f598aae46f24eb012c7998&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:40:19Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Abb24db17f7d047f090da8eee159f5c4e232b28fd0938eef2c71095ec03818641&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:40:34Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ac9232c3f65a9bc1e500d72d5976544d26ce72e1115c3f8dc27a93fc58eb8b852&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:40:35Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Acf470f313c90fc100680f3cc6c7ec99a536700e1d7fee3e9a153a6591c8f467e&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:40:36Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad012027468623b67eb05dc327f4a5b34222c5b4f250d9cff7dff9e00af562e7e&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
BIG DELAY HERE
time="2022-04-12T11:42:43Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad012027468623b67eb05dc327f4a5b34222c5b4f250d9cff7dff9e00af562e7e&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:43Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad343c65aeab0c5b4f83a57d3b24980f9b5a0c86c971f1f06015455a6d9a0e9d8&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:43Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad343c65aeab0c5b4f83a57d3b24980f9b5a0c86c971f1f06015455a6d9a0e9d8&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:43Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad404aec325b35205c6808a692be5849c765bb875928277f46df4cae3f0876aa5&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:44Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad404aec325b35205c6808a692be5849c765bb875928277f46df4cae3f0876aa5&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:44Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad4f70e52c6794af5f210175517eaea18df74c5b1e0c349b928772659b27bf86e&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:44Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad5636aa350438a52bdbbe097f9fb0d39ac4b8f20e279bff59bd991ad30ab3ffd&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:44Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Adb0297103cafedcccec656018f92155e6bb9cad2e6210b39cf5eac2170f08d41&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:44Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Add60f02c52911dafa35489838dd4ed7ae27db4b6a6df59ed29052c1b37da2233&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:44Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Adf9b9388f04ad6279a7410b85cedfdcb2208c0a003da7ab5613af71079148139&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:44Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ae596fa3ddc015cf3c3dc820fdc068c333ae1cc7e44fcbe762669b68b4a0e622f&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:44Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ae79a999588a86a12c441e4b27869202ca527215cbc7d41a36162b1eb4aa02951&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:44Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ae7c96db7181be991f19a9fb6975cdbbd73c65f4a2681348e63a141a2192a5f10&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:44Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Aea31e28140126c8e117f40993a82b3193b42c2e40dd21be3601cb00ef7d8cef3&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:45Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Aebdc23d5b7d146b7e673cba24d36b317af44ebcf43b275e58f3aae21473b7d3c&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:45Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Aebdc23d5b7d146b7e673cba24d36b317af44ebcf43b275e58f3aae21473b7d3c&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:45Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Af25209966669ce7b4a6a3bf425d4e36aba6306c1300e7cddcccf2b43e28feeff&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:45Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Af25209966669ce7b4a6a3bf425d4e36aba6306c1300e7cddcccf2b43e28feeff&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:45Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Af9191a2e65382f7ae88837aa687bce4f0e9d3ee44a4981dcfe4385846185fb02&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:45Z" level=debug msg="save cache req https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/caches body={\"key\":\"buildkit-blob-1-sha256:f9191a2e65382f7ae88837aa687bce4f0e9d3ee44a4981dcfe4385846185fb02\",\"version\":\"693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2\"}"
time="2022-04-12T11:42:45Z" level=debug msg="save cache resp: {\"cacheId\":44153}"
time="2022-04-12T11:42:45Z" level=debug msg="upload cache chunk https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/caches/44153, range 0-13833373"
time="2022-04-12T11:42:47Z" level=debug msg="commit cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/caches/44153, size 13833374"
time="2022-04-12T11:42:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Afaff432e5fc2807d9bc412fe86c2d3e65311c62433583447f9d70967ce9f30b3&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Afc27f066d4d5848ab583e6256957815b31560c7ac9adb00fafc5fe2d466476be&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Afc27f066d4d5848ab583e6256957815b31560c7ac9adb00fafc5fe2d466476be&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Afecd67e01344bdc1f7eb9e943f2b78a1d23977e4861800993245cca11194f380&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Afecd67e01344bdc1f7eb9e943f2b78a1d23977e4861800993245cca11194f380&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=index-nginx-1-a780633b%23&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:42:47Z" level=debug msg="save cache req https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/caches body={\"key\":\"index-nginx-1-a780633b#1\",\"version\":\"693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2\"}"
time="2022-04-12T11:42:48Z" level=debug msg="save cache resp: {\"cacheId\":44154}"
time="2022-04-12T11:42:48Z" level=debug msg="upload cache chunk https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/caches/44154, range 0-108697"
time="2022-04-12T11:42:48Z" level=debug msg="commit cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/caches/44154, size 108698"
time="2022-04-12T11:42:48Z" level=debug msg="session finished: <nil>"
@dhadka if you want to take a look at your telemetry, the job is here: https://github.com/owsy/bindhq-webapp/runs/5989075683
another really long delay in the same job:
docker/build-and-push logs:
2022-04-12T11:32:09.8431241Z #15 importing cache manifest from gha:1241927905649341978
2022-04-12T11:35:47.8803590Z #15 DONE 259.0s
buildkit logs for roughly the same timestamp:
time="2022-04-12T11:31:29Z" level=debug msg=fetch digest="sha256:b50fc4ab93d035ae8c48b51fd7ef92d6363e9bf95710d40ccdfa4a867076030d" mediatype=application/vnd.docker.container.image.v1+json size=14459
time="2022-04-12T11:32:14Z" level=debug msg="remove snapshot" key=wsf1xiika1x3udsdokbf6ux86 snapshotter=overlayfs
time="2022-04-12T11:32:14Z" level=debug msg="schedule snapshotter cleanup" snapshotter=overlayfs
time="2022-04-12T11:32:14Z" level=debug msg="removed snapshot" key=buildkit/5/wsf1xiika1x3udsdokbf6ux86 snapshotter=overlayfs
time="2022-04-12T11:32:14Z" level=debug msg="snapshot garbage collected" d=1.1643ms snapshotter=overlayfs
time="2022-04-12T11:35:47Z" level=debug msg="load cache for copy /bin /srv/app/bin/ with sha256:eaebdeb6bf54a36eb047f4560bfed7c879962aeb42b3b866f48090f2a34ab5b8"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Aebdc23d5b7d146b7e673cba24d36b317af44ebcf43b275e58f3aae21473b7d3c&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache for copy /templates /srv/app/templates/ with sha256:63d9cbafc8c61a83ab78d4de2a46894849c6571b70a170197087d1b931d2569c"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A4c34b1bc3ea0b3f6bf7637883d0d0e186b7521f8578a36e32a1b2794f5096efa&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache for copy /config /srv/app/config/ with sha256:f417c59d016c681df219a8fe7006c2af352b3a192a96bd655ec2ad14f7bacc55"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad012027468623b67eb05dc327f4a5b34222c5b4f250d9cff7dff9e00af562e7e&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache for copy /translations /srv/app/translations/ with sha256:968f4cac3fcaa7da248725fd4eb67f1401ed86a9dbfca3ee43ab23ca999eb247"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A428201cb534aaa1d597ebcc2de47a5cd767c986970b704b513dbfc979392af7a&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache for copy /migrations /srv/app/migrations/ with sha256:9cde55ee25904748b973b111694b8780acfde46024b131333389706227c2881f"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A239527ba7c4a4fa1cad33fc07fc560422a245f1a2dd2d2a699f3b0096ffc8d46&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache for copy /docker/php/gruntkms_linux_amd64 /usr/local/bin/gruntkms with sha256:dafc0e753d4f3b29fd8644534f2bf35ea65a6c1548d62adde9c6d4a92e4f4555"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A916e50832cf360c385bdb7d15daf5c2b01d60cc7bfe2addf49a37bbc6c9fec47&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache for copy /public /srv/app/public/ with sha256:00e1e1b653749f0dfa7f89535a6134b935f0b1b744419294b07e88aa7930d11a"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A40a9c48c1787361fd83c96f2e33115d5e8dd9bb889da93d647ceff9ceef4242f&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache for copy /docker/bin/ecs-console /srv/app/bin/ecs-console with sha256:ad0ebc67a14d08769bbbcb6ddd493aefce24296a95ff8554e01370607c1cb41d"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A42a5762ee696794409481a81eaaf8821e54beb50bf3c3837f7dbb9a78f215cf8&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache for copy /docker/php/docker-entrypoint.sh /usr/local/bin/docker-entrypoint with sha256:90452c9ea205944e06e56302104552118f8dec8972860a9b8d228e3579652c5f"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ab24eae34319fd6f832b1c9692e68271405435ffb89981e888918b29d7ced9a12&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache for copy /docker/php/conf.d/*.ini.template /usr/local/etc/php/conf.d/ with sha256:fcc6299e24cf406266ec41abbb270c34272c11e550450167ddc65439347ee447"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A380ba4b233b98398459de8ec54202c21337dba6cb619bf9a4b49dd46d9c4efe0&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache for copy /docker/php/fpm/conf.d/*.conf.template /usr/local/etc/php-fpm.d/ with sha256:53fd5d148dd8a267b67df8bdfd653a4c440880b342e5d872c11066f94e2c9ce2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A53e21c35da50d060066d90460be4441a46c971f95ca738ff8991c3247ce1327f&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache for [encore-build-production 21/21] RUN --mount=type=cache,target=/root/.yarn,id=yarn --mount=source=package.json,target=package.json --mount=source=webpack.config.js,target=webpack.config.js --mount=source=yarn.lock,target=yarn.lock yarn encore production with sha256:30673ab343efe77262a47437da61b610aacdda9a67af0e88b573785473046855"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Add60f02c52911dafa35489838dd4ed7ae27db4b6a6df59ed29052c1b37da2233&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Adf9b9388f04ad6279a7410b85cedfdcb2208c0a003da7ab5613af71079148139&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad5636aa350438a52bdbbe097f9fb0d39ac4b8f20e279bff59bd991ad30ab3ffd&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Aa35fb614082db35b154c2130de41d365b7c3a67821ca9795f07f864b55c16683&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A14e16d3b67f2aaeb896ab59ae07e6754c70dac758eabaacd506d5400577b5d7f&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad4f70e52c6794af5f210175517eaea18df74c5b1e0c349b928772659b27bf86e&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Acf470f313c90fc100680f3cc6c7ec99a536700e1d7fee3e9a153a6591c8f467e&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A9fe4c0e12b908f307a4711f693a3a82bccc496b6f7e3f239bc50a359ccedce69&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A15e1303265b539194de30f286256393af9511fe2aea8e7f149f589103ecf92c8&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Aba0cacf811e3083651bcd86de5b3e0401d5e8893d1f598aae46f24eb012c7998&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A8af5ded66fae5329db4466e7aeba08d187dc3127ac0431e42fe8401a646bcfa1&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A17c37096cc2d8596417bbd4fcf19350154ad7d8ad20c3851e28112f8e12d1b6b&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A573756353b707382996e1fd42008039c0468e90aeb415f92f393cd06d3b07bbe&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A148cece67cdbdc5345404c666d95df9556c470620399095cc90aad0ccae2e5aa&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A60f365d7c97aff5841f86a5664d47f4d0a5657e25ea1bfc57653514112b78ad1&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A9a6137028f2193fca3d3dc132a8873c397831e0729ff0300adb129bb2daed577&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ae596fa3ddc015cf3c3dc820fdc068c333ae1cc7e44fcbe762669b68b4a0e622f&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A6a945c44151b163af9a4f86e87c6353cb51131d4cfe23e8fcc46c66682b216aa&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A62d7a848c15a7aa8ef310a53f6332dac861690d57843ef008dc11157a4c64126&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A71de9e94fc2affffa16ffd8355788b569f9da6b93089485c8feb6b9019144e15&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3A61976d0b00aabec047dbe6a07d06cfa5fc3ce1cdce22ea134f60dd559e004701&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Afc27f066d4d5848ab583e6256957815b31560c7ac9adb00fafc5fe2d466476be&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Af25209966669ce7b4a6a3bf425d4e36aba6306c1300e7cddcccf2b43e28feeff&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad343c65aeab0c5b4f83a57d3b24980f9b5a0c86c971f1f06015455a6d9a0e9d8&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
time="2022-04-12T11:35:47Z" level=debug msg="load cache https://artifactcache.actions.githubusercontent.com/07rP7SPOAq3eGFUefOJZOWtENsyeDzZaTdyI3aAHjpO6xrXNKj/_apis/artifactcache/cache?keys=buildkit-blob-1-sha256%3Ad404aec325b35205c6808a692be5849c765bb875928277f46df4cae3f0876aa5&version=693bb7016429d80366022f036f84856888c9f13e00145f5f6f4dce303a38d6f2"
@bendavies I do see rate limiting for the main repo referenced above, about 5% of the GET requests:
| Command | BlockedRequests | TotalRequests |
|---|---|---|
| GetCache | 6194 | 138663 |
| ReserveCache | 0 | 2426 |
| SealCache | 0 | 2334 |
| UploadChunk | 0 | 2559 |
☝️ is over several days. Looking at just the time window for your example run above:
| Command | BlockedRequests | TotalRequests |
|---|---|---|
| GetCache | 28 | 241 |
| ReserveCache | 0 | 1 |
| SealCache | 0 | 1 |
| UploadChunk | 0 | 1 |
So it is still worth us looking into increasing the limit @t-dedah
@dhadka that would be very much appreciated!
Like is said in the OP, we are hitting these limits (i think) pretty constatly (before i disabled cache writing) with a pretty small team of 5 devs.
I'm not sure how larger teams are coping if using caching with docker/build-and-push.
that does leave the mystery of why my bendavies/docker-build-cache-limits reproducer is slow, if it's not rate limiting :-/
that does leave the mystery of why my bendavies/docker-build-cache-limits reproducer is slow, if it's not rate limiting :-/
Yeah, fixing the rate limiting will certainly help, but based on the investigations in this issue it sounds like there's additional overhead causing slowness. Any chance you tried @tonistiigi 's suggestion of using a local cache to see if the slowness appears there?
@tonistiigi seems correct. local cache is also slow (but not as slow)
run 1 (unprimed local cache): https://github.com/bendavies/docker-build-cache-limits/actions/runs/2167840770/attempts/1 run 2: https://github.com/bendavies/docker-build-cache-limits/actions/runs/2167840770/attempts/2
the slow bit in the local cache logs:
docker/build-and-push:
Thu, 14 Apr 2022 14:46:42 GMT #409 [prod 201/201] RUN echo "400"
Thu, 14 Apr 2022 14:50:38 GMT #409 CACHED
buildkit:
time="2022-04-14T14:46:42Z" level=debug msg="load cache for [prod 201/201] RUN echo \"400\" with sha256:83a67a5cd04a3003dd4401f9743f1cc5770412b9dbee1880bf861f91f01eb20c"
time="2022-04-14T14:46:49Z" level=debug msg="remove snapshot" key=yblpyun0okp8ui4ladmt9ov42 snapshotter=overlayfs
time="2022-04-14T14:46:49Z" level=debug msg="remove snapshot" key=ywk15htx6u9mfsqkzsp721c7h snapshotter=overlayfs
time="2022-04-14T14:46:49Z" level=debug msg="schedule snapshotter cleanup" snapshotter=overlayfs
time="2022-04-14T14:46:49Z" level=debug msg="removed snapshot" key=buildkit/5/yblpyun0okp8ui4ladmt9ov42 snapshotter=overlayfs
time="2022-04-14T14:46:49Z" level=debug msg="removed snapshot" key=buildkit/6/ywk15htx6u9mfsqkzsp721c7h snapshotter=overlayfs
time="2022-04-14T14:46:49Z" level=debug msg="snapshot garbage collected" d=1.658628ms snapshotter=overlayfs
time="2022-04-14T14:50:38Z" level=debug msg=push digest="sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1" mediatype=application/vnd.docker.image.rootfs.diff.tar.gzip size=32
...
time="2022-04-14T14:50:39Z" level=debug msg="do request" digest="sha256:98c55f5331568f48359fca371a1d78b693a30e99e7505b1dcba6c65cb6cc03c1" mediatype=application/vnd.docker.distribution.manifest.v2+json request.header.content-type=application/vnd.docker.distribution.manifest.v2+json request.header.user-agent=buildkit/v0.10 request.method=PUT size=83342 url="https://ghcr.io/v2/bendavies/docker-build-cache-limits/manifests/prod"
time="2022-04-14T14:50:43Z" level=debug msg="fetch response received" digest="sha256:98c55f5331568f48359fca371a1d78b693a30e99e7505b1dcba6c65cb6cc03c1" mediatype=application/vnd.docker.distribution.manifest.v2+json response.header.content-length=0 response.header.content-type=application/json response.header.date="Thu, 14 Apr 2022 14:50:43 GMT" response.header.docker-content-digest="sha256:98c55f5331568f48359fca371a1d78b693a30e99e7505b1dcba6c65cb6cc03c1" response.header.docker-distribution-api-version=registry/2.0 response.header.location="/v2/bendavies/docker-build-cache-limits/manifests/sha256:98c55f5331568f48359fca371a1d78b693a30e99e7505b1dcba6c65cb6cc03c1" response.header.x-github-request-id="0441:351D:B437:20867:625834BF" response.status="201 Created" size=83342 url="https://ghcr.io/v2/bendavies/docker-build-cache-limits/manifests/prod"
time="2022-04-14T14:52:48Z" level=debug msg=fetch digest="sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1" mediatype=application/vnd.oci.image.layer.v1.tar+gzip size=32
i'm seeing a few of these 401 Unauthorized, but not sure if it's related or even a problem:
time="2022-04-14T14:50:38Z" level=debug msg="fetch response received" digest="sha256:c42883e97de28a9f7e297275b9c8cdee26a80386f550092fb07e2929a52e7752" mediatype=application/vnd.docker.container.image.v1+json response.header.content-length=73 response.header.content-type=application/json response.header.date="Thu, 14 Apr 2022 14:50:38 GMT" response.header.www-authenticate="***"https://ghcr.io/token\",service=\"ghcr.io\",scope=\"repository:bendavies/docker-build-cache-limits:pull\"" response.header.x-github-request-id="0443:4832:D568:22B78:625834BE" response.status="401 Unauthorized" size=84376 url="https://ghcr.io/v2/bendavies/docker-build-cache-limits/blobs/sha256:c42883e97de28a9f7e297275b9c8cdee26a80386f550092fb07e2929a52e7752"
@dhadka @bendavies Ill discuss with the team about increasing the GET limit.
I know there are some non-linear complexity issues on loading big layer chains that we have not prioritized because they should be impractical.
I checked out the type=local example and it is indeed the issue with LoadWithParents() being inefficient with big layer chains.
My results were:
- 50 layers: <1s
- 100 layers: 4.3s
- 200 layers: 20.7s
Some refactoring would be needed to solve this so it isn't entirely trivial. I'm not sure if it has anything to do with the initial issue you had in your real code. We can change this issue to track this inefficiency or create a new one. It is a low priority for us as with any practical layer chain length it is unnoticeable to the user.
@tonistiigi thanks for the investigation. I'm happy to raise a new issue if you prefer
Hey,
When GitHub Action Cache returns an error while importing/exporting cache, It causes Buildkit to Exponentially backoff and the build process to inevitably timeout.
I hope this information will help, to better address this issue.
Thank you all very much for your time and all of your hard work. Have a great weekend!
