Skip to content

fix: record latency before ret/err events #2

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.

Sign up for GitHub

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

Merged
pruthvikar merged 3 commits into from
Mar 16, 2026
Merged

fix: record latency before ret/err events #2

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
b1db5d6
fix: record latency before ret/err events
pruthvikar Mar 16, 2026
1114d32
style: format expand.rs with rustfmt
pruthvikar Mar 16, 2026
c250d29
fix: resolve clippy warnings in tracing-subscriber
pruthvikar Mar 16, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
73 changes: 44 additions & 29 deletions tracing-attributes/src/expand.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -243,7 +243,9 @@ fn gen_block<B: ToTokens>(
}

let custom_fields = &args.fields;
let latency_field = args.latency.then(|| quote!(latency = ::tracing::field::Empty,));
let latency_field = args
.latency
.then(|| quote!(latency = ::tracing::field::Empty,));

quote!(::tracing::span!(
target: #target,
Expand Down Expand Up @@ -302,10 +304,27 @@ fn gen_block<B: ToTokens>(
// If `ret` is in args, instrument any resulting `Ok`s when the function
// returns `Result`s, otherwise instrument any resulting values.
if async_context {
let latency_inst = args
.latency
.then(|| quote!(let __tracing_attr_latency = ::std::time::Instant::now();));
let latency_record = args.latency.then(|| {
quote!(
__tracing_attr_span.record(
"latency",
__tracing_attr_latency.elapsed().as_millis() as u64,
);
)
});

// Record latency BEFORE ret/err events so it appears in their log output.
// This matches the old TraceLatency Drop behavior where the timer was a
// local inside the block that dropped before events fired.
let mk_fut = match (err_event, ret_event) {
(Some(err_event), Some(ret_event)) => quote_spanned!(block.span()=>
async move {
#latency_inst
let __match_scrutinee = async move #block.await;
#latency_record
match __match_scrutinee {
#[allow(clippy::unit_arg)]
Ok(x) => {
Expand All @@ -321,7 +340,10 @@ fn gen_block<B: ToTokens>(
),
(Some(err_event), None) => quote_spanned!(block.span()=>
async move {
match async move #block.await {
#latency_inst
let __match_scrutinee = async move #block.await;
#latency_record
match __match_scrutinee {
#[allow(clippy::unit_arg)]
Ok(x) => Ok(x),
Err(e) => {
Expand All @@ -333,36 +355,26 @@ fn gen_block<B: ToTokens>(
),
(None, Some(ret_event)) => quote_spanned!(block.span()=>
async move {
#latency_inst
let x = async move #block.await;
#latency_record
#ret_event;
x
}
),
(None, None) => quote_spanned!(block.span()=>
async move #block
async move {
#latency_inst
let __tracing_attr_result = async move #block.await;
#latency_record
__tracing_attr_result
}
),
};

let latency_inst = args.latency.then(|| {
quote!(let __tracing_attr_latency = ::std::time::Instant::now();)
});
let latency_record = args.latency.then(|| {
quote!(
__tracing_attr_span.record(
"latency",
__tracing_attr_latency.elapsed().as_millis() as u64,
);
)
});

return quote!(
let __tracing_attr_span = #span;
let __tracing_instrument_future = async {
#latency_inst
let __tracing_attr_result = #mk_fut .await;
#latency_record
__tracing_attr_result
};
let __tracing_instrument_future = #mk_fut;
if !__tracing_attr_span.is_disabled() {
#follows_from
::tracing::Instrument::instrument(
Expand All @@ -376,9 +388,9 @@ fn gen_block<B: ToTokens>(
);
}

let latency_inst = args.latency.then(|| {
quote!(let __tracing_attr_latency = ::std::time::Instant::now();)
});
let latency_inst = args
.latency
.then(|| quote!(let __tracing_attr_latency = ::std::time::Instant::now();));
let latency_record = args.latency.then(|| {
quote!(
__tracing_attr_span.record(
Expand Down Expand Up @@ -409,11 +421,14 @@ fn gen_block<B: ToTokens>(
#latency_inst
);

// Record latency BEFORE ret/err events so it appears in their log output.
match (err_event, ret_event) {
(Some(err_event), Some(ret_event)) => quote_spanned! {block.span()=>
#span
#[allow(clippy::redundant_closure_call)]
let __tracing_attr_result = match (move || #block)() {
let __tracing_attr_block_result = (move || #block)();
#latency_record
let __tracing_attr_result = match __tracing_attr_block_result {
#[allow(clippy::unit_arg)]
Ok(x) => {
#ret_event;
Expand All @@ -424,29 +439,29 @@ fn gen_block<B: ToTokens>(
Err(e)
}
};
#latency_record
__tracing_attr_result
},
(Some(err_event), None) => quote_spanned!(block.span()=>
#span
#[allow(clippy::redundant_closure_call)]
let __tracing_attr_result = match (move || #block)() {
let __tracing_attr_block_result = (move || #block)();
#latency_record
let __tracing_attr_result = match __tracing_attr_block_result {
#[allow(clippy::unit_arg)]
Ok(x) => Ok(x),
Err(e) => {
#err_event;
Err(e)
}
};
#latency_record
__tracing_attr_result
),
(None, Some(ret_event)) => quote_spanned!(block.span()=>
#span
#[allow(clippy::redundant_closure_call)]
let x = (move || #block)();
#ret_event;
#latency_record
#ret_event;
x
),
(None, None) => quote_spanned!(block.span() =>
Expand Down
6 changes: 3 additions & 3 deletions tracing-subscriber/src/filter/env/field.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -169,7 +169,7 @@ impl Match {
let value = parts
.next()
.map(|part| match regex {
true => ValueMatch::parse_regex(part),
true => ValueMatch::parse_regex(part).map_err(Box::new),
false => Ok(ValueMatch::parse_non_regex(part)),
})
.transpose()?;
Expand Down Expand Up @@ -334,7 +334,7 @@ impl Eq for MatchPattern {}
impl PartialOrd for MatchPattern {
#[inline]
fn partial_cmp(&self, other: &Self) -> Option<Ordering> {
Some(self.pattern.cmp(&other.pattern))
Some(self.cmp(other))
}
}

Expand Down Expand Up @@ -430,7 +430,7 @@ impl Eq for MatchDebug {}
impl PartialOrd for MatchDebug {
#[inline]
fn partial_cmp(&self, other: &Self) -> Option<Ordering> {
Some(self.pattern.cmp(&other.pattern))
Some(self.cmp(other))
}
}

Expand Down
Loading