Reduce log verbosity from info -> trace for many common functions

[kevinaboos]

At the default INFO log level, the log gets inundated with thousands of emitted statements, primarily related to is_display_name_ambiguous(). The execution of this tiny function certainly doesn't need to be traced every time, at least not at the info log level.

Note: some of these could be debatably reduced to debug level rather than trace level, but I went with "trace" because they all seem to be trace statements rather than actual debug dump outputs (there is no actual program state dumped out).

Signed-off-by: Kevin Boos [email protected]

[codecov]

Codecov Report

Attention: Patch coverage is 85.71429% with 1 line in your changes missing coverage. Please review.

Project coverage is 86.13%. Comparing base (c33c61a) to head (0ad31b7).

Files with missing lines	Patch %	Lines
crates/matrix-sdk-ui/src/timeline/builder.rs	75.00%	1 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #4747      +/-   ##
==========================================
- Coverage   86.15%   86.13%   -0.02%     
==========================================
  Files         292      292              
  Lines       34304    34304              
==========================================
- Hits        29553    29549       -4     
- Misses       4751     4755       +4     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[bnjbvr]

Thanks! Makes sense, these logs can be verbose. I'm less certain about the span changes, though: I think those span make sense to keep, to isolate where things are happening; could we keep them, please?

[bnjbvr]

This will only create a span (i.e. instrument) if the level is trace, does it actually change anything, since the only log i can see below is already at the trace log level?

[kevinaboos]

yes, this was the key change that made a difference. The default level of tracing's instrument attribute is the INFO level, according to their docs. So, without this, the instrumentation tracing printout of this function will occur at the INFO level.

[kevinaboos]

oh, perhaps i misunderstood what you were asking. if you were asking about how this change affects the trace!("Checking if a display name is ambiguous"); line within this function, then the answer is that they're separate.

This attribute adds an implicit trace/log output every time that this function is entered, which is what caused the ~4000 INFO-level log outputs in Robrix. The latter trace!() statement in line 94 is an independent, explicit trace statement that is independent from the instrumentation attribute.

[bnjbvr]

so, I learned about the log level parameter for a span only as of today, so please bear with me :)

My understanding was that if a span is at log level ABC, then this log level ABC must be enabled at runtime for the span to be instantiated; otherwise, it is not.

So when if I have:

#[instrument(level = "trace")
fn my_func(val: u32) {
  tracing::trace!("le trace");
  tracing::warn!("le warning");
}

and I'm running this with RUST_LOG=warn, then I'll see, with the default tracing subscriber formatter:

le warning

but if I run with RUST_LOG=trace, then I'll get:

my_func(val = 42): le trace
my_func(val = 42): le warning

Is that understanding correct? If so, maybe I misunderstood your intent, and you only wanted to reduce the size of an individual line, by having fewer recorded fields in a span, etc.?

(In that case: i'll need to check on a case-by-case basis, but I think the context brought by some of these spans is always useful, so we might want to enable them all the time.)

[bnjbvr]

I think we should keep these spans at the regular log level, as they're important to realize where a log message is coming from.

[kevinaboos]

oh sure, that's a fair point. I originally changed it to follow the adjusted log levels from INFO -> TRACE in the actual log statements in L329 and L340, but yea it would definitely make sense to keep this span at the info level for any other info-level trace logs that get emitted within that span.

On that note, there is also an explicit warn!() statement in L234, which would not be affected by this span even if i change it back to the INFO level. Is that intentional/desired?

[bnjbvr]

ditto here