-
Notifications
You must be signed in to change notification settings - Fork 12.9k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
[experiment] Enable debug-logging by default #111924
Conversation
@bors try @rust-timer queue |
This comment has been minimized.
This comment has been minimized.
⌛ Trying commit 8dd0f8f0c44b0f41a5dd1c4f2c05291c747a280c with merge e2de86325568355c6a9821deb2a4454056df5ddf... |
☀️ Try build successful - checks-actions |
This comment has been minimized.
This comment has been minimized.
Finished benchmarking commit (e2de86325568355c6a9821deb2a4454056df5ddf): comparison URL. Overall result: ❌ regressions - ACTION NEEDEDBenchmarking this pull request likely means that it is perf-sensitive, so we're automatically marking it as not fit for rolling up. While you can manually mark this PR as fit for rollup, we strongly recommend not doing so since this PR may lead to changes in compiler perf. Next Steps: If you can justify the regressions found in this try perf run, please indicate this with @bors rollup=never Instruction countThis is a highly reliable metric that was used to determine the overall result at the top of this comment.
Max RSS (memory usage)ResultsThis is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.
CyclesResultsThis is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.
Binary sizeThis benchmark run did not return any relevant results for this metric. Bootstrap: 647.059s -> 675.597s (4.41%) |
We could probably change various |
@bors try @rust-timer queue |
This comment has been minimized.
This comment has been minimized.
⌛ Trying commit a5a5d00576d7b8bb3d5098eeb487e2ead21fb412 with merge dd6ffc5d6d4227555cbf5114e84563776133d50e... |
This comment has been minimized.
This comment has been minimized.
@rust-timer build dd6ffc5d6d4227555cbf5114e84563776133d50e |
This comment has been minimized.
This comment has been minimized.
Finished benchmarking commit (dd6ffc5d6d4227555cbf5114e84563776133d50e): comparison URL. Overall result: ❌ regressions - ACTION NEEDEDBenchmarking this pull request likely means that it is perf-sensitive, so we're automatically marking it as not fit for rolling up. While you can manually mark this PR as fit for rollup, we strongly recommend not doing so since this PR may lead to changes in compiler perf. Next Steps: If you can justify the regressions found in this try perf run, please indicate this with @bors rollup=never Instruction countThis is a highly reliable metric that was used to determine the overall result at the top of this comment.
Max RSS (memory usage)ResultsThis is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.
CyclesResultsThis is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.
Binary sizeThis benchmark run did not return any relevant results for this metric. Bootstrap: 644.952s -> 665.666s (3.21%) |
@bors try @rust-timer queue |
This comment has been minimized.
This comment has been minimized.
forgot to start the timer apparently 🤦 @bors try @rust-timer queue |
This comment has been minimized.
This comment has been minimized.
⌛ Trying commit a97eec4 with merge 3a5274a5159b2c2e9e8614d529da73af3b9bea6f... |
☀️ Try build successful - checks-actions |
This comment has been minimized.
This comment has been minimized.
Finished benchmarking commit (3a5274a5159b2c2e9e8614d529da73af3b9bea6f): comparison URL. Overall result: ❌ regressions - ACTION NEEDEDBenchmarking this pull request likely means that it is perf-sensitive, so we're automatically marking it as not fit for rolling up. While you can manually mark this PR as fit for rollup, we strongly recommend not doing so since this PR may lead to changes in compiler perf. Next Steps: If you can justify the regressions found in this try perf run, please indicate this with @bors rollup=never Instruction countThis is a highly reliable metric that was used to determine the overall result at the top of this comment.
Max RSS (memory usage)ResultsThis is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.
CyclesResultsThis is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.
Binary sizeThis benchmark run did not return any relevant results for this metric. Bootstrap: 643.715s -> 661.714s (2.80%) |
Ok, I think I'm hitting diminishing returns on demoting things from debug to trace. I don't think it's going to go much below a 3% regression. @hawkw do you know if there's any remaining low-hanging fruit for speeding up event! calls? Happy to invest time into it if you have a suggestions on how to set up a proper benchmark. |
to be clear, I'm talking about the case when no subscriber is registered, it's fine to be slow if RUSTC_LOG=debug is set |
Uhh...we have benchmarks around this in |
FWIW, disabled |
@hawkw can you talk more about Spans? the two main ways rustc uses the core tracing library are through |
The |
Got it. I'm trying to lower the max_static_level from let __tracing_attr_span;
let __tracing_attr_guard;
if tracing::Level::DEBUG <= ::tracing::level_filters::STATIC_MAX_LEVEL
&& tracing::Level::DEBUG <= ::tracing::level_filters::LevelFilter::current()
{
__tracing_attr_span = /* ... */ |
actually, let me see if I can get a cachegrind report of exactly what's slower, that will be easier than trying to figure this out from first principles |
Hmm, |
ahh, yeah I see this snippet in the function-like macros that's not in the instrument macro: && {
let interest = CALLSITE.interest();
!interest.is_never()
&& $crate::__macro_support::__is_enabled(CALLSITE.metadata(), interest)
}; |
that's a slower path for per-callsite cached interests --- it happens when a subscriber does exist and the level is less verbose than the static max level. it happens inside the |
(by "slow path" i suppose what i really mean is "less fast path", since the actually slow path is to actually ask a filter what it thinks of a particular piece of span metadata --- the cached interest path is so that we can avoid having to do that more than once) |
lol this just shows the calling functions being slower - don't know what i expected
|
I'm going to close this for now - don't have ideas on how to speed it up further and 3% seems too heavy to land unfortunately. |
Make queries traceable again This can't be tested without something along the lines of rust-lang#111924 unfortunately. We could benchmark turning query tracing into an `info` level tracing statement, but let's get this fix landed first so we can actually debug properly again
Make queries traceable again This can't be tested without something along the lines of rust-lang#111924 unfortunately. We could benchmark turning query tracing into an `info` level tracing statement, but let's get this fix landed first so we can actually debug properly again
#74726 (comment):
r? @ghost