cache icon indicating copy to clipboard operation
cache copied to clipboard
verified publisher icon actions

Restoring cache on MacOS is extremely slow

Open andrmoel opened this issue 4 years ago • 3 comments

I figured out restoring the cache is very slow on MacOS. I have created a test case with some node_modules for a React Native application. The following action is used:

uses: actions/cache@v2
with:
    path: 'node_modules'
    key: ${{ runner.os }}-node_modules-${{ hashFiles('**/yarn.lock') }}

Here are the results:

Restoring on ubuntu: Test run 1 took 6s: https://github.com/andrmoel/github-actions-speed-test/runs/3476428716?check_suite_focus=true Test run 2 took 8s: https://github.com/andrmoel/github-actions-speed-test/runs/3476523783?check_suite_focus=true

Restoring on macos: Test run 1 took 3m25s: https://github.com/andrmoel/github-actions-speed-test/runs/3476430657?check_suite_focus=true Test run 2 took 24s: https://github.com/andrmoel/github-actions-speed-test/runs/3476523785?check_suite_focus=true

In the best case restoring the cache on MacOS takes 3 times longer than on ubuntu. But what really makes me worry are the 3m25s from MacOS test run number 1.

Edit: I did some research on another repository and I assume the long action happens every time when the cache was hit the first time.

I have created a test repository with two identical github-actions. One action runs on ubuntu-latest the other one on macos-latest

https://github.com/andrmoel/github-actions-speed-test

andrmoel avatar Aug 31 '21 18:08 andrmoel

I am seeing the same thing on a self hosted runner on macos. But the initial checkout is fast

Cache restore

Received 0 of 56392883 (0.0%), 0.0 MBs/sec
9
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
10
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
11
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
12
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
13
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
14
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
15
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
16
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
17
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
18
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
19
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
20
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
21
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
22
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
23
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
24
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
25
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
26
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
27
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
28
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
29
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
30
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
31
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
32
Received 0 of 56392883 (0.0%), 0.0 MBs/sec
33
Received 16777216 of 56392883 (29.8%), 0.6 MBs/sec
34
Received 29360128 of 56392883 (52.1%), 1.0 MBs/sec
35
Received 29360128 of 56392883 (52.1%), 1.0 MBs/sec
36
Received 29360128 of 56392883 (52.1%), 1.0 MBs/sec
37
Received 33554432 of 56392883 (59.5%), 1.1 MBs/sec
38
Received 33554432 of 56392883 (59.5%), 1.0 MBs/sec
39
Received 33554432 of 56392883 (59.5%), 1.0 MBs/sec
40
Received 33554432 of 56392883 (59.5%), 1.0 MBs/sec
41
Received 33554432 of 56392883 (59.5%), 0.9 MBs/sec
42
Received 33554432 of 56392883 (59.5%), 0.9 MBs/sec
43
Received 33554432 of 56392883 (59.5%), 0.9 MBs/sec
44
Received 35421363 of 56392883 (62.8%), 0.9 MBs/sec
45
Received 35421363 of 56392883 (62.8%), 0.9 MBs/sec
46
Received 35421363 of 56392883 (62.8%), 0.9 MBs/sec
47
Received 35421363 of 56392883 (62.8%), 0.8 MBs/sec
48
Received 35421363 of 56392883 (62.8%), 0.8 MBs/sec
49
Received 35421363 of 56392883 (62.8%), 0.8 MBs/sec
50
Received 35421363 of 56392883 (62.8%), 0.8 MBs/sec
51
Received 35421363 of 56392883 (62.8%), 0.8 MBs/sec
52
Received 56392883 of 56392883 (100.0%), 1.2 MBs/sec

Checkout

  Receiving objects:   0% (1/1494)
252
  Receiving objects:   1% (15/1494)
253
  Receiving objects:   2% (30/1494)
254
  Receiving objects:   3% (45/1494)
255
  Receiving objects:   4% (60/1494)
256
  Receiving objects:   5% (75/1494)
257
  Receiving objects:   6% (90/1494)
258
  Receiving objects:   7% (105/1494)
259
  Receiving objects:   8% (120/1494)
