Spurious rebuilds of `rules_rust` tool deps after idleness

[rejuvenile]

My project uses rules_rust. After periods of idleness, Bazel will take it upon itself to rebuild some of the rules_rust dependencies, even though nothing at all has been touched in my directory tree (even my own project sources).

Example:

❯ bazel test -c opt //...
INFO: Invocation ID: 64dd997d-3fa5-46e7-9db2-3f9a175663dc
INFO: Analyzed 7 targets (269 packages loaded, 9252 targets configured).
INFO: Found 5 targets and 2 test targets...
INFO: Writing explanation of rebuilds to 'explain.log'
INFO: Elapsed time: 13.249s, Critical Path: 11.57s
INFO: 211 processes: 232 action cache hit, 149 disk cache hit, 21 internal, 10 darwin-sandbox, 31 remote.
INFO: Build completed successfully, 211 total actions
//<some test> (cached) PASSED in 0.2s

wait one hour

❯ bazel test -c opt //...
INFO: Invocation ID: a1c7cee0-d065-4ea0-84cc-93ebcc3e3195
INFO: Analyzed 7 targets (0 packages loaded, 0 targets configured).
INFO: Found 5 targets and 2 test targets...
INFO: Writing explanation of rebuilds to 'explain.log'
INFO: Elapsed time: 9.635s, Critical Path: 7.51s
INFO: 20 processes: 3 action cache hit, 3 internal, 17 remote.
INFO: Build completed successfully, 20 total actions
//<some test> (cached) PASSED in 0.2s

explain.log:

Build options: --experimental_disk_cache_gc_max_size=20G --enable_platform_specific_config --disk_cache='~/Work/bazel-cache' --remote_default_exec_properties='OSFamily=macos' --remote_executor=grpc://remote_executor.local:50051 --internal_spawn_scheduler --spawn_strategy=dynamic --define='EXECUTOR=remote' --extra_toolchains=@local-remote-execution//rust:rust-aarch64-darwin --extra_execution_platforms=@local-remote-execution//platforms:aarch64-darwin --platforms=@local-remote-execution//platforms:aarch64-darwin --host_platform=@local-remote-execution//platforms:aarch64-darwin --action_env='DYLD_LIBRARY_PATH=/Users/user/.rustup/toolchains/nightly-2025-01-23-aarch64-apple-darwin/lib' --host_action_env='DYLD_LIBRARY_PATH=/Users/user/.rustup/toolchains/nightly-2025-01-23-aarch64-apple-darwin/lib' --reuse_sandbox_directories --verbose_failures --noincompatible_disallow_empty_glob --noworker_sandboxing --remote_instance_name=main --remote_cache=grpc://remote_executor.local:50051 --explain=explain.log --verbose_explanations --incompatible_strict_action_env --watchfs --experimental_windows_watchfs --color=yes --jobs=10000 --keep_going --remote_retries=10 --workspace_status_command=./bld/workspace_status.sh --stamp --aspects=@rules_rust//rust:defs.bzl%rust_clippy_aspect --output_groups=+clippy_checks --remote_timeout=600 --action_env='CARGO_PKG_NAME=mock' --action_env='CARGO_PKG_VERSION_PATCH=mock' --action_env='CARGO_PKG_VERSION_MAJOR=mock' --action_env='CARGO_PKG_VERSION_MINOR=mock' --action_env='CARGO_PKG_VERSION=mock2' --action_env='CARGO_PKG_AUTHORS=mock2' --action_env='CARGO_PKG_DESCRIPTION=mock3' --action_env='CARGO_PKG_HOMEPAGE=mock4' --action_env='CARGO_PKG_LICENSE=mock5' --action_env='CARGO_PKG_REPOSITORY=mock6' --action_env='RUSTDOC=mock7' --test_output=errors --test_verbose_timeout_warnings --action_env='RUST_BACKTRACE=1' --compilation_mode=opt
Executing action 'BazelWorkspaceStatusAction stable-status.txt': unconditional execution is requested.
Executing action 'Compiling Rust (without process_wrapper) rlib tinyjson (4 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib cargo_build_script_runner (2 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib unicode_ident v1.0.14 (11 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib heck v0.5.0 (9 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib autocfg v1.4.0 (15 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust bin _bs_ (17 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust bin _bs_ (17 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib shlex v1.3.0 (2 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib cc v1.2.10 (24 files) [for tool]': One of the files has changed.
Executing action 'Creating symlink external/rules_rust++crate+crates__proc-macro2-1.0.93/_bs- [for tool]': One of the files has changed.
Executing action 'Running Cargo build script proc-macro2 [for tool]': One of the files has changed.
Executing action 'Creating symlink external/rules_rust++crate+crates__semver-1.0.25/_bs- [for tool]': One of the files has changed.
Executing action 'Running Cargo build script semver [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib proc_macro2 v1.0.93 (17 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib semver v1.0.25 (17 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib quote v1.0.38 (16 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib rustc_version v0.4.1 (2 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib syn v2.0.96 (96 files) [for tool]': One of the files has changed.
Executing action 'Compiling Rust rlib synstructure v0.13.1 (2 files) [for tool]': One of the files has changed.

