Investigating low perf improvements

[laurentsenta]

Slow CI was brought up in filecoin-project/builtin-actors#1366
I'm running a few experiment, might have found a few bugs that would explain the low improvements found with caching:

Incorrect setup?

It seems like the env is not correctly setup. We set a custom cache path env in the action, but we don't export this env out of the action. Which means the custom path value is not set anymore when we leave the rust-sscache, and the cache is not used.

See the steps in this experiment:
https://github.com/laurentsenta/builtin-actors/actions/runs/5868643859/job/15911934941

Step: Show Cache
ls: cannot access '/home/runner/work/builtin-actors/builtin-actors/.cache/sccache': No such file or directory

Step: Show Statistics
Cache location Local disk: "/home/runner/.cache/sccache"

• Fix: in the action, ALWAYS output to GITHUB_ENV.

Missing statistics

Looking at the statistics, it seems like the sscache is never used
https://github.com/laurentsenta/builtin-actors/actions/runs/5868643859/job/15911934941

Compile requests                      0
Compile requests executed             0
Cache hits                            0
Cache misses                          0
Cache timeouts                        0
Cache read errors                     0
Forced recaches                       0
Cache write errors                    0
Compilation failures                  0
Cache errors                          0
Non-cacheable compilations            0
Non-cacheable calls                   0
Non-compilation calls                 0
Unsupported compiler calls            0
Average cache write               0.000 s
Average cache read miss           0.000 s
Average cache read hit            0.000 s
Failed distributed compilations       0
Cache location                  Local disk: "/home/runner/.cache/sccache"

This seems to indicate an issue with our setup.
Seems like only the download cache (which is using a different tools) is working.

• Fix: in the action, add a post-action that outputs these stats for users to debug themselves.
• Fix: when trigger a job in debug mode, also output logs with https://github.com/mozilla/sccache#debugging
• Fix: run sscache in non daemon mode and output its stdout / stderr in debug mode? (related)

Still not working

Currently still no hit on the cache according to the stats:
https://github.com/laurentsenta/builtin-actors/actions/runs/5876203928/job/15933892319

I am running more tests with debug enabled,

• running with debug logging after a cache clear: https://github.com/laurentsenta/builtin-actors/actions/runs/5876795460/job/15935694923

Lots of

[2023-08-16T09:11:42Z DEBUG sccache::config] Attempting to read config file at "/home/runner/.config/sccache/config"
[2023-08-16T09:11:42Z DEBUG sccache::config] Couldn't open config file: No such file or directory (os error 2)
[2023-08-16T09:11:42Z DEBUG sccache::commands] Server sent UnhandledCompile

Incorrect path'ing?

https://github.com/mozilla/sccache#known-caveats

Absolute paths to files must match to get a cache hit. This means that even if you are using a shared cache, everyone will have to build at the same absolute path (i.e. not in $HOME) in order to benefit each other. In Rust this includes the source for third party crates which are stored in $HOME/.cargo/registry/cache by default.

That sounds silly but from what I read here caching doesn't depend on content but on pathes (how ironic), I'm running an experiment to check paths, IIRC github action are running in "random" folders.

More caveats?

https://github.com/mozilla/sccache#known-caveats

We disable incremental compilation,
Can we detect any other issue automatically? See the caveats:

• Crates that invoke the system linker cannot be cached. This includes bin, dylib, cdylib, and proc-macro crates. You may be able to improve compilation time of large bin crates by converting them to a lib crate with a thin bin wrapper.

• everything in https://github.com/mozilla/sccache/blob/main/docs/Rust.md

[laurentsenta]

My current goal is to tweak the workflow until I see some hits in the statistics.
I don't think missing configuration is a big deal, we use env variables. But we'll see when the job runs a second time starting from an existing cache. We should get some hits.

That UnhandledCompile is worrisome though.

[laurentsenta]

Incorrect Path'ing is my current target, debugging run in https://github.com/laurentsenta/builtin-actors/actions/runs/5877002270
will look into this when it's complete.

[laurentsenta]

github action related config we might want to use:

https://github.com/mozilla/sccache/blob/main/docs/GHA.md

