Setup tracing and document tracing usage #12730
Conversation
crates/red_knot/src/logging.rs
Outdated
| struct RedKnotFormat { | ||
| display_timestamp: bool, | ||
| display_level: bool, | ||
| show_spans: bool, | ||
| } | ||
|
|
||
| /// See <https://docs.rs/tracing-subscriber/0.3.18/src/tracing_subscriber/fmt/format/mod.rs.html#1026-1156> | ||
| impl<S, N> FormatEvent<S, N> for RedKnotFormat | ||
| where | ||
| S: Subscriber + for<'a> LookupSpan<'a>, | ||
| N: for<'a> FormatFields<'a> + 'static, | ||
| { | ||
| fn format_event( | ||
| &self, | ||
| ctx: &FmtContext<'_, S, N>, | ||
| mut writer: Writer<'_>, | ||
| event: &Event<'_>, | ||
| ) -> fmt::Result { | ||
| let meta = event.metadata(); | ||
| let ansi = writer.has_ansi_escapes(); | ||
|
|
||
| if self.display_timestamp { | ||
| let timestamp = chrono::Local::now() | ||
| .format("%Y-%m-%d %H:%M:%S.%f") | ||
| .to_string(); | ||
| if ansi { | ||
| write!(writer, "{} ", timestamp.dimmed())?; | ||
| } else { | ||
| write!( | ||
| writer, | ||
| "{} ", | ||
| chrono::Local::now().format("%Y-%m-%d %H:%M:%S.%f") | ||
| )?; | ||
| } | ||
| } | ||
|
|
||
| if self.display_level { | ||
| let level = meta.level(); | ||
| // Same colors as tracing | ||
| if ansi { | ||
| let formatted_level = level.to_string(); | ||
| match *level { | ||
| tracing::Level::TRACE => { | ||
| write!(writer, "{} ", formatted_level.purple().bold())? | ||
| } | ||
| tracing::Level::DEBUG => write!(writer, "{} ", formatted_level.blue().bold())?, | ||
| tracing::Level::INFO => write!(writer, "{} ", formatted_level.green().bold())?, | ||
| tracing::Level::WARN => write!(writer, "{} ", formatted_level.yellow().bold())?, | ||
| tracing::Level::ERROR => write!(writer, "{} ", level.to_string().red().bold())?, | ||
| } | ||
| } else { | ||
| write!(writer, "{level} ")?; | ||
| } | ||
| } | ||
|
|
||
| if self.show_spans { | ||
| let span = event.parent(); | ||
| let mut seen = false; | ||
|
|
||
| let span = span | ||
| .and_then(|id| ctx.span(id)) | ||
| .or_else(|| ctx.lookup_current()); | ||
|
|
||
| let scope = span.into_iter().flat_map(|span| span.scope().from_root()); | ||
|
|
||
| for span in scope { | ||
| seen = true; | ||
| if ansi { | ||
| write!(writer, "{}:", span.metadata().name().bold())?; | ||
| } else { | ||
| write!(writer, "{}:", span.metadata().name())?; | ||
| } | ||
| } | ||
|
|
||
| if seen { | ||
| writer.write_char(' ')?; | ||
| } | ||
| } | ||
|
|
||
| ctx.field_format().format_fields(writer.by_ref(), event)?; | ||
|
|
||
| writeln!(writer) | ||
| } | ||
| } |
There was a problem hiding this comment.
This is copied from uv. The only change is that I use local time over UTC time.
MichaReiser
force-pushed
the
red-knot-tracing
branch
from
f57e6fd to
5af2483
Compare
MichaReiser
force-pushed
the
red-knot-tracing
branch
from
5af2483 to
d0e2d78
Compare
MichaReiser
force-pushed
the
red-knot-tracing
branch
from
d0e2d78 to
9587230
Compare
MichaReiser
force-pushed
the
red-knot-tracing
branch
from
96c8bab to
268088c
Compare
|
What the heck it's not even user-facing and it's nicer than the setup we have in uv! |
|
Do you turn on nested span indentation at higher verbosity levels? That's kind of nice. |
MichaReiser
force-pushed
the
red-knot-tracing
branch
from
268088c to
9927c38
Compare
It's roughly the same as uv where Most of the code is actually just adopted from UV. |
|
MichaReiser
force-pushed
the
red-knot-tracing
branch
2 times, most recently
from
500d4d9 to
b0a37e9
Compare
MichaReiser
force-pushed
the
red-knot-tracing
branch
from
b0a37e9 to
24cda44
Compare
There was a problem hiding this comment.
This looks amazing!! Thanks for the clear documentation.
The one thing not mentioned here which I would find really useful is how to enable this for a test in e.g. red_knot_python_semantic crate, or if that's even doable. I often find myself debugging something in the context of a test, and it would be really useful to have tracing output.
| @@ -0,0 +1,103 @@ | |||
| # Tracing | |||
There was a problem hiding this comment.
I assume that the crates/red_knot/docs/... directory is for developer-facing docs, not user-facing docs?
There was a problem hiding this comment.
For now, that's certainly true I don't know about long-term. We could have docs/users and docs/dev if we end up with needing both. But most user-facing documentation should probably live on the website.
|
@carljm in what kind of tracing are you interested in tests? Is it the log messages or primarily the trace spans (or both) A test helper that accepts an EnvFilter does sound useful for ad-hoc test inspections. |
|
Potentially both. It's for the same debugging purposes that you'd use |
I can take a look as a separate (low priority) PR. I don't think I want to expose both |
CodSpeed Performance ReportMerging #12730 will improve performances by 7.46%Comparing Summary
Benchmarks breakdown
|
This PR extends our tracing configuration with more refined verbosity levels and adds a small guide on how/when to use tracing.
Filtering
I haven't figured out how to do field-level filtering. It is supported according to the
EnvFilterdocs but I always get too many events even if I write complete rubbish field filters ;(Existing messages
We should revisit our existing messages and improve them. But we can do so while working on the relevant code and as we learn more about logging.
When to use instrument
My take on this is that
instrumenthelps us to get nice flamegraphs and to attribute events to specific spans. I'm not entirely sure yet what the right amount ofinstrumentattributes is. I suspect that we currently have too many. Let's figure this out over time.Test plan
Using
-vUsing
-vvUsing
-vvvin release mode