[UebelAndre]

Dang, that's wild! Are you able to identify what changed in those files?

[havasd]

Isn't that caused by stamping and workspace status? Can you check if it is still happening if disable stamping?

[UebelAndre]

Isn't that caused by stamping and workspace status? Can you check if it is still happening if disable stamping?

Good eye, there is a —stamp flag in the explain log

[rejuvenile]

@havasd If I execute the builds in quick succession (e.g. within a half hour) zero items are rebuilt, even with --stamp. The value of the --stamp flag doesn't affect that behavior; even with --stamp=yes, I can't force a rebuild using bazel test. So I don't think it's stamping, but perhaps rules_rust has very non-deterministic stamping (say, a timestamp rounded to the hour). If rules_rust from a bzlmod module can be affected by --stamp in the topmost workspace, though, that might be a bug of its own, since I don't think it should be.

I'll try for a minimal repro.

[havasd]

I found that the stamp flag with workspace_status can behave weirdly in our project. For example sometimes it didn't trigger rebuild. But similarly when I triggered a CI later on the same changeset with proper caching it triggered.

I agree that the tool binaries shouldn't be impacted by this stamping at all

[rejuvenile]

In my own project (which uses all_crate_deps) I can repro. with bazel test -c opt //... --nowatchfs --nostamp && sleep 3600 && bazel test -c opt //... --nowatchfs --nostamp. Simply building rules_rust, I cannot. This might be a bug in Bazel.

[rejuvenile]

Perhaps unrelatedly, when building with --nowatchfs, I can get into a state where the following symlinks are recreated 100% of the time:

Executing action 'BazelWorkspaceStatusAction stable-status.txt': unconditional execution is requested.
Executing action 'Creating symlink external/rules_rust++crate+crates__semver-1.0.25/_bs- [for tool]': One of the files has changed.
Executing action 'Creating symlink external/rules_rust++crate+crates__object-0.36.7/_bs-': One of the files has changed.
Executing action 'Creating symlink external/rules_rust++crate+crates__proc-macro2-1.0.93/_bs- [for tool]': One of the files has changed.
Executing action 'Creating symlink external/rules_rust++crate+crates__scrap-0.5.0/_bs-': One of the files has changed.
Executing action 'Creating symlink external/rules_rust++crate+crates__typenum-1.17.0/_bs-': One of the files has changed.
Executing action 'Creating symlink external/rules_rust++crate+crates__libc-0.2.169/_bs-': One of the files has changed.

[havasd]

Can you try without workspace status file?

[rejuvenile]

@havasd That was the first thing I tried. I still repros even without any workspace status.

[rejuvenile]

This may not be helpful, as I don't know rules_rust very well, but it looks like a certain set of files are always marked as changed, possibly when they shouldn't be:

250418 22:00:02.267:I 28986 [com.google.devtools.build.lib.skyframe.FilesystemValueChecker.getDirtyActionValues] Completed output file stat checks, 308 actions' outputs changed, first few: [ActionLookupData0{actionLookupKey=ConfiguredTargetKey{label=@@rules_rust++crate+crates__serde_urlencoded-0.7.1//:cargo_toml_env_vars, config=BuildConfigurationKey[693d7220c1595aaf8e04623698890b61719bbcf0b8572038a4df43c9a0dceae8]}, actionIndex=0}, ActionLookupData0{actionLookupKey=ConfiguredTargetKey{label=@@rules_rust++crate+crates__sentry-contexts-0.37.0//:_bs_, config=BuildConfigurationKey[eb17936e64f417615aec2d9c45f49f99ed365095427fa640c8d89cccc724a451]}, actionIndex=0}, ActionLookupData0{actionLookupKey=ConfiguredTargetKey{label=@@rules_rust++crate+crates__typenum-1.18.0//:_bs_, config=BuildConfigurationKey[eb17936e64f417615aec2d9c45f49f99ed365095427fa640c8d89cccc724a451]}, actionIndex=0}, ActionLookupData0{actionLookupKey=ConfiguredTargetKey{label=@@rules_rust++crate+crates__thiserror-1.0.69//:cargo_toml_env_vars, config=BuildConfigurationKey[693d7220c1595aaf8e04623698890b61719bbcf0b8572038a4df43c9a0dceae8]}, actionIndex=0}, ...
[com.google.devtools.build.lib.skyframe.SequencedSkyframeExecutor.detectModifiedOutputFiles] Found 334 modified files from last build