(related: https://github.com/Mozilla-Actions/sccache-action#rust-code)

[laurentsenta]

https://github.com/mozilla/sccache#rust

Crates that invoke the system linker cannot be cached. This includes bin, dylib, cdylib, and proc-macro crates. You may be able to improve compilation time of large bin crates by converting them to a lib crate with a thin bin wrapper.

I export sccache logs in https://github.com/laurentsenta/builtin-actors/actions/runs/5878478080 (sccache_log.txt)

I'm seeing "CannotCache(crate-type, cdylib)":

[2023-08-16T12:06:02Z DEBUG sccache::server] parse_arguments: CannotCache(crate-type, cdylib): ["--crate-name", "fil_actor_reward", "--edition=2021", "actors/reward/src/lib.rs", "--error-format=json", "--json=diagnostic-rendered-ansi,artifacts,future-incompat", "--crate-type", "cdylib", "--crate-type", "lib", "--emit=dep-info,link", "-C", "embed-bitcode=no", "-C", "debuginfo=2", "-C", "metadata=643c0eef26d9ed9b", "--out-dir", "/home/runner/work/builtin-actors/builtin-actors/target/debug/deps", "-L", "dependency=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps", "--extern", "fil_actors_runtime=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libfil_actors_runtime-33f092d751e4e01a.rlib", "--extern", "fvm_ipld_blockstore=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libfvm_ipld_blockstore-c5f68d40c69c5978.rlib", "--extern", "fvm_ipld_encoding=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libfvm_ipld_encoding-99310a355adf4573.rlib", "--extern", "fvm_shared=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libfvm_shared-3c1c72705c0fed3c.rlib", "--extern", "lazy_static=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/liblazy_static-34ba320d3cb503b3.rlib", "--extern", "log=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/liblog-c1e3f819e8124d7e.rlib", "--extern", "num_derive=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libnum_derive-4e8c6e744b8545ea.so", "--extern", "num_traits=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libnum_traits-b237925f6bfbb7f7.rlib", "--extern", "serde=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libserde-ed1f073a161035a8.rlib", "-Dwarnings"]
...
[2023-08-16T12:06:02Z DEBUG sccache::server] parse_arguments: CannotCache(crate-type, cdylib): ["--crate-name", "fil_actor_power", "--edition=2021", "actors/power/src/lib.rs", "--error-format=json", "--json=diagnostic-rendered-ansi,artifacts,future-incompat", "--crate-type", "cdylib", "--crate-type", "lib", "--emit=dep-info,link", "-C", "embed-bitcode=no", "-C", "debuginfo=2", "-C", "metadata=46e92c40c6aacf22", "--out-dir", "/home/runner/work/builtin-actors/builtin-actors/target/debug/deps", "-L", "dependency=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps", "--extern", "anyhow=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libanyhow-2a8b4879abb5c883.rlib", "--extern", "cid=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libcid-ebbfbd3fd0104842.rlib", "--extern", "fil_actors_runtime=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libfil_actors_runtime-33f092d751e4e01a.rlib", "--extern", "frc42_dispatch=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libfrc42_dispatch-f1e5faae1cf05121.rlib", "--extern", "fvm_ipld_blockstore=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libfvm_ipld_blockstore-c5f68d40c69c5978.rlib", "--extern", "fvm_ipld_encoding=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libfvm_ipld_encoding-99310a355adf4573.rlib", "--extern", "fvm_ipld_hamt=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libfvm_ipld_hamt-67e728adeda7c566.rlib", "--extern", "fvm_shared=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libfvm_shared-3c1c72705c0fed3c.rlib", "--extern", "indexmap=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libindexmap-4c43011223709acb.rlib", "--extern", "integer_encoding=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libinteger_encoding-ab25b1291bcf0898.rlib", "--extern", "lazy_static=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/liblazy_static-34ba320d3cb503b3.rlib", "--extern", "log=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/liblog-c1e3f819e8124d7e.rlib", "--extern", "num_derive=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libnum_derive-4e8c6e744b8545ea.so", "--extern", "num_traits=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libnum_traits-b237925f6bfbb7f7.rlib", "--extern", "serde=/home/runner/work/builtin-actors/builtin-actors/target/debug/deps/libserde-ed1f073a161035a8.rlib", "-Dwarnings"]