Outline all tracing events

[ibraheemdev]

It doesn't make sense for these to be inlined as they're typically disabled anyways.

[netlify]

✅ Deploy Preview for salsa-rs canceled.

Name	Link
🔨 Latest commit	e982eb8
🔍 Latest deploy log	https://app.netlify.com/projects/salsa-rs/deploys/687fce9efe2ec10008d1c59d

[codspeed-hq]

CodSpeed Performance Report

Merging #942 will improve performances by 7.21%

_{Comparing ibraheemdev:ibraheem/optimize-tracing (e982eb8) with master (53cd6b1)}

Summary

⚡ 2 improvements
✅ 10 untouched benchmarks

Benchmarks breakdown

	Benchmark	BASE	HEAD	Change
⚡	amortized[InternedInput]	2.6 µs	2.4 µs	+7.21%
⚡	amortized[SupertypeInput]	3.1 µs	2.9 µs	+5.73%

[MichaReiser]

An alternative to this could be something like bevyengine/bevy#7639

So that the logs can be removed statically at compile time. It may require us to fine tune some of the log levels used by salsa

[davidbarsky]

An alternative to this could be something like bevyengine/bevy#7639

So that the logs can be removed statically at compile time. It may require us to fine tune some of the log levels used by salsa

Personally, I don't recommend it. We made a mistake using cargo's features to compile out tracing; we should have used RUSTFLAGS instead.

[MichaReiser]

Personally, I don't recommend it. We made a mistake using cargo's features to compile out tracing; we should have used RUSTFLAGS instead.

Can you say more? How would a RUSTFLAGS approach work?

[davidbarsky]

Personally, I don't recommend it. We made a mistake using cargo's features to compile out tracing; we should have used RUSTFLAGS instead.

Can you say more?

Cargo features are additive and therefore unify across the crate graph, while RUSTFLAGS do not. The latter can only be set by the root Cargo package and do not propagate across a cargo publish. This means that the existing compile-time filtering features in tracing can be enabled at distance by another dependency in your crate graph.

How would a RUSTFLAGS approach work?

Take a look at Tokio's usage; I think the examples are pretty solid.

[MichaReiser]

Oh interesting. Thanks for explaining. I wasn't aware that RUSTFLAGS exist and can be used that way.

[ibraheemdev]

I realized that the enabled macro does a lot of work for checking fine-grained event filters, compared to checking LevelFilter::current, which just loads a global atomic. The downside of a compile-time setting is of course that you have to recompile salsa just to enable logging, which is particularly difficult for users trying to submit extra context for a bug report. I think it's fine to have a runtime check, especially if it's just a load and branch.

FWIW Tracing also has max_level_* feature flags which should eliminate the branches if we check the STATIC_MAX_LEVEL constant FWIW, though that of course applies globally not just to salsa.

[MichaReiser]

FWIW Tracing also has max_level_* feature flags which should eliminate the branches if we check the STATIC_MAX_LEVEL constant FWIW, though that of course applies globally not just to salsa.

We use this in ty for TRACE level logs but Salsa has many debug/info level traces with which this won't help :(

[ibraheemdev]

I realized that LevelFilter::current isn't really helpful when you have per-crate filters.. maybe it is worth having a compile-time flag here.

[ibraheemdev]

Alternatively, we could make the assumption that the logging filters do not change across calls to salsa (e.g. you aren't using scoped subscribers for different queries), at least within the same thread, and cache the check.

[davidbarsky]

I think it's fine to have a runtime check, especially if it's just a load and branch.

That’s unironically the unofficial tracing: it’s just a load and branch!

Alternatively, we could make the assumption that the logging filters do not change across calls to salsa (e.g. you aren't using scoped subscribers for different queries), at least within the same thread, and cache the check.

iirc, tracing should be doing something similar to internally. by the way of example, i think compile-time filters only have rustc about 1%, and that’s because rustc does a lot of per-process invocations, but Salsa is typically used in long-lived processes.

[ibraheemdev]

iirc, tracing should be doing something similar to internally

tracing::enabled has to check:

1. TheMAX_LEVEL constant.
2. The callsite interest.
3. The global subscriber filter.
4. The scoped subscriber filter.

Actually it does those last two steps twice (tokio-rs/tracing#3342)! Switching to the LevelFilter::current check (which is the ideal case of just a single flag) improved the benchmarks by almost 5%, so there's real potential savings there. We could also maybe cache the check in attach, so within a given query execution (including nested query calls) we assume that the subscriber does not change, which seems reasonable.

[ibraheemdev]

I reverted the last commit, so this just uses tracing::enabled! now. This should still be a clear improvement and hopefully can be optimized more on the tracing side.

[MichaReiser]

Oh no... you just demonstrated that there's still a salsa concurrency bug

    thread '<unnamed>' panicked at /home/runner/work/salsa/salsa/src/storage.rs:249:23:
    assertion `left == right` failed
      left: 2
     right: 0
    note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Edit: Never mind, that's the one we are aware of (par_map)