CI - Investigate why Rust nightly tests take almost double the time of regular Rust tests

[mrinalwadhwa]

Here's an example run

https://github.com/build-trust/ockam/actions/runs/2822798599

[neil2468]

Hi,

I took a look at some recent GitHub logs for scheduled Rust workflows, and ran some tests inside an ockam-builder docker.

It seems / I think...

• The Rust Nightly Test is always slower than Rust Test. It spends more time compiling tests and running tests (see log below). I suspect the tests take longer to run because some of the tests are also doing compilation (e.g. those which use example_test_helper).
• Every 24 hours the nightly toolchain is released and this triggers Rust Nightly Test to correctly re-compile the dependencies of ockam.
• The cache for target/.. depends on the hash of all Cargo.lock files (see action.yml). It seems the Rust Nightly Test cache was last updated on 9 Sep when ockam was released (Rust #5166, cache status). So, since 9 Sep Rust Nightly Test had to re-compile dependencies every time it ran.

One possible improvement would be to make the caches dependent on both Cargo.lock files and rustc's version. That way the cache for Rust Test would be updated mostly as it is now, but the cache for Rust Nightly Test would be updated every 24 hours.

Thoughts? Shall I create a PR? @mrinalwadhwa

===================
5125_logs_163148/1_Rust - Test.txt
772:2022-09-08T01:38:06.1211546Z     Finished test [unoptimized + debuginfo] target(s) in 2m 17s
1006:2022-09-08T01:40:31.3210907Z      Summary [ 144.903s] 176 tests run: 176 passed, 4 skipped

5125_logs_163148/1_Rust - Nightly Test.txt
1057:2022-09-08T01:39:44.9032778Z     Finished test [unoptimized + debuginfo] target(s) in 3m 55s
1238:2022-09-08T01:43:10.1034108Z      Summary [ 204.876s] 176 tests run: 176 passed, 4 skipped
>> compile slower by 41%
>> run tests slower by 29%

===================
5176_logs_163452/1_Rust - Test.txt
776:2022-09-11T01:37:05.1399738Z     Finished test [unoptimized + debuginfo] target(s) in 2m 36s
1010:2022-09-11T01:39:47.9407831Z      Summary [ 162.413s] 176 tests run: 176 passed, 4 skipped

5176_logs_163452/1_Rust - Nightly Test.txt
1057:2022-09-11T01:37:54.1982941Z     Finished test [unoptimized + debuginfo] target(s) in 3m 43s
1237:2022-09-11T01:41:13.0987635Z      Summary [ 198.566s] 176 tests run: 176 passed, 4 skipped
>> compile slower by 30%
>> run tests slower by 18%

===================
5144_logs_163244/1_Rust - Test.txt
780:2022-09-09T01:42:49.3207269Z     Finished test [unoptimized + debuginfo] target(s) in 3m 09s
1014:2022-09-09T01:46:00.7205742Z      Summary [ 190.974s] 176 tests run: 176 passed, 4 skipped

5144_logs_163244/1_Rust - Nightly Test.txt
1055:2022-09-09T01:42:42.9403928Z     Finished test [unoptimized + debuginfo] target(s) in 3m 44s
1235:2022-09-09T01:46:03.0411648Z      Summary [ 199.863s] 176 tests run: 176 passed, 4 skipped
>> compile slower by 15%
>> run tests slower by 4%

===================
5167_logs_163423/1_Rust - Test.txt
771:2022-09-10T01:40:07.3589886Z     Finished test [unoptimized + debuginfo] target(s) in 2m 23s
1005:2022-09-10T01:42:39.2601531Z      Summary [ 151.567s] 176 tests run: 176 passed, 4 skipped

5167_logs_163423/1_Rust - Nightly Test.txt
1068:2022-09-10T01:43:37.4054893Z     Finished test [unoptimized + debuginfo] target(s) in 5m 17s
1249:2022-09-10T01:48:10.8055957Z      Summary [ 272.986s] 176 tests run: 176 passed, 4 skipped
>> compile slower by 54%
>> run tests slower by 44%

[metaclips]

Hi,

I took a look at some recent GitHub logs for scheduled Rust workflows, and ran some tests inside an ockam-builder docker.

Thanks @neil2468 for the detailed investigation. We cache both nightly and stable build with same cache key leading to a race on who is first to upload, which is dominantly rust-stable as this step takes longer for rust-nightly thereby making rust-stable workflow upload cache first (except if rustup update nightly is already updated which is rare), this leads to rust-nightly having to recompile 3rd party crates every-time as the downloaded cache is that of stable.

One possible improvement would be to make the caches dependent on both Cargo.lock files and rustc's version. That way the cache for Rust Test would be updated mostly as it is now, but the cache for Rust Nightly Test would be updated every 24 hours.

I believe this is the right way to go. Other way to do this is to add a nightly keyword to cache-key (for only nightly tests) using workflow input cache-cargo-target-${{ github.workflow }}-${{ github.job }}-ghcr.io/build-trust/ockam-builder@sha256:e43dd94652096b03cc472a3c709c7335e8b166cab77b7a7b56f88fa38f3d24cc- can be cache-cargo-nightly-target-${{ github.workflow }}-${{ github.job }}-ghcr.io/build-trust/ockam-builder@sha256:e43dd94652096b03cc472a3c709c7335e8b166cab77b7a7b56f88fa38f3d24cc-.

Thoughts? Shall I create a PR? @mrinalwadhwa

Nice. Please do 🚀