The number of modified files is relatively stable but not completely deterministic. They're related to Cargo build envs. The stat values have changed and either the hashes aren't checked, or they've changed too, leading to a number of other rebuilds:

50418 22:11:34.424:I 30118 [com.google.devtools.build.lib.runtime.BuildSummaryStatsModule.buildComplete] Slowest actions:
  0.17s action 'BazelWorkspaceStatusAction stable-status.txt'
  0.02s action 'Compiling Rust bin _bs_ (17 files) [for tool]'
  0.01s action 'Compiling Rust bin _bs_ (11 files) [for tool]'
  0.01s action 'Compiling Rust bin _bs_ (92 files) [for tool]'
  0.01s action 'Compiling Rust bin _bs_ (9 files) [for tool]'
  0.01s action 'Compiling Rust bin _bs_ (6 files) [for tool]'
  0.01s action 'Compiling Rust bin _bs_ (7 files) [for tool]'
  0.01s action 'Running Cargo build script typeid [for tool]'
  0.01s action 'Running Cargo build script proc-macro2 [for tool]'
  0.01s action 'Running Cargo build script semver [for tool]'
...
  0.00s action 'Compiling Rust bin _bs_ (15 files) [for tool]'
  0.00s action 'Compiling Rust rlib form_urlencoded v1.2.1 (1 files) [for tool]'
  0.00s action 'Compiling Rust rlib indexmap v2.7.1 (30 files) [for tool]'
  0.00s action 'ExtractCargoTomlEnvVars external/rules_rust++crate+crates__futures-sink-0.3.31/cargo_toml_env_vars.env'
  0.00s action 'ExtractCargoTomlEnvVars external/rules_rust++crate+crates__fastrand-2.3.0/cargo_toml_env_vars.env'
  0.00s action 'ExtractCargoTomlEnvVars external/rules_rust++crate+crates__adler2-2.0.0/cargo_toml_env_vars.env'
  0.00s action 'ExtractCargoTomlEnvVars external/rules_rust++crate+crates__futures-io-0.3.31/cargo_toml_env_vars.env'
  0.00s action 'ExtractCargoTomlEnvVars external/rules_rust++crate+crates__futures-task-0.3.31/cargo_toml_env_vars.env'
  0.00s action 'ExtractCargoTomlEnvVars external/rules_rust++crate+crates__rand-0.8.5/cargo_toml_env_vars.env'
  0.00s action 'ExtractCargoTomlEnvVars external/rules_rust++crate+crates__fnv-1.0.7/cargo_toml_env_vars.env'
  0.00s action 'Creating symlink external/rules_rust++i2+rules_rust_ctve__typeid-1.0.2/_bs- [for tool]'

Then, for some reason, Bazel's cache has either lost the intermediate outputs (somehow, while idle) or has been forced to recompile them due to real (but probably unnecessary). changes upstream. The above work/log messages happen on every build, but only after long periods of idleness does the invalidation (or cache loss of intermediate outputs) end up propagating far downstream and taking a lot of time.

Repeatedly no-op building in the same tree does seem to result in a lot of cache misses (and my caches are quite large), with a 50:1 cache miss-to-hit-ratio, but I don't know what to make of it:

250418 22:31:28.998:I 42206 [com.google.devtools.build.lib.runtime.CacheFileDigestsModule.logStats] Accumulated cache stats after command: hit count=194, miss count=10232, hit rate=0.0186073, eviction count=0

Perhaps rules_rust "from Cargo" deps are really, really non-deterministic at the lowest levels.

[rejuvenile]

During the spurious rebuilds we also see:

250421 15:12:54.747:I 7793 [com.google.devtools.build.lib.skyframe.SequencedSkyframeExecutor.detectModifiedOutputFiles] Found 2506 modified files from last build

[havasd]

One thing which came to my mind. You could also use the build event file for more information. --build_event_json_file. At least that helped me in identifying some cases what was the reason for cache invalidation.

If you already using this than my comment is stale.