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::DefaultCallsite, Callsite as _};
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 {}ms", self.id, self.start.elapsed().as_millis());
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` at the `debug` log level.
66    pub fn new_debug(
67        callsite: &'static DefaultCallsite,
68        id: String,
69        level: tracing::Level,
70    ) -> Self {
71        Self { id, callsite, start: Instant::now(), level }
72    }
73}
74
75/// Macro to create a RAII timer that will log a `tracing` event once it's
76/// dropped.
77///
78/// The tracing level can be specified as a first argument, but it's optional.
79/// If it's missing, this will use the debug level.
80#[macro_export]
81macro_rules! timer {
82    ($level:expr, $string:expr) => {{
83        static __CALLSITE: tracing::callsite::DefaultCallsite = tracing::callsite2! {
84            name: tracing::__macro_support::concat!(
85                "event ",
86                file!(),
87                ":",
88                line!(),
89            ),
90            kind: tracing::metadata::Kind::EVENT,
91            target: module_path!(),
92            level: $level,
93            fields: []
94        };
95
96        $crate::tracing_timer::TracingTimer::new_debug(&__CALLSITE, $string.into(), $level)
97    }};
98
99    ($string:expr) => {
100        $crate::timer!(tracing::Level::DEBUG, $string)
101    };
102}
103
104#[cfg(test)]
105mod tests {
106    #[cfg(not(target_arch = "wasm32"))]
107    #[matrix_sdk_test_macros::async_test]
108    async fn test_timer_name() {
109        use tracing::{span, Level};
110
111        tracing::warn!("Starting test...");
112
113        mod time123 {
114            pub async fn run() {
115                let _timer_guard = timer!(tracing::Level::DEBUG, "test");
116                tokio::time::sleep(ruma::time::Duration::from_millis(123)).await;
117                // Displays: 2023-08-25T15:18:31.169498Z DEBUG
118                // matrix_sdk_common::tracing_timer::tests: test finished in
119                // 124ms
120            }
121        }
122
123        time123::run().await;
124
125        let span = span!(Level::DEBUG, "le 256ms span");
126        let _guard = span.enter();
127
128        let _timer_guard = timer!("in span");
129        tokio::time::sleep(ruma::time::Duration::from_millis(256)).await;
130
131        tracing::warn!("Test about to finish.");
132        // Displays: 2023-08-25T15:18:31.427070Z DEBUG le 256ms span:
133        // matrix_sdk_common::tracing_timer::tests: in span finished in 257ms
134    }
135}
matrix_sdk_common/tracing_timer.rs

matrix_sdk_common/
tracing_timer.rs
