internal: Simplify logger

[Veykril]

Another go at https://github.com/rust-lang/rust-analyzer/pull/11625/files
From the looks of it, removing the tracing-log interop layer works out fine for us since all our log usages are using static paths anyways it seems (and we don't have a lot of things actively depending on log).

[Veykril]

I'm still not happy with this ...

[davidbarsky]

out of curiosity, what would make you happier with logging in rust-analyzer? happy to point you in the right direction.

[Veykril]

I am not quite sure yet :) For one I want to remove the tracing-log part, we shouldn't need it, there is only one dependency that uses log that is somewhat relevant but I think it wouldn't hurt if the logs suffer from that a bit.

I am still a bit uncertain how to properly make use of tracing for our needs here, but in general we want to move our profiling stuff to tracing #3794 and I am very much unsure how to interoperate that with our current tracing logging. I am still quite unsure about how to properly leverage tracing for all these things I think, I tried myself at that issue twice now I think, I unfortunately do not remember what the concrete problems where that I run into but at this point I am a bit too annoyed to try again and I also kind of lost sight of how to approach that issue 😅

[davidbarsky]

I am not quite sure yet :) For one I want to remove the tracing-log part, we shouldn't need it, there is only one dependency that uses log that is somewhat relevant but I think it wouldn't hurt if the logs suffer from that a bit.

That's fair. Like you alluded, if you want that dependency to emit logs that tracing can understand, you'll need tracing-log.

I am still a bit uncertain how to properly make use of tracing for our needs here, but in general we want to move our profiling stuff to tracing #3794 and I am very much unsure how to interoperate that with our current tracing logging.

Naively, I'd add a target/field for things values that you intend profile with, but I think for the performance overhead of tracing when profiling, we'd like to land a change that avoids boxing extensions in the Registry. I've tried to find an issue on tracing's side, but I realized I never wrote one. In the meantime, here's a comment I wrote on Bevy describing the approach: bevyengine/bevy#4892 (comment).

[Veykril]

So (I think) ideally we would want to just be able to slap tracing::instrument on everything we want, the main question is how to "dynamically" enable profiling like we currently can with the profiling env var. I haven't tinkered much with tracing functionality though so maybe we don't even need this kind of configurability? All we need is to be able to trace calls of some specific function and record the timings. Again I haven't really used the tracing ecosystem here so maybe this is just a very simple thing and our current infra makes it look more complex than necessary.

Ideally all we have is really just tracing and no extra stuff I think.

[davidbarsky]

(Sorry for the delay in responding; I thought I responded five days ago!)

I haven't tinkered much with tracing functionality though so maybe we don't even need this kind of configurability? All we need is to be able to trace calls of some specific function and record the timings.

You've got two options:

• @CAD97's tracing-filter: https://github.com/CAD97/tracing-filter
• tracing_subscriber::filter::filter_fn: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/fn.filter_fn.html

Both these options need to be used with https://docs.rs/tracing-subscriber/latest/tracing_subscriber/reload/index.html to live-reload the filters.

I think for performance in profiling to be more reasonable, we (on the tracing side of things) should implement tokio-rs/tracing#2230, which should reduce some of the overhead reported in the Bevy issue I linked to (if that overhead is okay for y'all, then that's great! If not, I can try to prioritize this change.)

[CAD97]

(since I got pinged)

If you want help configuring filtering to select the events you want, please do open a discussion on tracing-filter. The domain for tracing-filter is quite literally to enable whatever span/event filtering/selection anybody could possibly want, so having people actually try to use it is a great boon.

The current state of tracing-filter is just that it can do anything log's envfilter¹ or tracing-subscriber's envfilter² can do, and doing more is being worked on.

Necessary disclaimer: tracing-filter is still alpha software. However,

• The timeline for exiting alpha and releasing 0.3 (1.0 against tracing-subscriber-0.3) is late September / early October.
• Development is active and funded until then by a Rust Foundation grant 🙂
• The simple and legacy filter directives are stable (they're bug-for-bug compatible with upstreams' directive syntax); the unstable bit is the parsing API.

Footnotes

1. Caveat: regex filtering is not implemented yet, because tracing previously did not support it. The needed support for filtering on event fields is in now, so that's next on the docket for the alpha.3 release. ↩

2. It's a bit less lock contention-y than upstream envfilter because it requires being used with a LookupSpan subscriber, whereas upstream envfilter doesn't because it was written before LookupSpan's extensions API was available. ↩

[Veykril]

Alright, thansk for you guys' input, very much appreciated. I'll try out tracing-filter and see where that goes. Fwiw for profiling we currently allow filtering specific (non-tracing) spans by their name and the duration they took. So for example we can say foo>100 which will then only show all foo traces (and the children of such a foo trace) if the foo trace took longer than 100ms. Is this something on your roadmap? If yes I'll put up an issue for discussion regarding that up on tracing-filter.

[CAD97]

Filtering to events inside selected span(s) is something that IIRC EnvFilter can't do¹, but is absolutely on the roadmap for tracing-filter's full functionality.

Filtering by duration is not something I had considered, but is something obviously useful that I'm kinda sad I overlooked as a possibility.

For tracing-filter's initial development push, this is out of scope; it just provides a normal as-they-come-in filter, and it's not possible to go back in time² to include a span('s children) if it takes more than a time threshold.

What this does indicate though is something which can be addressed: querying not just metadata and record fields, but also extension data recorded by subscriber layers. This might require integration into tracing-subscriber and using valuable and/or provide_any to allow querying the typed information without knowing³ the types, but fits nicely as a stretch goal to at least figure out the design space for.

Profiling mostly wants to serialize the tracing data and filter it post facto, which is outside the domain of tracing (and e.g. in the domain of OpenTelemetry). However, I do want to (in a future milestone) allow tracing-filter to also be used to filter recorded tracing data, though doing so will be quite involved due to the differences between having the tracing-subscriber registry and not⁴.

I hope that sort of helps clarify where tracing-filter is positioned?

Footnotes

1. In EnvFilter, the target[span] syntax filters the span's emission itself, and I don't think it impacts the events within the (potentially omitted) span at all. In fact, filtering out the span means you can't even tell if the children are in it, because the span never gets entered, IIUC.

   tracing-filter's "query filter" design tentatively has CSS-like span > event syntax to select on events contained in a span. ↩

2. What could be done and is interesting to consider is including events after the timeframe has passed, even though we can't go back and include the past events.... without buffering, which would allow time travelling the events forward (rather than the filter information backward). ↩

3. At one extreme end of the design space is setting up some sort of "query plugin" system, where e.g. tracing-instant could be a layer which stores Instant in the span extensions, and offers e.g. instant:(…) as a query filter callback into tracing-instant to parse … and filter events/spans on. ↩

4. The biggest one being all of the metadata which tracing expects to be 'static but which isn't when in the deserialized case. I have Ideas about how to remove the 'static requirements from tracing, but this is obviously a quite invasive breaking change to nearly everything. This is a very-long-term project that unfortunately may not be reachable without a significant amount of full-time work inside of tracing cleared to make (justified) breaking changes, whereas tracing-filter is by design restricting itself to being just another downstream plugin. (Though I have added the ability to filter on event fields to tracing proper as part of the tracing-filter work.) ↩