260
  Receiving objects:   9% (135/1494)
261
  Receiving objects:  10% (150/1494)
262
  Receiving objects:  11% (165/1494)
263
  Receiving objects:  12% (180/1494)
264
  Receiving objects:  13% (195/1494)
265
  Receiving objects:  14% (210/1494)
266
  Receiving objects:  15% (225/1494)
267
  Receiving objects:  16% (240/1494)
268
  Receiving objects:  17% (254/1494)
269
  Receiving objects:  18% (269/1494)
270
  Receiving objects:  19% (284/1494), 1.69 MiB | 3.24 MiB/s
271
  Receiving objects:  20% (299/1494), 1.69 MiB | 3.24 MiB/s
272
  Receiving objects:  21% (314/1494), 1.69 MiB | 3.24 MiB/s
273
  Receiving objects:  21% (315/1494), 10.02 MiB | 9.62 MiB/s
274
  Receiving objects:  21% (315/1494), 16.39 MiB | 8.01 MiB/s
275
  Receiving objects:  22% (329/1494), 16.39 MiB | 8.01 MiB/s
276
  Receiving objects:  23% (344/1494), 16.39 MiB | 8.01 MiB/s
277
  Receiving objects:  24% (359/1494), 16.39 MiB | 8.01 MiB/s
278
  Receiving objects:  25% (374/1494), 16.39 MiB | 8.01 MiB/s
279
  Receiving objects:  26% (389/1494), 16.39 MiB | 8.01 MiB/s
280
  Receiving objects:  27% (404/1494), 16.39 MiB | 8.01 MiB/s
281
  Receiving objects:  28% (419/1494), 16.39 MiB | 8.01 MiB/s
282
  Receiving objects:  29% (434/1494), 16.39 MiB | 8.01 MiB/s
283
  Receiving objects:  30% (449/1494), 16.39 MiB | 8.01 MiB/s
284
  Receiving objects:  31% (464/1494), 16.39 MiB | 8.01 MiB/s
285
  Receiving objects:  32% (479/1494), 19.62 MiB | 7.70 MiB/s
286
  Receiving objects:  33% (494/1494), 19.62 MiB | 7.70 MiB/s
287
  Receiving objects:  34% (508/1494), 19.62 MiB | 7.70 MiB/s
288
  Receiving objects:  35% (523/1494), 19.62 MiB | 7.70 MiB/s
289
  Receiving objects:  36% (538/1494), 19.62 MiB | 7.70 MiB/s
290
  Receiving objects:  37% (553/1494), 19.62 MiB | 7.70 MiB/s
291
  Receiving objects:  38% (568/1494), 19.62 MiB | 7.70 MiB/s
292
  Receiving objects:  39% (583/1494), 19.62 MiB | 7.70 MiB/s
293
  Receiving objects:  40% (598/1494), 19.62 MiB | 7.70 MiB/s
294
  Receiving objects:  41% (613/1494), 19.62 MiB | 7.70 MiB/s
295
  Receiving objects:  42% (628/1494), 19.62 MiB | 7.70 MiB/s
296
  Receiving objects:  43% (643/1494), 19.62 MiB | 7.70 MiB/s
297
  Receiving objects:  44% (658/1494), 19.62 MiB | 7.70 MiB/s
298
  Receiving objects:  45% (673/1494), 19.62 MiB | 7.70 MiB/s
299
  Receiving objects:  46% (688/1494), 19.62 MiB | 7.70 MiB/s
300
  Receiving objects:  47% (703/1494), 19.62 MiB | 7.70 MiB/s
301
  Receiving objects:  48% (718/1494), 19.62 MiB | 7.70 MiB/s
302
  Receiving objects:  49% (733/1494), 19.62 MiB | 7.70 MiB/s
303
  Receiving objects:  50% (747/1494), 19.62 MiB | 7.70 MiB/s
304
  Receiving objects:  51% (762/1494), 19.62 MiB | 7.70 MiB/s
305
  Receiving objects:  52% (777/1494), 19.62 MiB | 7.70 MiB/s
306
  Receiving objects:  52% (779/1494), 19.62 MiB | 7.70 MiB/s
