diff --git a/Cargo.lock b/Cargo.lock index 1893f89fe..1d41ad244 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3247,6 +3247,7 @@ dependencies = [ name = "typst-timing" version = "0.13.1" dependencies = [ + "indexmap 2.7.1", "parking_lot", "serde", "serde_json", diff --git a/crates/typst-library/src/foundations/func.rs b/crates/typst-library/src/foundations/func.rs index dd999ddc3..5d923a825 100644 --- a/crates/typst-library/src/foundations/func.rs +++ b/crates/typst-library/src/foundations/func.rs @@ -298,7 +298,12 @@ impl Func { } /// Non-generic implementation of `call`. - #[typst_macros::time(name = "func call", span = self.span())] + #[typst_macros::time( + name = "func call", + span = self.span(), + callsite = args.span, + func = self.name().unwrap_or("anonymous") + )] fn call_impl( &self, engine: &mut Engine, diff --git a/crates/typst-macros/src/lib.rs b/crates/typst-macros/src/lib.rs index 82e63ddc8..40733a950 100644 --- a/crates/typst-macros/src/lib.rs +++ b/crates/typst-macros/src/lib.rs @@ -333,9 +333,18 @@ pub fn derive_cast(item: BoundaryStream) -> BoundaryStream { /// invocations of the function and store them in a global map. The map can be /// accessed through the `typst_trace::RECORDER` static. /// -/// You can also specify the span of the function invocation: -/// - `#[time(span = ..)]` to record the span, which will be used for the -/// `EventKey`. +/// You can also specify the following arguments (in that order): +/// - the name of the event type using `#[time(name = ..)]`, by default uses the +/// function's name. +/// - the span of the function declaration using `#[time(span = ..)]`. +/// - the span of the callsite using `#[time(callsite = ..)]`. +/// - the name of the function being called using `#[time(func = ..)]`. +/// - any extra arguments, which must be at the end of the argument list, they +/// can be of four types: +/// - serialize arguments `#[time( = )]` +/// - debug arguments `#[time( = ?)]` +/// - display arguments `#[time( = #)]` +/// - span arguments `#[time( = $)]` /// /// By default, all tracing is omitted using the `wasm32` target flag. /// This is done to avoid bloating the web app, which doesn't need tracing. diff --git a/crates/typst-macros/src/time.rs b/crates/typst-macros/src/time.rs index 94fa4e5be..3ae4d217d 100644 --- a/crates/typst-macros/src/time.rs +++ b/crates/typst-macros/src/time.rs @@ -1,20 +1,23 @@ use proc_macro2::TokenStream; -use quote::{quote, ToTokens}; +use quote::{format_ident, quote, ToTokens}; use syn::parse::{Parse, ParseStream}; use syn::{parse_quote, Result}; -use crate::util::{kw, parse_key_value, parse_string}; +use crate::util::{eat_comma, kw, parse_key_value, parse_string}; /// Expand the `#[time(..)]` macro. pub fn time(stream: TokenStream, item: syn::ItemFn) -> Result { let meta: Meta = syn::parse2(stream)?; - Ok(create(meta, item)) + create(meta, item) } /// The `..` in `#[time(..)]`. pub struct Meta { - pub span: Option, pub name: Option, + pub span: Option, + pub callsite: Option, + pub func: Option, + pub extras: Vec<(String, Mode, syn::Expr)>, } impl Parse for Meta { @@ -22,23 +25,96 @@ impl Parse for Meta { Ok(Self { name: parse_string::(input)?, span: parse_key_value::(input)?, + callsite: parse_key_value::(input)?, + func: parse_key_value::(input)?, + extras: { + let mut pairs = Vec::new(); + while input.peek(syn::Ident) { + let key: syn::Ident = input.parse()?; + let _: syn::Token![=] = input.parse()?; + + // Get the mode of this extra argument. + let mode = Mode::parse(input)?; + + let value = input.parse()?; + eat_comma(input); + + pairs.push((key.to_string(), mode, value)); + } + pairs + }, }) } } -fn create(meta: Meta, mut item: syn::ItemFn) -> TokenStream { +#[derive(Debug, Clone, Copy, PartialEq, Eq)] + +pub enum Mode { + Span, + Serialize, + Debug, + Display, +} + +impl Parse for Mode { + fn parse(input: ParseStream) -> Result { + if input.peek(syn::Token![$]) { + input.parse::()?; + Ok(Self::Span) + } else if input.peek(syn::Token![?]) { + input.parse::()?; + Ok(Self::Debug) + } else if input.peek(syn::Token![#]) { + input.parse::()?; + Ok(Self::Display) + } else { + Ok(Self::Serialize) + } + } +} + +fn create(meta: Meta, mut item: syn::ItemFn) -> Result { let name = meta.name.unwrap_or_else(|| item.sig.ident.to_string()); - let construct = match meta.span.as_ref() { - Some(span) => quote! { with_span(#name, Some(#span.into_raw())) }, - None => quote! { new(#name) }, - }; + let mut extras = Vec::new(); + if let Some(func) = &meta.func { + extras.push(quote! { .with_func(#func) }); + } + + if let Some(span) = &meta.span { + extras.push(quote! { .with_span(#span.into_raw()) }); + } + + if let Some(callsite) = &meta.callsite { + extras.push(quote! { .with_callsite(#callsite.into_raw()) }); + } + + for (key, mode, value) in &meta.extras { + let (method, transform) = match mode { + Mode::Span => { + (format_ident!("with_named_span"), Some(quote! { .into_raw() })) + } + Mode::Debug => (format_ident!("with_debug"), None), + Mode::Display => (format_ident!("with_display"), None), + Mode::Serialize => (format_ident!("with_arg"), None), + }; + + extras.push(quote! { .#method(#key, (#value) #transform) }); + if matches!(mode, Mode::Serialize) { + let error_msg = format!("failed to serialize {key}"); + extras.push(quote! { .expect(#error_msg) }) + } + } item.block.stmts.insert( 0, parse_quote! { - let __scope = ::typst_timing::TimingScope::#construct; + let __scope = ::typst_timing::TimingScope::new(#name).map(|__scope| { + __scope + #(#extras)* + .build() + }); }, ); - item.into_token_stream() + Ok(item.into_token_stream()) } diff --git a/crates/typst-macros/src/util.rs b/crates/typst-macros/src/util.rs index e8c0910b6..6c611dffc 100644 --- a/crates/typst-macros/src/util.rs +++ b/crates/typst-macros/src/util.rs @@ -254,6 +254,8 @@ impl Parse for BareType { pub mod kw { syn::custom_keyword!(name); syn::custom_keyword!(span); + syn::custom_keyword!(callsite); + syn::custom_keyword!(func); syn::custom_keyword!(title); syn::custom_keyword!(scope); syn::custom_keyword!(contextual); diff --git a/crates/typst-realize/src/lib.rs b/crates/typst-realize/src/lib.rs index 5d9e0a23a..f48d6ab1b 100644 --- a/crates/typst-realize/src/lib.rs +++ b/crates/typst-realize/src/lib.rs @@ -33,7 +33,7 @@ use typst_syntax::Span; use typst_utils::{SliceExt, SmallBitSet}; /// Realize content into a flat list of well-known, styled items. -#[typst_macros::time(name = "realize")] +#[typst_macros::time(name = "realize", span = content.span())] pub fn realize<'a>( kind: RealizationKind, engine: &mut Engine, diff --git a/crates/typst-timing/Cargo.toml b/crates/typst-timing/Cargo.toml index dbc2813c7..dc6035763 100644 --- a/crates/typst-timing/Cargo.toml +++ b/crates/typst-timing/Cargo.toml @@ -13,6 +13,7 @@ keywords = { workspace = true } readme = { workspace = true } [dependencies] +indexmap = { workspace = true } parking_lot = { workspace = true } serde = { workspace = true } serde_json = { workspace = true } diff --git a/crates/typst-timing/src/lib.rs b/crates/typst-timing/src/lib.rs index 6da2cdf02..7adb8c4c1 100644 --- a/crates/typst-timing/src/lib.rs +++ b/crates/typst-timing/src/lib.rs @@ -1,9 +1,14 @@ //! Performance timing for Typst. +use std::borrow::Cow; +use std::fmt::Display; use std::io::Write; use std::num::NonZeroU64; +use std::ops::Not; use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; +use std::sync::Arc; +use indexmap::IndexMap; use parking_lot::Mutex; use serde::ser::SerializeSeq; use serde::{Serialize, Serializer}; @@ -93,20 +98,15 @@ pub fn export_json( mut source: impl FnMut(NonZeroU64) -> (String, u32), ) -> Result<(), String> { #[derive(Serialize)] - struct Entry { + struct Entry<'a> { name: &'static str, cat: &'static str, ph: &'static str, ts: f64, pid: u64, tid: u64, - args: Option, - } - - #[derive(Serialize)] - struct Args { - file: String, - line: u32, + #[serde(skip_serializing_if = "Option::is_none")] + args: Option, Cow<'a, serde_json::Value>>>, } let lock = EVENTS.lock(); @@ -118,6 +118,16 @@ pub fn export_json( .map_err(|e| format!("failed to serialize events: {e}"))?; for event in events.iter() { + let mut args = IndexMap::new(); + if let Some(func) = event.func.as_ref() { + args.insert("func".into(), Cow::Owned(serde_json::json!(func))); + } + + for (key, arg) in event.arguments.iter() { + arg.to_json(&mut source, key, &mut args) + .map_err(|e| format!("failed to serialize event argument: {e}"))?; + } + seq.serialize_element(&Entry { name: event.name, cat: "typst", @@ -128,7 +138,7 @@ pub fn export_json( ts: event.timestamp.micros_since(events[0].timestamp), pid: 1, tid: event.thread_id, - args: event.span.map(&mut source).map(|(file, line)| Args { file, line }), + args: args.is_empty().not().then_some(args), }) .map_err(|e| format!("failed to serialize event: {e}"))?; } @@ -139,61 +149,155 @@ pub fn export_json( } /// A scope that records an event when it is dropped. +#[must_use] pub struct TimingScope { name: &'static str, - span: Option, - thread_id: u64, + func: Option, + args: IndexMap<&'static str, EventArgument>, } impl TimingScope { /// Create a new scope if timing is enabled. #[inline] pub fn new(name: &'static str) -> Option { - Self::with_span(name, None) + if is_enabled() { + Some(Self { name, func: None, args: IndexMap::new() }) + } else { + None + } } - /// Create a new scope with a span if timing is enabled. - /// - /// The span is a raw number because `typst-timing` can't depend on - /// `typst-syntax` (or else `typst-syntax` couldn't depend on - /// `typst-timing`). - #[inline] - pub fn with_span(name: &'static str, span: Option) -> Option { - if is_enabled() { - return Some(Self::new_impl(name, span)); - } - None + pub fn with_func(mut self, func: impl ToString) -> Self { + self.func = Some(func.to_string()); + self + } + + pub fn with_span(mut self, span: NonZeroU64) -> Self { + self.args.insert("span", EventArgument::Span(span)); + self + } + + pub fn with_callsite(mut self, callsite: NonZeroU64) -> Self { + self.args.insert("callsite", EventArgument::Span(callsite)); + self + } + + pub fn with_named_span(mut self, name: &'static str, span: NonZeroU64) -> Self { + self.args.insert(name, EventArgument::Span(span)); + self + } + + pub fn with_display(self, name: &'static str, value: impl Display) -> Self { + self.with_arg(name, value.to_string()) + .expect("failed to serialize display value") + } + + pub fn with_debug(self, name: &'static str, value: impl std::fmt::Debug) -> Self { + self.with_arg(name, format!("{value:?}")) + .expect("failed to serialize debug value") + } + + pub fn with_arg( + mut self, + arg: &'static str, + value: impl Serialize, + ) -> Result { + let value = serde_json::to_value(value)?; + self.args.insert(arg, EventArgument::Value(value)); + Ok(self) } /// Create a new scope without checking if timing is enabled. - fn new_impl(name: &'static str, span: Option) -> Self { + pub fn build(self) -> TimingScopeGuard { let (thread_id, timestamp) = THREAD_DATA.with(|data| (data.id, Timestamp::now_with(data))); - EVENTS.lock().push(Event { + let event = Event { kind: EventKind::Start, timestamp, - name, - span, + name: self.name, + func: self.func.clone(), thread_id, - }); - Self { name, span, thread_id } + arguments: Arc::new(self.args), + }; + EVENTS.lock().push(event.clone()); + TimingScopeGuard { scope: Some(event) } } } -impl Drop for TimingScope { +pub struct TimingScopeGuard { + scope: Option, +} + +impl Drop for TimingScopeGuard { fn drop(&mut self) { let timestamp = Timestamp::now(); - EVENTS.lock().push(Event { - kind: EventKind::End, - timestamp, - name: self.name, - span: self.span, - thread_id: self.thread_id, - }); + + let mut scope = self.scope.take().expect("scope already dropped"); + scope.timestamp = timestamp; + scope.kind = EventKind::End; + + EVENTS.lock().push(scope); + } +} + +enum EventArgument { + Span(NonZeroU64), + Value(serde_json::Value), +} + +impl EventArgument { + fn to_json<'a>( + &'a self, + mut source: impl FnMut(NonZeroU64) -> (String, u32), + key: &'static str, + out: &mut IndexMap, Cow<'a, serde_json::Value>>, + ) -> Result<(), serde_json::Error> { + match self { + EventArgument::Span(span) => { + let (file, line) = source(*span); + // Insert file and line information for the span + if key == "span" { + out.insert("file".into(), Cow::Owned(serde_json::json!(file))); + out.insert("line".into(), Cow::Owned(serde_json::json!(line))); + + return Ok(()); + } + + // Small optimization for callsite + if key == "callsite" { + out.insert( + "callsite_file".into(), + Cow::Owned(serde_json::json!(file)), + ); + out.insert( + "callsite_line".into(), + Cow::Owned(serde_json::json!(line)), + ); + + return Ok(()); + } + + out.insert( + format!("{key}_file").into(), + Cow::Owned(serde_json::json!(file)), + ); + + out.insert( + format!("{key}_line").into(), + Cow::Owned(serde_json::json!(line)), + ); + } + EventArgument::Value(value) => { + out.insert(key.into(), Cow::Borrowed(value)); + } + } + + Ok(()) } } /// An event that has been recorded. +#[derive(Clone)] struct Event { /// Whether this is a start or end event. kind: EventKind, @@ -201,8 +305,10 @@ struct Event { timestamp: Timestamp, /// The name of this event. name: &'static str, - /// The raw value of the span of code that this event was recorded in. - span: Option, + /// The additional arguments of this event. + arguments: Arc>, + /// The function being called (if any). + func: Option, /// The thread ID of this event. thread_id: u64, }