GHA backend is pretty slow

[NobodyXu]

GHA backend is so slow that my project (openssh-sftp-client) somehow doesn't get much speedup from it.

openssh-sftp-client only has 63 deps to load from GHA, yet it's not much difference from using a actions/cache with a fixed key.

[sylvestre]

You should have a look to the logs to see what happens. Hit rate limit on the gh side?

[NobodyXu]

You should have a look to the logs to see what happens. Hit rate limit on the gh side?

I checked the sccache stats from post-run and it seems that it's doing pretty good:

/opt/hostedtoolcache/sccache/0.4.2/x64/sccache --show-stats
Compile requests                    103
Compile requests executed            63
Cache hits                           62
Cache hits (Rust)                    62
Cache misses                          0
Cache timeouts                        0
Cache read errors                     0
Forced recaches                       0
Cache write errors                    0
Compilation failures                  1
Cache errors                          0
Non-cacheable compilations            0
Non-cacheable calls                  40
Non-compilation calls                 0
Unsupported compiler calls            0
Average cache write               0.000 s
Average compiler                  0.000 s
Average cache read hit            0.000 s
Failed distributed compilations       0

Non-cacheable reasons:
crate-type                           33
-                                     7

Cache location                  ghac, name: sccache-v0.4.2, prefix: /sccache/
Version (client)                0.4.2

from https://github.com/openssh-rust/openssh-sftp-client/actions/runs/4892335084/jobs/8733974083

[sylvestre]

I was talking about log. This doesn't show much, sorry

[NobodyXu]

@sylvestre I've re-run the CI with GitHub debug logs.

[NobodyXu]

If you need anything else, feel free to ping me and I will try providing information required for you to debug the problem.

[sylvestre]

sccache debug, not github and please have a look to the log yourself :) https://github.com/mozilla/sccache/blob/3e1717e53b5a5c93d815212ec3260d2bdf1af633/README.md?plain=1#L211

[NobodyXu]

@sylvestre I've enabled sccache debug as you instructed: https://github.com/openssh-rust/openssh-sftp-client/actions/runs/4935781747

[sylvestre]

And did you see anything unusual?

[NobodyXu]

And did you see anything unusual?

Nope, though I think it could be that either GitHub cache is too slow or sccache-dist is a bit slow, which might be improved by porting https://github.com/paritytech/cachepot/pull/131/files#diff-6d63828d1891ff3303de7191b656bc451d27703548c42bd9786fcd1c157aa459L313

Anyway, I think I can try improving the CI by increasing number of rustc invoked in paralle via -j, so that sccache-dist can fetch more cached objects in parallel.

I also wonder if sccache caching strategy for GHA is too fine grind, it seems like accessing GHA takes quite some time compared to local disk access.

[drahnr]

And did you see anything unusual?

Nope, though I think it could be that either GitHub cache is too slow or sccache-dist is a bit slow, which might be improved by porting https://github.com/paritytech/cachepot/pull/131/files#diff-6d63828d1891ff3303de7191b656bc451d27703548c42bd9786fcd1c157aa459L313

Happy to review the code port :)

Anyway, I think I can try improving the CI by increasing number of rustc invoked in paralle via -j, so that sccache-dist can fetch more cached objects in parallel.

That only works to the degree of parallel dependency branches in the dependency tree at each level.

I also wonder if sccache caching strategy for GHA is too fine grind, it seems like accessing GHA takes quite some time compared to local disk access.

GHA is surely disgned for larger individual blobs, rather than individual artifacts, so it might be worth to open a support ticket and get some additional insights on the behavior.

[NobodyXu]

Happy to review the code port :)

Thanks, though it is a really large PR and I'm not that familiar with sccache code base, so it would take me quite some time to do this.

I'm not sure whether it can be split into multiple PRs.

That only works to the degree of parallel dependency branches in the dependency tree at each level.

Yeah you are right, though it might still help a bit, especially at the start of the compilation.

GHA is surely disgned for larger individual blobs, rather than individual artifacts, so it might be worth to open a support ticket and get some additional insights on the behavior.

Opened #1762 for this

[drahnr]

I meant support ticket as in against github as the platform to clarify any throttling that is applied and how to make it compatible with more + smaller requests.

A separate issue is good too though

[NobodyXu]

I meant support ticket as in against github as the platform to clarify any throttling that is applied and how to make it compatible with more + smaller requests.

Thanks, I will do that.

[NobodyXu]

A separate issue is good too though

I still think it might be better for sccache to use more coarse grind caching in GHA.

Granted GHA is free, the response from GitHub might just be "you need to change the way you cache".

[NobodyXu]

I meant support ticket as in against github as the platform to clarify any throttling that is applied and how to make it compatible with more + smaller requests.

I've created a ticket https://github.com/orgs/community/discussions/55049

[sylvestre]

Thanks for doing this!

[NobodyXu]

Thanks for doing this!

You are welcome

[luser]

@sylvestre I've enabled sccache debug as you instructed: https://github.com/openssh-rust/openssh-sftp-client/actions/runs/4935781747

I looked your log, and I find the fact that every cache hit is logged as taking no time at all extremely suspicious, e.g.:

[2023-05-10T10:12:20Z DEBUG sccache::compiler::compiler] [thiserror]: Cache hit in 0.000 s

It looks like this got broken at some point: https://github.com/mozilla/sccache/blob/62c8f0aa168037628058221448d2aab67fd7968d/src/compiler/compiler.rs#L268

The future it's trying to time is being awaited after that gets calculated: https://github.com/mozilla/sccache/blob/62c8f0aa168037628058221448d2aab67fd7968d/src/compiler/compiler.rs#L277

[luser]

I'd be interested to see a log from a build using GHA storage with my fix in #1818 included, to get actual timings.