Implement a way to be able to debug cache misses that can be always on without too much overhead

[lberki]

Description of the feature request:

Sometimes, it's useful to be able to dig into why a particular action was not cached by remote execution.

The usual culprits are a changed input file, different input files or a different command line. Bazel provides ample tools to query what it would run (aquery) and what it did (--execution_log_*_file or the BEP) but neither of these is amenable to post-facto debugging:

• aquery requires extra conscious effort
• The execution logs are too large to be always uploaded
• The BEP does not contain enough information

So it would be nice to be able to do some sort of logging to answer questions like "why did this build done two days ago did not reuse the cached actions from that other build done 30 minutes before it".

This doesn't necessarily need to be done within Bazel (although that's the particular hammer I have); I could also imagine logging on the remote execution side where it is logged with actions are done by which Bazel invocations.

What underlying problem are you trying to solve with this feature?

Being able to tell why a particular action was not cached so that future cache hit rates are higher.

Which operating system are you running Bazel on?

No response

What is the output of bazel info release?

No response

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 master; git rev-parse HEAD ?

No response

Have you found anything relevant by searching the web?

No response

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

No response

[tbaing]

Our exec logs turn out to be ~120GB (and ~150GB once run through the parser) so we'd appreciate anything that can significantly reduce the amount of output while still letting us answer questions about which actions needed a rebuild (rather than being reusable from cache) and which dependencies drove that need.

[lberki]

cc @ramymedhat

[meisterT]

Ok, I did look into this a bit and found some issues and some avenues.

Reducing the size

There is is a couple things we could do to reduce the size of the output:

• use compression, zstd has proven most useful a couple of times both because of low CPU cost and good compression rates
• use an indexed format for artifacts instead of listing each artifact in full where it appears as input or output
• instead of listing inputs as a list, include the nested set structure, again indexed; this is non-trivial and would incur additional CPU cost, so I would like to avoid that.
• leaner proto with less fields populated (removing command lines, listed outputs, textual status, progress message)

I tried zstd compression outside of Bazel (but this can easily be done within Bazel as well if we decide this is the way to go) and also did some dirty hacks to understand the benefits from artifact indexing and a leaner proto.

large build:

what	without compression	zstd compressed
before	99GB	20GB
artifact indexing	5.1GB	610MB
artifact indexing plus lean fields	2.3GB	450MB

medium build:

what	without compression	zstd compressed
before	1.3GB	65MB
artifact indexing	217MB	14MB
artifact indexing plus lean fields	47MB	9MB

The path indexing contains the exact same information as before, but needs to be re-constructed to compare. The lean format does leave out information but probably most of these are not relevant, one exception is command lines where I would store one high level hash. You can still see that the command line has changed and you can reconstruct it, e.g. using aquery. A tool could do this, see more below.

Performance overhead

I noticed that action execution was quite a bit slower with the execution log turned on (regardless of which variant). I added more profiling to the JSON trace profile to better understand it (and will send a PR to add this permanently). For the large build from above, the with the exec log it took ~75mins, without ~7mins.

I think we should move to a producer / consumer pattern where we put spawns to be processed in a queue and work on writing the file in a separate thread. We have to see how much overhead this pattern is memory-wise.

I am not sure whether that is enough to reduce the overhead into acceptable levels.

Different formats

We should use the opportunity to clean up the different logging options anyway. Currently we have:

• --experimental_execution_log_file: “unordered” spawn protos
• --execution_log_binary_file: First writes the file from above to /tmp and then parses it again and then sorts it in stable order which is CPU and memory intensive (e.g. see improve usability of --experimental_execution_log_file #6807). In my opinion, this is nothing that should live in Bazel and should be removed.
• --execution_log_json_file: Same as --execution_log_binary_file, should also go away at least in the current form with sorting. @aherrmann mentions in Documentation issue: Debugging remote cache hits for remote execution #12770 that the JSON format has the advantage of using jq and being human readable. So, we might want to keep the option to output both binary and JSON around in some form.
• --experimental_execution_log_spawn_metrics: Adds spawn metrics to the profile. If we add an option to produce a leaner exec log as mentioned above, we could consider making this option go away and write it always unless the lean log format is requested.

Perhaps it would also make sense to add an option to only write the exec log for specific actions (basically filtering on mnemonics and targets, see also #12075) and for the other actions only include high-level information? This would not only help addressing size issues but also performance concerns.

How to compare protos

For large exec logs, a tool to compare them is essential. @coeuvre created https://github.com/coeuvre/bazel-find-non-deterministic-actions - it helps finding deterministic actions, but is built on top of the JSON output. The tool needs to be changed to support the lean proto format.

Then we could also let the tool spit out other helpful commands like bazel aquery for further debugging.

Related issues

• Include execution cache hit ratios #16043: Include execution cache hit ratios
• View local cache hits and compare against remote cache hits #12960: View local cache hits and compare against remote cache hits
• Documentation issue: Debugging remote cache hits for remote execution #12770: documentation is stale
• Feature request: Filtering execution log #12075: FR to add filtering
• improve usability of --experimental_execution_log_file #6807: stable sorting is expensive
• Stable sort of execution logs is unaware of shards #15155: stable sorting is buggy
• Execlog parser should output each action's digest  #16741: usability concerns
• An --execution-log-level= flag that determines the level of execution logging #13269: FR to add control over how much data is in the exec log
• Execution log file doesn't expand params files #8718: FR to expand param files

Next steps

I am aware that I am abusing this feature request a little bit to do one step back and understand the bigger picture. I want to give people some time to voice their opinions here before proceeding, so please let me know what you think.

[sheldonneuberger-sc]

@meisterT thanks for that detailed outline, it aligns with what I see too: massive exec logs (50GB+), and the build is slower if exec log is on. I'd prefer to have exec logging always on, but this makes it unworkable.

[chancilasnap]

we would prefer this data be visible through BES somehow, be it as a cas artifact (like the profile) or via special messages...the BES also prints actions (generally on failure only) but it can emit all actions in a slightly different format...it's annoying the BES actions and exec log spawns don't match since exec log seems richer...

I noticed that action execution was quite a bit slower with the execution log turned on (regardless of which variant). I added more profiling to the JSON trace profile to better understand it (and will send a PR to add this permanently). For the large build from above, the with the exec log it took ~75mins, without ~7mins.

I think we should move to a producer / consumer pattern where we put spawns to be processed in a queue and work on writing the file in a separate thread. We have to see how much overhead this pattern is memory-wise.

I am not sure whether that is enough to reduce the overhead into acceptable levels.

are execlogs written in the threads running the actions? seems like that would have huge contention issues possibly