Bazel `info` -> `cquery` invalidate part of cache

[SinimaWath]

Description of the bug:

Running: 1 - bazel info 2 - bazel cquery target 3 - bazel run/build target

Invalidate part of cache (for example, suddenly npm modules start extracting, but must be taken from cache). For more info see reproduction steps

Which category does this issue belong to?

Core

What's the simplest, easiest way to reproduce this bug? Please provide a minimal example if possible.

Add to ~/.bazelrc:

common --experimental_check_output_files=false
common --noexperimental_check_external_repository_files

1 - git clone https://github.com/bazelbuild/examples.git - Clone examples repo 2 - cd frontend - go to frontend example. 3 - bazel build //next.js:next - build application 4 - bazel build //next.js:next - check build is from cache 5 - bazel info && bazel cquery //next.js:next && bazel build //next.js:next

After step 5, in logs (bazel info server_log) we see there were Extracting npm package (building without info and cquery doesn't have extracting npm package):

240514 09:51:17.209:I 6609 [com.google.devtools.build.lib.runtime.BuildSummaryStatsModule.buildComplete] Critical Path: 0.08s, Remote (0.00% of the time): [parse: 0.00%, queue: 0.00%, network: 0.00%, upload: 0.00%, setup: 0.00%, process: 0.00%, fetch: 0.00%, retry: 0.00%, processOutputs: 0.00%, other: 0.00%, input files: 0, input bytes: 0, memory bytes: 0]
  0.00s action 'JsRunBinary next.js/.next'
  0.00s action 'Transpiling & type-checking TypeScript project @@//next.js/pages:pages [tsc -p next.js/tsconfig.json]'
  0.00s action 'Transpiling & type-checking TypeScript project @@//next.js/pages/api:api [tsc -p next.js/tsconfig.json]'
  0.08s action 'Extracting npm package [email protected]_-1955910335'
240514 09:51:17.209:I 6609 [com.google.devtools.build.lib.runtime.BuildSummaryStatsModule.buildComplete] Slowest actions:
  0.08s action 'Extracting npm package [email protected]_-1955910335'
  0.04s action 'Extracting npm package [email protected]_-1955910335 [for tool]'
  0.04s action 'Copying directory packages/one/one'
  0.04s action 'Extracting npm package @babel/[email protected] [for tool]'
  0.02s action 'Extracting npm package [email protected] [for tool]'
  0.02s action 'Extracting npm package @babel/[email protected] [for tool]'
  0.02s action 'Extracting npm package [email protected]_react_18.2.0'
  0.02s action 'Extracting npm package [email protected]_986221465 [for tool]'
  0.02s action 'Extracting npm package [email protected]'
  0.02s action 'Extracting npm package @babel/[email protected] [for tool]'
  0.02s action 'Extracting npm package @babel/[email protected]_at_babel_core_7.23.5 [for tool]'
  0.02s action 'Extracting npm package [email protected] [for tool]'
  0.02s action 'Extracting npm package [email protected]'
  0.01s action 'Extracting npm package @babel/[email protected] [for tool]'
  0.01s action 'Extracting npm package [email protected]'
  0.01s action 'Extracting npm package @babel/[email protected] [for tool]'
  0.01s action 'Extracting npm package @babel/[email protected] [for tool]'
  0.01s action 'Extracting npm package @babel/[email protected]'
  0.01s action 'Extracting npm package @babel/[email protected] [for tool]'
  0.01s action 'Extracting npm package @jridgewell/[email protected] [for tool]'
  0.01s action 'Extracting npm package @babel/[email protected]'
  0.01s action 'BazelWorkspaceStatusAction stable-status.txt'
  0.01s action 'Extracting npm package [email protected]'
  0.01s action 'Extracting npm package @babel/[email protected]'
  0.01s action 'Extracting npm package @babel/[email protected] [for tool]'
  0.01s action 'Extracting npm package @babel/[email protected] [for tool]'
  0.01s action 'Extracting npm package @babel/[email protected] [for tool]'
  0.01s action 'Extracting npm package [email protected]'
  0.01s action 'Extracting npm package @babel/[email protected]'
  0.01s action 'Extracting npm package [email protected] [for tool]'
240514 09:51:17.212:I 6609 [com.google.devtools.build.lib.sandbox.AsynchronousTreeDeleter.setThreads] Resizing async tree deletion pool to 4 threads
240514 09:51:17.212:I 6609 [com.google.devtools.build.lib.runtime.CacheFileDigestsModule.logStats] Accumulated cache stats after command: hit count=63355, miss count=17619, hit rate=0.782412, eviction count=0
240514 09:51:17.212:I 6609 [com.google.devtools.build.lib.runtime.CacheFileDigestsModule.logStats] Cache stats for finished command: hit count=12671, miss count=1, hit rate=0.999921, eviction count=0

Which operating system are you running Bazel on?

macos

What is the output of bazel info release?

release 7.1.0

If bazel info release returns development version or (@non-git), tell us how you built Bazel.

No response

What's the output of git remote get-url origin; git rev-parse HEAD ?

No response

Is this a regression? If yes, please try to identify the Bazel commit where the bug was introduced.

No response

Have you found anything relevant by searching the web?

https://github.com/bazelbuild/bazel/issues/17914

Any other information, logs, or outputs that you want to share?

GrpcServerImpl.executeCommand logs, without --client-env (removed it)

240515 12:10:24.009:I 8721 [com.google.devtools.build.lib.server.GrpcServerImpl.executeCommand] [info, --startup_time=32, --command_wait_time=0, --extract_data_time=0, --binary_path=/Users/user_name/Library/Caches/bazelisk/downloads/sha256/fb5e7bc62fc3c8f2511e3b64d795296444129b26f13d8dece4d4cee1845b758f/bin/bazel, --rc_source=client, --default_override=0:common=--isatty=1, --default_override=0:common=--terminal_columns=156, --rc_source=/Users/user_name/trash/examples/frontend/.bazelrc, --rc_source=/Users/user_name/.bazelrc, --default_override=1:common=--@aspect_rules_ts//ts:skipLibCheck=always]
240515 12:10:24.097:I 8721 [com.google.devtools.build.lib.server.GrpcServerImpl.executeCommand] [cquery, --startup_time=21, --command_wait_time=0, --extract_data_time=0, --binary_path=/Users/user_name/Library/Caches/bazelisk/downloads/sha256/fb5e7bc62fc3c8f2511e3b64d795296444129b26f13d8dece4d4cee1845b758f/bin/bazel, --rc_source=client, --default_override=0:common=--isatty=1, --default_override=0:common=--terminal_columns=156, --rc_source=/Users/user_name/trash/examples/frontend/.bazelrc, --rc_source=/Users/user_name/.bazelrc, --default_override=1:common=--@aspect_rules_ts//ts:skipLibCheck=always, //next.js:next]
240515 12:10:24.223:I 8721 [com.google.devtools.build.lib.server.GrpcServerImpl.executeCommand] [build, --startup_time=21, --command_wait_time=0, --extract_data_time=0, --binary_path=/Users/user_name/Library/Caches/bazelisk/downloads/sha256/fb5e7bc62fc3c8f2511e3b64d795296444129b26f13d8dece4d4cee1845b758f/bin/bazel, --rc_source=client, --default_override=0:common=--isatty=1, --default_override=0:common=--terminal_columns=156, --rc_source=/Users/user_name/trash/examples/frontend/.bazelrc, --rc_source=/Users/user_name/.bazelrc, --default_override=1:common=--@aspect_rules_ts//ts:skipLibCheck=always, //next.js:next]

[tpasternak]

I'm not sure if this is related, but I also noticed that commands such as bazel info or bazel mod cause invalidaiton of large portions of skyframe. It can be easily verified with bazel build && bazel dump --skyframe=summary && bazel info && bazel dump --skyframe=summary

[SinimaWath]

@tpasternak You are right.

Checked and even just bazel info invalidate part of cache, thanks!

[fmeum]

@tpasternak Are you using --disk_cache or --remote_cache when you reproduce this?

I'm seeing some weird Skyframe invalidation when using these flags, but not without them.

Changed keys without new values: [ActionLookupData0{actionLookupKey=ConfiguredTargetKey{label=@@rules_java~//toolchains:platformclasspath, config=BuildConfigurationKey[b85621dae172f731976165fe86631f99030f401e70ed2b02d58c69595e5ea36d]}, actionIndex=0}]

[fmeum]

Possibly related: https://github.com/bazelbuild/bazel/issues/22367

@tpasternak Could you build Bazel with the patch I added to that issue and rerun on your reproducer?

[tjgq]

Does this repro with --noexperimental_merged_skyframe_analysis_execution? I'm wondering if it's the limitation described in this commit description (and afaik not yet lifted since then): https://github.com/bazelbuild/bazel/commit/d94816a68980628e43f509bcd6a49e98984658b5 (although I would concur that bazel info at least ought not to invalidate anything).

[tpasternak]

@fmeum with your help I figured out what's wrong - I was using --override_repository when running build, but not when running bazel info. When I tried bazel info --override_repository it didn't trigger skyframe eviction

[tpasternak]

Probably my comments are unrelated to the original issue, sorry for messing

[SinimaWath]

Does this repro with --noexperimental_merged_skyframe_analysis_execution? I'm wondering if it's the limitation described in this commit description (and afaik not yet lifted since then): d94816a (although I would concur that bazel info at least ought not to invalidate anything).

@tjgq

Repro without --noexperimental_merged_skyframe_analysis_execution

[SinimaWath]

Can we up this? The bug is still reproduced.

[reimai]

Might not be realated (it's rather a problem with my settings), but I had an issue with an invalidated action cache. It would drop between runs of bazel info and bazel query. I debugged this a bit, and the problem turned out to be incompatible_unambiguous_label_stringification flag set to false for build commands in .bazelrc:

build --incompatible_unambiguous_label_stringification=false

It affects semantics of bazel build and bazel info:

StarlarkSemantics{enable_bzlmod=false, incompatible_java_common_parameters=false, incompatible_unambiguous_label_stringification=false}

but not bazel query:

StarlarkSemantics{enable_bzlmod=false, incompatible_java_common_parameters=false}

Setting it to common helped to avoid cache eviction, the problem script saved about 30sec on that:

common --incompatible_unambiguous_label_stringification=false

So it might be feasible to look for flags distinct between commands.

[SinimaWath]

@reimai

So it might be feasible to look for flags distinct between commands.

Reproducing even without flags (

[SinimaWath]

Found out, that running bazel info output_base doesn't evict cache.

bazel info output_base && bazel cquery //next.js:next && bazel build //next.js:next works as expected, but running bazel info evict part of cache