get-cmake takes over 2 min when there is no cache

[njzjz]

For unclear reasons, get-cmake takes over 2 min on macos-14:

[lukka]

@njzjz the first step would be to identify which opertion is taking an unusual amount of time. You can enable the timestamps in the log and see where most of the time is spent. Then you can dig into the step further and expand the expandable section to get more granular results, such as the following screenshot (where action debugging is enabled to get verbose output and more information):

[njzjz]

2024-05-04T19:47:48.4552500Z ##[debug]File Size: 79676783
2024-05-04T19:47:48.4552710Z ##[debug]Reserving Cache
2024-05-04T19:47:48.4553370Z ##[debug]Resource Url: https://acghubeus1.actions.githubusercontent.com/uPHkKHTGkNyfEAEFlQHIgX60BlaZ4YPIhUfireRydgQsF8KDq3/_apis/artifactcache/caches
2024-05-04T19:47:48.4553580Z ##[debug]Saving Cache (ID: 2401)
2024-05-04T19:47:48.4553780Z ##[debug]Upload cache
2024-05-04T19:47:48.4554560Z ##[debug]Resource Url: https://acghubeus1.actions.githubusercontent.com/uPHkKHTGkNyfEAEFlQHIgX60BlaZ4YPIhUfireRydgQsF8KDq3/_apis/artifactcache/caches/2401
2024-05-04T19:47:48.4555420Z ##[debug]Upload concurrency: 4
2024-05-04T19:47:48.4555780Z ##[debug]Upload chunk size: 33554432
2024-05-04T19:47:48.4556150Z ##[debug]Awaiting all uploads
2024-05-04T19:47:48.4556810Z ##[debug]Uploading chunk of size 33554432 bytes at offset 0 with content range: bytes 0-33554431/*
2024-05-04T19:47:48.4557650Z ##[debug]Uploading chunk of size 33554432 bytes at offset 33554432 with content range: bytes 33554432-67108863/*
2024-05-04T19:47:48.4558530Z ##[debug]Uploading chunk of size 12567919 bytes at offset 67108864 with content range: bytes 67108864-79676782/*
2024-05-04T19:47:50.1947630Z ##[debug]Commiting cache
2024-05-04T19:47:50.2116270Z Cache Size: ~76 MB (79676783 B)
2024-05-04T19:47:50.2299470Z ##[debug]Resource Url: https://acghubeus1.actions.githubusercontent.com/uPHkKHTGkNyfEAEFlQHIgX60BlaZ4YPIhUfireRydgQsF8KDq3/_apis/artifactcache/caches/2401
2024-05-04T19:47:50.3907930Z Cache saved successfully
2024-05-04T19:47:50.3921060Z Saved '/Users/runner/work/_temp/1878740783' to the GitHub cache service with key '1878740783'.
2024-05-04T19:47:50.3922250Z ::endgroup::
2024-05-04T19:47:50.3922430Z ##[endgroup]
2024-05-04T19:47:50.3922690Z get-cmake action execution succeeded
2024-05-04T19:50:00.7458260Z ##[debug]Node Action run completed with exit code 0
2024-05-04T19:50:00.7469730Z ##[debug]Finishing: Run lukka/get-cmake@latest

full log

The issue only happens when it saves the cache in the first runtime. Deleting the cache manually can reproduce it.

[njzjz]

Maybe a similar issue as hendrikmuhs/ccache-action#181

[njzjz]

I found I got the same issue with Ubuntu, so it's not related to macos.

[lukka]

@njzjz thank you for all the references.
My take:

• the root cause is a bug in node v20+. Hopefully that is going to be fixed soon.
• the impact is that when cache is not hit, 2 additional minutes would be spent, but usually cache-hits outnumber cache-misses.

If a simple solution can be applied to get-cmake, please make a pull request. I am looking for a fix that doesn't introduce any regressions in terms of functionality or security.

[Xevion]

Still, not fixed, no progress. At 3 weeks with no progress, I believe a note should be included in the GitHub repository so new users should not be confused about why the action consumes 90% of the total runtime of their workflow, both on the first run, and whenever a new CMake version is used.

[Xevion]

Also, would you mind referencing what bug in Node v20 is causing this issue?

[lukka]

@njzjz @Xevion could you test with uses: lukka/get-cmake@dev/ninja-1.12.1 ? The fix is in this PR: #139 ready to be merged as soon as anyone confirm it is fixing this problem.

[Xevion]