307
  Receiving objects:  53% (792/1494), 22.84 MiB | 7.41 MiB/s
308
  Receiving objects:  54% (807/1494), 25.99 MiB | 7.25 MiB/s
309
  Receiving objects:  55% (822/1494), 25.99 MiB | 7.25 MiB/s
310
  Receiving objects:  55% (830/1494), 25.99 MiB | 7.25 MiB/s
311
  Receiving objects:  56% (837/1494), 29.22 MiB | 7.16 MiB/s
312
  Receiving objects:  57% (852/1494), 29.22 MiB | 7.16 MiB/s
313
  Receiving objects:  58% (867/1494), 29.22 MiB | 7.16 MiB/s
314
  Receiving objects:  59% (882/1494), 29.22 MiB | 7.16 MiB/s
315
  Receiving objects:  60% (897/1494), 29.22 MiB | 7.16 MiB/s
316
  Receiving objects:  61% (912/1494), 29.22 MiB | 7.16 MiB/s
317
  Receiving objects:  62% (927/1494), 29.22 MiB | 7.16 MiB/s
318
  Receiving objects:  63% (942/1494), 29.22 MiB | 7.16 MiB/s
319
  Receiving objects:  64% (957/1494), 29.22 MiB | 7.16 MiB/s
320
  Receiving objects:  65% (972/1494), 29.22 MiB | 7.16 MiB/s
321
  Receiving objects:  66% (987/1494), 29.22 MiB | 7.16 MiB/s
322
  Receiving objects:  67% (1001/1494), 29.22 MiB | 7.16 MiB/s
323
  Receiving objects:  68% (1016/1494), 29.22 MiB | 7.16 MiB/s
324
  Receiving objects:  69% (1031/1494), 29.22 MiB | 7.16 MiB/s
325
  Receiving objects:  70% (1046/1494), 29.22 MiB | 7.16 MiB/s
326
  Receiving objects:  71% (1061/1494), 29.22 MiB | 7.16 MiB/s
327
  Receiving objects:  72% (1076/1494), 29.22 MiB | 7.16 MiB/s
328
  Receiving objects:  73% (1091/1494), 29.22 MiB | 7.16 MiB/s
329
  Receiving objects:  74% (1106/1494), 29.22 MiB | 7.16 MiB/s
330
  Receiving objects:  75% (1121/1494), 29.22 MiB | 7.16 MiB/s
331
  Receiving objects:  76% (1136/1494), 29.22 MiB | 7.16 MiB/s
332
  Receiving objects:  77% (1151/1494), 29.22 MiB | 7.16 MiB/s
333
  Receiving objects:  78% (1166/1494), 29.22 MiB | 7.16 MiB/s
334
  Receiving objects:  79% (1181/1494), 29.22 MiB | 7.16 MiB/s
335
  Receiving objects:  80% (1196/1494), 29.22 MiB | 7.16 MiB/s
336
  Receiving objects:  81% (1211/1494), 29.22 MiB | 7.16 MiB/s
337
  Receiving objects:  82% (1226/1494), 29.22 MiB | 7.16 MiB/s
338
  Receiving objects:  83% (1241/1494), 32.36 MiB | 7.06 MiB/s
339
  Receiving objects:  84% (1255/1494), 32.36 MiB | 7.06 MiB/s
340
  Receiving objects:  85% (1270/1494), 32.36 MiB | 7.06 MiB/s
341
  Receiving objects:  86% (1285/1494), 32.36 MiB | 7.06 MiB/s
342
  Receiving objects:  87% (1300/1494), 32.36 MiB | 7.06 MiB/s
343
  Receiving objects:  88% (1315/1494), 32.36 MiB | 7.06 MiB/s
344
  Receiving objects:  89% (1330/1494), 32.36 MiB | 7.06 MiB/s
345
  Receiving objects:  90% (1345/1494), 32.36 MiB | 7.06 MiB/s
346
  Receiving objects:  91% (1360/1494), 32.36 MiB | 7.06 MiB/s
347
  Receiving objects:  92% (1375/1494), 32.36 MiB | 7.06 MiB/s
