diff --git a/Cargo.lock b/Cargo.lock index dcd154367..a2b9e56bc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3247,6 +3247,7 @@ dependencies = [ name = "typst-timing" version = "0.13.1" dependencies = [ + "ecow", "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..d160cbf87 100644 --- a/crates/typst-macros/src/time.rs +++ b/crates/typst-macros/src/time.rs @@ -1,44 +1,138 @@ +use std::collections::HashSet; + 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<(syn::Ident, Mode, syn::Expr)>, } impl Parse for Meta { fn parse(input: ParseStream) -> Result { - Ok(Self { + let out = 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, mode, value)); + } + pairs + }, + }; + + let mut keys = HashSet::new(); + keys.insert("name".to_string()); + keys.insert("span".to_string()); + keys.insert("callsite".to_string()); + keys.insert("func".to_string()); + + // Check that the keys are unique. + for (key, _, _) in &out.extras { + if !keys.insert(key.to_string()) { + bail!(key, "Duplicate key in #[time(..)]: `{}`", key); + } + } + + Ok(out) } } -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), + }; + + let key = key.to_string(); + 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 f3f071505..1dcd8c162 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..6cb805e7b 100644 --- a/crates/typst-timing/Cargo.toml +++ b/crates/typst-timing/Cargo.toml @@ -13,6 +13,7 @@ keywords = { workspace = true } readme = { workspace = true } [dependencies] +ecow = { 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..9738c303e 100644 --- a/crates/typst-timing/src/lib.rs +++ b/crates/typst-timing/src/lib.rs @@ -1,11 +1,15 @@ //! 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 ecow::EcoVec; use parking_lot::Mutex; -use serde::ser::SerializeSeq; +use serde::ser::{SerializeMap, SerializeSeq}; use serde::{Serialize, Serializer}; /// Creates a timing scope around an expression. @@ -93,20 +97,18 @@ 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", + serialize_with = "serialize_vec_as_map" + )] + args: Option, Cow<'a, serde_json::Value>)>>, } let lock = EVENTS.lock(); @@ -118,6 +120,16 @@ pub fn export_json( .map_err(|e| format!("failed to serialize events: {e}"))?; for event in events.iter() { + let mut args = EcoVec::with_capacity(event.arguments.len() * 2 + 1); + if let Some(func) = event.func.as_ref() { + args.push(("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,72 +140,167 @@ 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}"))?; } - seq.end().map_err(|e| format!("failed to serialize events: {e}"))?; + SerializeSeq::end(seq).map_err(|e| format!("failed to serialize events: {e}"))?; Ok(()) } /// 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: EcoVec<(&'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: EcoVec::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.push(("span", EventArgument::Span(span))); + self + } + + pub fn with_callsite(mut self, callsite: NonZeroU64) -> Self { + self.args.push(("callsite", EventArgument::Span(callsite))); + self + } + + pub fn with_named_span(mut self, name: &'static str, span: NonZeroU64) -> Self { + self.args.push((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.push((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: self.args.clone(), + }; + 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); + } +} + +#[derive(Clone)] +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 EcoVec<(Cow<'static, str>, 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.push(("file".into(), Cow::Owned(serde_json::json!(file)))); + out.push(("line".into(), Cow::Owned(serde_json::json!(line)))); + + return Ok(()); + } + + // Small optimization for callsite + if key == "callsite" { + out.push(( + "callsite_file".into(), + Cow::Owned(serde_json::json!(file)), + )); + out.push(( + "callsite_line".into(), + Cow::Owned(serde_json::json!(line)), + )); + + return Ok(()); + } + + out.push(( + format!("{key}_file").into(), + Cow::Owned(serde_json::json!(file)), + )); + + out.push(( + format!("{key}_line").into(), + Cow::Owned(serde_json::json!(line)), + )); + } + EventArgument::Value(value) => { + out.push((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 +308,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: EcoVec<(&'static str, EventArgument)>, + /// The function being called (if any). + func: Option, /// The thread ID of this event. thread_id: u64, } @@ -307,3 +416,24 @@ impl WasmTimer { self.time_origin + self.perf.now() } } + +// Custom serialization function for handling `EcoVec` as a map in JSON. +fn serialize_vec_as_map( + data: &Option, Cow)>>, + serializer: S, +) -> Result +where + S: Serializer, +{ + let Some(data) = data.as_deref() else { + // Should not happen, but if it does, we turn it into a `null` value. + return serializer.serialize_none(); + }; + + let mut map = serializer.serialize_map(Some(data.len()))?; + for (key, value) in data { + map.serialize_entry(key, value)?; + } + + map.end() +}