@lukka Hey, had a chance to run it today, seems to work. You can confirm it with the logs below, but the cache upload below counts as far as I can tell, right? No cache (missed), so it executes and uploads to the cache, where the upload takes 2 minutes to time out.

As far as I know, that's the bug, the conditions in my logs present those same conditions, and the bug doesn't happen here (3-second upload, instead of 130+ seconds).

2024-06-02T23:33:14.9234430Z ##[group]Run lukka/get-cmake@dev/ninja-1.12.1
2024-06-02T23:33:14.9234923Z with:
2024-06-02T23:33:14.9235225Z   useCloudCache: true
2024-06-02T23:33:14.9235642Z   cmakeVersion: 3.22.1
2024-06-02T23:33:14.9236005Z   useLocalCache: false
2024-06-02T23:33:14.9236343Z ##[endgroup]
2024-06-02T23:33:15.0822229Z useCloudCache:true
2024-06-02T23:33:15.0833003Z useLocalCache:false
2024-06-02T23:33:15.0837442Z user defined cmake version:3.22.1
2024-06-02T23:33:15.0842720Z user defined ninja version:
2024-06-02T23:33:15.0847407Z cmake version:3.22.1
2024-06-02T23:33:15.0851804Z ninja version:latest
2024-06-02T23:33:15.0879140Z ##[group]Computing cache key from the downloads' URLs
2024-06-02T23:33:15.0885264Z Cache key: '-1205811067'.
2024-06-02T23:33:15.0897182Z Local install root: '/home/runner/work/_temp/-1205811067''.
2024-06-02T23:33:15.0903386Z ##[endgroup]
2024-06-02T23:33:15.0911554Z ##[group]Restoring from GitHub cloud cache using key '-1205811067' into '/home/runner/work/_temp/-1205811067'
2024-06-02T23:33:15.2255776Z Cloud cache miss.
2024-06-02T23:33:15.2256860Z ##[endgroup]
2024-06-02T23:33:15.2305014Z ##[group]Downloading and extracting CMake
2024-06-02T23:33:15.9027799Z [command]/usr/bin/tar xz --warning=no-unknown-keyword --overwrite -C /home/runner/work/_temp/-1205811067 -f /home/runner/work/_temp/14285dad-1f77-45b4-88a7-8ebc3008f846
2024-06-02T23:33:17.2942159Z ##[endgroup]
2024-06-02T23:33:17.2943967Z ##[group]Downloading and extracting Ninja
2024-06-02T23:33:17.3740917Z [command]/usr/bin/unzip -o -q /home/runner/work/_temp/2f79ad6a-c461-4b82-b7b7-d7b3e217548c
2024-06-02T23:33:17.4520366Z ##[endgroup]
2024-06-02T23:33:17.4522303Z ##[group]Add CMake and Ninja to PATH
2024-06-02T23:33:17.4523998Z CMake path: '/home/runner/work/_temp/-1205811067/cmake-3.22.1-linux-x86_64/bin/'
2024-06-02T23:33:17.4528069Z Ninja path: '/home/runner/work/_temp/-1205811067'
2024-06-02T23:33:17.4536089Z ##[group]Validating the installed CMake and Ninja
2024-06-02T23:33:17.4557919Z CMake actual path is: '/home/runner/work/_temp/-1205811067/cmake-3.22.1-linux-x86_64/bin/cmake'
2024-06-02T23:33:17.4559868Z Ninja actual path is: '/home/runner/work/_temp/-1205811067/ninja'
2024-06-02T23:33:17.4561459Z ##[endgroup]
2024-06-02T23:33:17.4562676Z ##[endgroup]
2024-06-02T23:33:17.4563926Z ##[group]Saving to GitHub cloud cache using key '-1205811067'
2024-06-02T23:33:17.4921837Z [command]/usr/bin/tar --posix -cf cache.tzst --exclude cache.tzst -P -C /home/runner/work/fizz-py/fizz-py --files-from manifest.txt --use-compress-program zstdmt
2024-06-02T23:33:20.6852900Z Cache Size: ~43 MB (45403977 B)
2024-06-02T23:33:20.7611706Z Cache saved successfully
2024-06-02T23:33:20.7779001Z Saved '/home/runner/work/_temp/-1205811067' to the GitHub cache service with key '-1205811067'.
2024-06-02T23:33:20.7780530Z ##[endgroup]
2024-06-02T23:33:20.7781278Z get-cmake action execution succeeded
2024-06-02T23:33:20.8109900Z ##[group]Run lukka/run-vcpkg@v11

[lukka]

@Xevion thank you, this is looking good to me! Closing this issue, let me know if any other issue comes up.