348
  Receiving objects:  93% (1390/1494), 32.36 MiB | 7.06 MiB/s
349
  Receiving objects:  94% (1405/1494), 32.36 MiB | 7.06 MiB/s
350
  Receiving objects:  95% (1420/1494), 32.36 MiB | 7.06 MiB/s
351
  Receiving objects:  96% (1435/1494), 32.36 MiB | 7.06 MiB/s
352
  Receiving objects:  97% (1450/1494), 32.36 MiB | 7.06 MiB/s
353
  Receiving objects:  98% (1465/1494), 32.36 MiB | 7.06 MiB/s
354
  remote: Total 1494 (delta 262), reused 827 (delta 85), pack-reused 0        
355
  Receiving objects:  99% (1480/1494), 32.36 MiB | 7.06 MiB/s
356
  Receiving objects: 100% (1494/1494), 32.36 MiB | 7.06 MiB/s
357
  Receiving objects: 100% (1494/1494), 32.73 MiB | 7.04 MiB/s, done.

michaelst avatar Dec 07 '21 21:12 michaelst

gtar performance on macos-11 is wildly inconsistent.

I have a run where it took 10 min:

Wed, 09 Feb 2022 14:37:31 GMT
Cache Size: ~1394 MB (1461838173 B)

Wed, 09 Feb 2022 14:37:31 GMT
/usr/local/bin/gtar --use-compress-program zstd -d -xf /Users/runner/work/_temp/uuid/cache.tzst -P -C /Users/runner/work/app --delay-directory-restore

Wed, 09 Feb 2022 14:47:42 GMT
Cache restored successfully

And 30 seconds in the previous run:

Wed, 09 Feb 2022 14:03:19 GMT
Cache Size: ~1394 MB (1461421762 B)

Wed, 09 Feb 2022 14:03:19 GMT
/usr/local/bin/gtar --use-compress-program zstd -d -xf /Users/runner/work/_temp/uuid/cache.tzst -P -C /Users/runner/work/app --delay-directory-restore

Wed, 09 Feb 2022 14:03:50 GMT
Cache restored successfully

headsvk avatar Feb 09 '22 15:02 headsvk

I'm having the same issue on MacOS. It was taking over 27 minutes to decompress 1.2 GB and it still wasn't done, so I cancelled it. This isn't unacceptable. I'm using actions/cache@v3 and macos-11.

Mattijah avatar Mar 31 '22 23:03 Mattijah

Closing this issue as we could not recreate the above macos performance issue. Feel free to create another issue if the problem recurs.

lvpx avatar Nov 16 '22 09:11 lvpx

@pdotl I'm seeing the same issue.

this repo contains a reproducible workflow

MacOS is consistently much slower than linux: Screen Shot 2022-11-30 at 20 26 41 Screen Shot 2022-11-30 at 20 26 34 Screen Shot 2022-11-30 at 20 26 26

I've also observed this many times in an real world environment of the same dependencies (notice the same hash in both runs 8f697dca40e59245771bc3babd61ce7eec68e51d1af2f99a79dff601c742dfe4):

linux: 30sec

Screen Shot 2022-11-30 at 20 30 28

macOS: 2:10min

Screen Shot 2022-11-30 at 20 30 39 
name: Slow cache example
on:
  workflow_dispatch:
  push:
  pull_request:

jobs:
  generate:
    name: generate
    runs-on: ubuntu-latest
    steps:
      - uses: actions/checkout@v3
      - name: generate large file to cache
        run: dd if=/dev/urandom of=some-large-file bs=1M count=500
      - name: cache large file
        uses: actions/cache@v3
        with:
          path: some-large-file
          key: ${{ hashFiles('some-large-file') }}
  restore-linux:
    name:  restore-linux
    needs: generate
    runs-on: ubuntu-latest
    steps:
      - name: restore cached large file
        uses: actions/cache@v3
        with:
          path: some-large-file
          key: large-file
  restore-macos:
    name:  restore-macos
    needs: generate
    runs-on: macos-12
    steps:
      - name: restore cached large file
        uses: actions/cache@v3
        with:
          path: some-large-file
          key: large-file

penchef avatar Dec 01 '22 01:12 penchef