diff --git a/Cargo.lock b/Cargo.lock index 4e82598a3..05ef6635a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3162,6 +3162,8 @@ dependencies = [ "serde", "serde_json", "tokio", + "tracing", + "tracing-subscriber", "wasm-bindgen-futures", "wasm-bindgen-test", ] diff --git a/bindings/matrix-sdk-ffi/src/tracing.rs b/bindings/matrix-sdk-ffi/src/tracing.rs index eb3d4dd5b..ea42047d9 100644 --- a/bindings/matrix-sdk-ffi/src/tracing.rs +++ b/bindings/matrix-sdk-ffi/src/tracing.rs @@ -26,9 +26,9 @@ fn log_event(file: String, line: Option, level: LogLevel, target: String, m let id = MetadataId { file, line, level, target, name: None }; let callsite = get_or_init_metadata(&CALLSITES, id, &["message"], MetadataKind::EVENT); - let metadata = callsite.metadata(); if span_or_event_enabled(callsite) { + let metadata = callsite.metadata(); let fields = metadata.fields(); let message_field = fields.field("message").unwrap(); #[allow(trivial_casts)] // The compiler is lying, it can't infer this cast diff --git a/crates/matrix-sdk-common/Cargo.toml b/crates/matrix-sdk-common/Cargo.toml index 8941690f5..9fcc5b81b 100644 --- a/crates/matrix-sdk-common/Cargo.toml +++ b/crates/matrix-sdk-common/Cargo.toml @@ -24,6 +24,7 @@ instant = "0.1.12" ruma = { workspace = true } serde = { workspace = true } serde_json = { workspace = true } +tracing = { workspace = true } [target.'cfg(target_arch = "wasm32")'.dependencies] futures-util = { workspace = true, features = ["channel"] } @@ -36,3 +37,4 @@ tokio = { workspace = true, features = ["rt", "time"] } [dev-dependencies] matrix-sdk-test = { path = "../../testing/matrix-sdk-test/", version= "0.6.0"} wasm-bindgen-test = "0.3.33" +tracing-subscriber = "0.3.15" diff --git a/crates/matrix-sdk-common/src/lib.rs b/crates/matrix-sdk-common/src/lib.rs index f7af81d22..5d4109293 100644 --- a/crates/matrix-sdk-common/src/lib.rs +++ b/crates/matrix-sdk-common/src/lib.rs @@ -25,6 +25,7 @@ pub mod deserialized_responses; pub mod executor; pub mod ring_buffer; pub mod timeout; +pub mod tracing_timer; /// Alias for `Send` on non-wasm, empty trait (implemented by everything) on /// wasm. diff --git a/crates/matrix-sdk-common/src/tracing_timer.rs b/crates/matrix-sdk-common/src/tracing_timer.rs new file mode 100644 index 000000000..927985184 --- /dev/null +++ b/crates/matrix-sdk-common/src/tracing_timer.rs @@ -0,0 +1,134 @@ +// Copyright 2023 The Matrix.org Foundation C.I.C. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +use std::time::Instant; + +use tracing::{callsite::DefaultCallsite, Callsite as _}; + +/// A named RAII that will show on Drop how long its covered section took to +/// execute. +pub struct TracingTimer { + id: String, + callsite: &'static DefaultCallsite, + start: Instant, + level: tracing::Level, +} + +#[cfg(not(tarpaulin_include))] +impl std::fmt::Debug for TracingTimer { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.debug_struct("TracingTimer").field("id", &self.id).field("start", &self.start).finish() + } +} + +impl Drop for TracingTimer { + fn drop(&mut self) { + let message = format!("{} finished in {}ms", self.id, self.start.elapsed().as_millis()); + + let enabled = tracing::level_enabled!(self.level) && { + let interest = self.callsite.interest(); + !interest.is_never() + && tracing::__macro_support::__is_enabled(self.callsite.metadata(), interest) + }; + + if !enabled { + return; + } + + let metadata = self.callsite.metadata(); + let fields = metadata.fields(); + let message_field = fields.field("message").unwrap(); + #[allow(trivial_casts)] // The compiler is lying, it can't infer this cast + let values = [(&message_field, Some(&message as &dyn tracing::Value))]; + + // This function is hidden from docs, but we have to use it + // because there is no other way of obtaining a `ValueSet`. + // It's not entirely clear why it is private. See this issue: + // https://github.com/tokio-rs/tracing/issues/2363 + let values = fields.value_set(&values); + + tracing::Event::dispatch(metadata, &values); + } +} + +impl TracingTimer { + /// Create a new `TracingTimer` at the `debug` log level. + pub fn new_debug( + callsite: &'static DefaultCallsite, + id: String, + level: tracing::Level, + ) -> Self { + Self { id, callsite, start: Instant::now(), level } + } +} + +/// Macro to create a RAII timer that will log a `tracing` event once it's +/// dropped. +/// +/// The tracing level can be specified as a first argument, but it's optional. +/// If it's missing, this will use the debug level. +#[macro_export] +macro_rules! timer { + ($level:expr, $string:expr) => {{ + static CALLSITE: tracing::callsite::DefaultCallsite = tracing::callsite2! { + name: tracing::__macro_support::concat!( + "event ", + file!(), + ":", + line!(), + ), + kind: tracing::metadata::Kind::EVENT, + target: module_path!(), + level: $level, + fields: [] + }; + + $crate::tracing_timer::TracingTimer::new_debug(&CALLSITE, $string.into(), $level) + }}; + + ($string:expr) => { + timer!(tracing::Level::DEBUG, $string) + }; +} + +#[cfg(test)] +mod tests { + #[cfg(not(target_arch = "wasm32"))] + #[matrix_sdk_test::async_test] + async fn test_timer_name() { + use tracing::{span, Level}; + + tracing_subscriber::fmt::init(); + + mod time123 { + pub async fn run() { + let _timer_guard = timer!(tracing::Level::DEBUG, "test"); + tokio::time::sleep(instant::Duration::from_millis(123)).await; + // Displays: 2023-08-25T15:18:31.169498Z DEBUG + // matrix_sdk_common::tracing_timer::tests: test finished in + // 124ms + } + } + + time123::run().await; + + let span = span!(Level::DEBUG, "le 256ms span"); + let _guard = span.enter(); + + let _timer_guard = timer!("in span"); + tokio::time::sleep(instant::Duration::from_millis(256)).await; + // Displays: 2023-08-25T15:18:31.427070Z DEBUG le 256ms span: + // matrix_sdk_common::tracing_timer::tests: in span finished in 257ms + } +}