matrix_sdk_common/tracing_timer.rs
1// Copyright 2023 The Matrix.org Foundation C.I.C.
2//
3// Licensed under the Apache License, Version 2.0 (the "License");
4// you may not use this file except in compliance with the License.
5// You may obtain a copy of the License at
6//
7// http://www.apache.org/licenses/LICENSE-2.0
8//
9// Unless required by applicable law or agreed to in writing, software
10// distributed under the License is distributed on an "AS IS" BASIS,
11// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12// See the License for the specific language governing permissions and
13// limitations under the License.
14
15use ruma::time::Instant;
16use tracing::{Callsite as _, callsite::DefaultCallsite};
17
18/// A named RAII that will show on `Drop` how long its covered section took to
19/// execute.
20pub struct TracingTimer {
21 id: String,
22 callsite: &'static DefaultCallsite,
23 start: Instant,
24 level: tracing::Level,
25}
26
27#[cfg(not(tarpaulin_include))]
28impl std::fmt::Debug for TracingTimer {
29 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
30 f.debug_struct("TracingTimer").field("id", &self.id).field("start", &self.start).finish()
31 }
32}
33
34impl Drop for TracingTimer {
35 fn drop(&mut self) {
36 let message = format!("_{}_ finished in {:?}", self.id, self.start.elapsed());
37
38 let enabled = tracing::level_enabled!(self.level) && {
39 let interest = self.callsite.interest();
40 !interest.is_never()
41 && tracing::__macro_support::__is_enabled(self.callsite.metadata(), interest)
42 };
43
44 if !enabled {
45 return;
46 }
47
48 let metadata = self.callsite.metadata();
49 let fields = metadata.fields();
50 let message_field = fields.field("message").unwrap();
51 #[allow(trivial_casts)] // The compiler is lying, it can't infer this cast
52 let values = [(&message_field, Some(&message as &dyn tracing::Value))];
53
54 // This function is hidden from docs, but we have to use it
55 // because there is no other way of obtaining a `ValueSet`.
56 // It's not entirely clear why it is private. See this issue:
57 // https://github.com/tokio-rs/tracing/issues/2363
58 let values = fields.value_set(&values);
59
60 tracing::Event::dispatch(metadata, &values);
61 }
62}
63
64impl TracingTimer {
65 /// Create a new `TracingTimer`.
66 pub fn new(callsite: &'static DefaultCallsite, id: String, level: tracing::Level) -> Self {
67 Self { id, callsite, start: Instant::now(), level }
68 }
69}
70
71/// Macro to create a RAII timer that will log on `Drop` how long its covered
72/// section took to execute.
73///
74/// The tracing level can be specified as a first argument, but it's optional.
75/// If it's missing, this will use the debug level.
76///
77/// ```rust,no_run
78/// # fn do_long_computation(_x: u32) {}
79/// # fn main() {
80/// use matrix_sdk_common::timer;
81///
82/// // It's possible to specify the tracing level we want to be used for the log message on drop.
83/// {
84/// let _timer = timer!(tracing::Level::TRACE, "do long computation");
85/// // But it's optional; by default it's set to `DEBUG`.
86/// let _debug_timer = timer!("do long computation but time it in DEBUG");
87/// // The macro doesn't support formatting / structured events (yet?), but you can use
88/// // `format!()` for that.
89/// let other_timer = timer!(format!("do long computation for parameter = {}", 123));
90/// do_long_computation(123);
91/// } // The log statements will happen here.
92/// # }
93/// ```
94#[macro_export]
95macro_rules! timer {
96 ($level:expr, $string:expr) => {{
97 static __CALLSITE: tracing::callsite::DefaultCallsite = tracing::callsite2! {
98 name: tracing::__macro_support::concat!(
99 "event ",
100 file!(),
101 ":",
102 line!(),
103 ),
104 kind: tracing::metadata::Kind::EVENT,
105 target: module_path!(),
106 level: $level,
107 fields: []
108 };
109
110 $crate::tracing_timer::TracingTimer::new(&__CALLSITE, $string.into(), $level)
111 }};
112
113 ($string:expr) => {
114 $crate::timer!(tracing::Level::DEBUG, $string)
115 };
116}
117
118#[cfg(test)]
119mod tests {
120 #[cfg(not(target_family = "wasm"))]
121 #[matrix_sdk_test_macros::async_test]
122 async fn test_timer_name() {
123 use tracing::{Level, span};
124
125 tracing::warn!("Starting test...");
126
127 mod time123 {
128 pub async fn run() {
129 let _timer_guard = timer!(tracing::Level::DEBUG, "test");
130 tokio::time::sleep(ruma::time::Duration::from_millis(123)).await;
131 // Displays: 2023-08-25T15:18:31.169498Z DEBUG
132 // matrix_sdk_common::tracing_timer::tests: _test_ finished in
133 // 124ms
134 }
135 }
136
137 time123::run().await;
138
139 let span = span!(Level::DEBUG, "le 256ms span");
140 let _guard = span.enter();
141
142 let _timer_guard = timer!("in span");
143 tokio::time::sleep(ruma::time::Duration::from_millis(256)).await;
144
145 tracing::warn!("Test about to finish.");
146 // Displays: 2023-08-25T15:18:31.427070Z DEBUG le 256ms span:
147 // matrix_sdk_common::tracing_timer::tests: in span finished in 257ms
148 }
149}