From c97ce11dbb4591748e04328c5b75083f9fb0a82b Mon Sep 17 00:00:00 2001 From: Dherse Date: Fri, 28 Mar 2025 10:43:16 +0100 Subject: [PATCH 1/6] Added callsite to func calls --- crates/typst-library/src/foundations/func.rs | 2 +- crates/typst-macros/src/time.rs | 22 +++++++--- crates/typst-macros/src/util.rs | 1 + crates/typst-timing/src/lib.rs | 43 ++++++++++++++++++-- 4 files changed, 57 insertions(+), 11 deletions(-) diff --git a/crates/typst-library/src/foundations/func.rs b/crates/typst-library/src/foundations/func.rs index 27eb34eac..c4a3be030 100644 --- a/crates/typst-library/src/foundations/func.rs +++ b/crates/typst-library/src/foundations/func.rs @@ -298,7 +298,7 @@ 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)] fn call_impl( &self, engine: &mut Engine, diff --git a/crates/typst-macros/src/time.rs b/crates/typst-macros/src/time.rs index 94fa4e5be..3253cb7ee 100644 --- a/crates/typst-macros/src/time.rs +++ b/crates/typst-macros/src/time.rs @@ -8,12 +8,13 @@ use crate::util::{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 callsite: Option, pub name: Option, } @@ -22,15 +23,24 @@ impl Parse for Meta { Ok(Self { name: parse_string::(input)?, span: parse_key_value::(input)?, + callsite: parse_key_value::(input)?, }) } } -fn create(meta: Meta, mut item: syn::ItemFn) -> TokenStream { +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 construct = match (meta.span.as_ref(), meta.callsite.as_ref()) { + (Some(span), Some(callsite)) => quote! { + with_callsite(#name, Some(#span.into_raw()), Some(#callsite.into_raw())) + }, + (Some(span), None) => quote! { + with_span(#name, Some(#span.into_raw())) + }, + (None, Some(expr)) => { + bail!(expr, "cannot have a callsite span without a main span") + } + (None, None) => quote! { new(#name) }, }; item.block.stmts.insert( @@ -40,5 +50,5 @@ fn create(meta: Meta, mut item: syn::ItemFn) -> TokenStream { }, ); - 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..39ef83ef3 100644 --- a/crates/typst-macros/src/util.rs +++ b/crates/typst-macros/src/util.rs @@ -254,6 +254,7 @@ impl Parse for BareType { pub mod kw { syn::custom_keyword!(name); syn::custom_keyword!(span); + syn::custom_keyword!(callsite); syn::custom_keyword!(title); syn::custom_keyword!(scope); syn::custom_keyword!(contextual); diff --git a/crates/typst-timing/src/lib.rs b/crates/typst-timing/src/lib.rs index 6da2cdf02..355acde55 100644 --- a/crates/typst-timing/src/lib.rs +++ b/crates/typst-timing/src/lib.rs @@ -107,6 +107,10 @@ pub fn export_json( struct Args { file: String, line: u32, + #[serde(skip_serializing_if = "Option::is_none")] + callsite_file: Option, + #[serde(skip_serializing_if = "Option::is_none")] + callsite_line: Option, } let lock = EVENTS.lock(); @@ -128,7 +132,15 @@ 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: event.span.map(&mut source).map(|(file, line)| { + let (callsite_file, callsite_line) = match event.callsite.map(&mut source) + { + Some((a, b)) => (Some(a), Some(b)), + None => (None, None), + }; + + Args { file, line, callsite_file, callsite_line } + }), }) .map_err(|e| format!("failed to serialize event: {e}"))?; } @@ -142,6 +154,7 @@ pub fn export_json( pub struct TimingScope { name: &'static str, span: Option, + callsite: Option, thread_id: u64, } @@ -159,14 +172,32 @@ impl TimingScope { /// `typst-timing`). #[inline] pub fn with_span(name: &'static str, span: Option) -> Option { + Self::with_callsite(name, span, 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_callsite( + name: &'static str, + span: Option, + callsite: Option, + ) -> Option { if is_enabled() { - return Some(Self::new_impl(name, span)); + return Some(Self::new_impl(name, span, callsite)); } None } /// Create a new scope without checking if timing is enabled. - fn new_impl(name: &'static str, span: Option) -> Self { + fn new_impl( + name: &'static str, + span: Option, + callsite: Option, + ) -> Self { let (thread_id, timestamp) = THREAD_DATA.with(|data| (data.id, Timestamp::now_with(data))); EVENTS.lock().push(Event { @@ -174,9 +205,10 @@ impl TimingScope { timestamp, name, span, + callsite, thread_id, }); - Self { name, span, thread_id } + Self { name, span, callsite: None, thread_id } } } @@ -188,6 +220,7 @@ impl Drop for TimingScope { timestamp, name: self.name, span: self.span, + callsite: self.callsite, thread_id: self.thread_id, }); } @@ -203,6 +236,8 @@ struct Event { name: &'static str, /// The raw value of the span of code that this event was recorded in. span: Option, + /// The raw value of the callsite span of the code that this event was recorded in. + callsite: Option, /// The thread ID of this event. thread_id: u64, } From d735e2ff7063e59c81c1be614f13a67eac2f1864 Mon Sep 17 00:00:00 2001 From: Dherse Date: Sun, 30 Mar 2025 12:54:15 +0200 Subject: [PATCH 2/6] Added function name in timing `func call` & more span --- crates/typst-library/src/foundations/func.rs | 7 ++++- crates/typst-macros/src/time.rs | 16 ++++++++++- crates/typst-macros/src/util.rs | 1 + crates/typst-realize/src/lib.rs | 2 +- crates/typst-timing/src/lib.rs | 29 +++++++++++++++----- 5 files changed, 45 insertions(+), 10 deletions(-) diff --git a/crates/typst-library/src/foundations/func.rs b/crates/typst-library/src/foundations/func.rs index c4a3be030..ca937f104 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(), callsite = args.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/time.rs b/crates/typst-macros/src/time.rs index 3253cb7ee..8bb24ccc5 100644 --- a/crates/typst-macros/src/time.rs +++ b/crates/typst-macros/src/time.rs @@ -16,6 +16,7 @@ pub struct Meta { pub span: Option, pub callsite: Option, pub name: Option, + pub func: Option, } impl Parse for Meta { @@ -24,15 +25,28 @@ impl Parse for Meta { name: parse_string::(input)?, span: parse_key_value::(input)?, callsite: parse_key_value::(input)?, + func: parse_key_value::(input)?, }) } } fn create(meta: Meta, mut item: syn::ItemFn) -> Result { let name = meta.name.unwrap_or_else(|| item.sig.ident.to_string()); + + let func = match meta.func { + Some(func) => { + if meta.callsite.is_none() { + bail!(func, "the `func` argument can only be used with a callsite") + } + + quote! { Some(#func.into()) } + } + None => quote! { None }, + }; + let construct = match (meta.span.as_ref(), meta.callsite.as_ref()) { (Some(span), Some(callsite)) => quote! { - with_callsite(#name, Some(#span.into_raw()), Some(#callsite.into_raw())) + with_callsite(#name, Some(#span.into_raw()), Some(#callsite.into_raw()), #func) }, (Some(span), None) => quote! { with_span(#name, Some(#span.into_raw())) diff --git a/crates/typst-macros/src/util.rs b/crates/typst-macros/src/util.rs index 39ef83ef3..6c611dffc 100644 --- a/crates/typst-macros/src/util.rs +++ b/crates/typst-macros/src/util.rs @@ -255,6 +255,7 @@ 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 151ae76ba..21c4e5c2f 100644 --- a/crates/typst-realize/src/lib.rs +++ b/crates/typst-realize/src/lib.rs @@ -34,7 +34,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/src/lib.rs b/crates/typst-timing/src/lib.rs index 355acde55..0c307696d 100644 --- a/crates/typst-timing/src/lib.rs +++ b/crates/typst-timing/src/lib.rs @@ -93,21 +93,23 @@ 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, + args: Option>, } #[derive(Serialize)] - struct Args { + struct Args<'a> { file: String, line: u32, #[serde(skip_serializing_if = "Option::is_none")] + function_name: Option<&'a str>, + #[serde(skip_serializing_if = "Option::is_none")] callsite_file: Option, #[serde(skip_serializing_if = "Option::is_none")] callsite_line: Option, @@ -139,7 +141,13 @@ pub fn export_json( None => (None, None), }; - Args { file, line, callsite_file, callsite_line } + Args { + file, + line, + callsite_file, + callsite_line, + function_name: event.func.as_deref(), + } }), }) .map_err(|e| format!("failed to serialize event: {e}"))?; @@ -155,6 +163,7 @@ pub struct TimingScope { name: &'static str, span: Option, callsite: Option, + func: Option, thread_id: u64, } @@ -172,7 +181,7 @@ impl TimingScope { /// `typst-timing`). #[inline] pub fn with_span(name: &'static str, span: Option) -> Option { - Self::with_callsite(name, span, None) + Self::with_callsite(name, span, None, None) } /// Create a new scope with a span if timing is enabled. @@ -185,9 +194,10 @@ impl TimingScope { name: &'static str, span: Option, callsite: Option, + func: Option, ) -> Option { if is_enabled() { - return Some(Self::new_impl(name, span, callsite)); + return Some(Self::new_impl(name, span, callsite, func)); } None } @@ -197,6 +207,7 @@ impl TimingScope { name: &'static str, span: Option, callsite: Option, + func: Option, ) -> Self { let (thread_id, timestamp) = THREAD_DATA.with(|data| (data.id, Timestamp::now_with(data))); @@ -206,9 +217,10 @@ impl TimingScope { name, span, callsite, + func: func.clone(), thread_id, }); - Self { name, span, callsite: None, thread_id } + Self { name, span, callsite: None, thread_id, func } } } @@ -222,6 +234,7 @@ impl Drop for TimingScope { span: self.span, callsite: self.callsite, thread_id: self.thread_id, + func: std::mem::take(&mut self.func), }); } } @@ -238,6 +251,8 @@ struct Event { span: Option, /// The raw value of the callsite span of the code that this event was recorded in. callsite: Option, + /// The function being called (if any). + func: Option, /// The thread ID of this event. thread_id: u64, } From b463dc9f6dbeb3ddb16234a6d1033c24eb93c463 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?S=C3=A9bastien=20d=27Herbais=20de=20Thun=20=28Dherse=29?= Date: Sun, 13 Jul 2025 17:14:45 +0200 Subject: [PATCH 3/6] Arbitrary arguments for `typst_macros::time` --- Cargo.lock | 1 + crates/typst-macros/src/lib.rs | 15 ++- crates/typst-macros/src/time.rs | 100 ++++++++++---- crates/typst-timing/Cargo.toml | 1 + crates/typst-timing/src/lib.rs | 224 ++++++++++++++++++++------------ 5 files changed, 230 insertions(+), 111 deletions(-) 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-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 8bb24ccc5..3ae4d217d 100644 --- a/crates/typst-macros/src/time.rs +++ b/crates/typst-macros/src/time.rs @@ -1,9 +1,9 @@ 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 { @@ -13,10 +13,11 @@ pub fn time(stream: TokenStream, item: syn::ItemFn) -> Result { /// The `..` in `#[time(..)]`. pub struct Meta { + pub name: Option, pub span: Option, pub callsite: Option, - pub name: Option, pub func: Option, + pub extras: Vec<(String, Mode, syn::Expr)>, } impl Parse for Meta { @@ -26,41 +27,92 @@ impl Parse for Meta { 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 + }, }) } } +#[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 mut extras = Vec::new(); + if let Some(func) = &meta.func { + extras.push(quote! { .with_func(#func) }); + } - let func = match meta.func { - Some(func) => { - if meta.callsite.is_none() { - bail!(func, "the `func` argument can only be used with a callsite") + 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), + }; - quote! { Some(#func.into()) } + 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) }) } - None => quote! { None }, - }; - - let construct = match (meta.span.as_ref(), meta.callsite.as_ref()) { - (Some(span), Some(callsite)) => quote! { - with_callsite(#name, Some(#span.into_raw()), Some(#callsite.into_raw()), #func) - }, - (Some(span), None) => quote! { - with_span(#name, Some(#span.into_raw())) - }, - (None, Some(expr)) => { - bail!(expr, "cannot have a callsite span without a main span") - } - (None, None) => quote! { new(#name) }, - }; + } 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() + }); }, ); 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 0c307696d..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}; @@ -100,19 +105,8 @@ pub fn export_json( ts: f64, pid: u64, tid: u64, - args: Option>, - } - - #[derive(Serialize)] - struct Args<'a> { - file: String, - line: u32, #[serde(skip_serializing_if = "Option::is_none")] - function_name: Option<&'a str>, - #[serde(skip_serializing_if = "Option::is_none")] - callsite_file: Option, - #[serde(skip_serializing_if = "Option::is_none")] - callsite_line: Option, + args: Option, Cow<'a, serde_json::Value>>>, } let lock = EVENTS.lock(); @@ -124,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", @@ -134,21 +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)| { - let (callsite_file, callsite_line) = match event.callsite.map(&mut source) - { - Some((a, b)) => (Some(a), Some(b)), - None => (None, None), - }; - - Args { - file, - line, - callsite_file, - callsite_line, - function_name: event.func.as_deref(), - } - }), + args: args.is_empty().not().then_some(args), }) .map_err(|e| format!("failed to serialize event: {e}"))?; } @@ -159,87 +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, - callsite: Option, func: Option, - thread_id: u64, + 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) - } - - /// 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 { - Self::with_callsite(name, span, None, 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_callsite( - name: &'static str, - span: Option, - callsite: Option, - func: Option, - ) -> Option { if is_enabled() { - return Some(Self::new_impl(name, span, callsite, func)); + Some(Self { name, func: None, args: IndexMap::new() }) + } else { + None } - 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, - callsite: Option, - func: 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, - callsite, - func: func.clone(), + name: self.name, + func: self.func.clone(), thread_id, - }); - Self { name, span, callsite: None, thread_id, func } + 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, - callsite: self.callsite, - thread_id: self.thread_id, - func: std::mem::take(&mut self.func), - }); + + 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, @@ -247,10 +305,8 @@ 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 raw value of the callsite span of the code that this event was recorded in. - callsite: Option, + /// The additional arguments of this event. + arguments: Arc>, /// The function being called (if any). func: Option, /// The thread ID of this event. From 0fb01fccc3fd9ecbfab3e4febd8668eb0e06bf14 Mon Sep 17 00:00:00 2001 From: Dherse Date: Mon, 14 Jul 2025 14:26:32 +0200 Subject: [PATCH 4/6] Replaced `IndexMap` with `EcoVec<(K, V)>` --- Cargo.lock | 2 +- crates/typst-timing/Cargo.toml | 2 +- crates/typst-timing/src/lib.rs | 50 +++++++++++++++++----------------- 3 files changed, 27 insertions(+), 27 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 1d41ad244..2e07d04f2 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3247,7 +3247,7 @@ dependencies = [ name = "typst-timing" version = "0.13.1" dependencies = [ - "indexmap 2.7.1", + "ecow", "parking_lot", "serde", "serde_json", diff --git a/crates/typst-timing/Cargo.toml b/crates/typst-timing/Cargo.toml index dc6035763..6cb805e7b 100644 --- a/crates/typst-timing/Cargo.toml +++ b/crates/typst-timing/Cargo.toml @@ -13,7 +13,7 @@ keywords = { workspace = true } readme = { workspace = true } [dependencies] -indexmap = { workspace = true } +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 7adb8c4c1..9f875b558 100644 --- a/crates/typst-timing/src/lib.rs +++ b/crates/typst-timing/src/lib.rs @@ -6,9 +6,8 @@ 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 ecow::EcoVec; use parking_lot::Mutex; use serde::ser::SerializeSeq; use serde::{Serialize, Serializer}; @@ -106,7 +105,7 @@ pub fn export_json( pid: u64, tid: u64, #[serde(skip_serializing_if = "Option::is_none")] - args: Option, Cow<'a, serde_json::Value>>>, + args: Option, Cow<'a, serde_json::Value>)>>, } let lock = EVENTS.lock(); @@ -118,9 +117,9 @@ pub fn export_json( .map_err(|e| format!("failed to serialize events: {e}"))?; for event in events.iter() { - let mut args = IndexMap::new(); + let mut args = EcoVec::with_capacity(event.arguments.len() * 2 + 1); if let Some(func) = event.func.as_ref() { - args.insert("func".into(), Cow::Owned(serde_json::json!(func))); + args.push(("func".into(), Cow::Owned(serde_json::json!(func)))); } for (key, arg) in event.arguments.iter() { @@ -153,7 +152,7 @@ pub fn export_json( pub struct TimingScope { name: &'static str, func: Option, - args: IndexMap<&'static str, EventArgument>, + args: EcoVec<(&'static str, EventArgument)>, } impl TimingScope { @@ -161,7 +160,7 @@ impl TimingScope { #[inline] pub fn new(name: &'static str) -> Option { if is_enabled() { - Some(Self { name, func: None, args: IndexMap::new() }) + Some(Self { name, func: None, args: EcoVec::new() }) } else { None } @@ -173,17 +172,17 @@ impl TimingScope { } pub fn with_span(mut self, span: NonZeroU64) -> Self { - self.args.insert("span", EventArgument::Span(span)); + self.args.push(("span", EventArgument::Span(span))); self } pub fn with_callsite(mut self, callsite: NonZeroU64) -> Self { - self.args.insert("callsite", EventArgument::Span(callsite)); + self.args.push(("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.args.push((name, EventArgument::Span(span))); self } @@ -203,7 +202,7 @@ impl TimingScope { value: impl Serialize, ) -> Result { let value = serde_json::to_value(value)?; - self.args.insert(arg, EventArgument::Value(value)); + self.args.push((arg, EventArgument::Value(value))); Ok(self) } @@ -217,7 +216,7 @@ impl TimingScope { name: self.name, func: self.func.clone(), thread_id, - arguments: Arc::new(self.args), + arguments: self.args.clone(), }; EVENTS.lock().push(event.clone()); TimingScopeGuard { scope: Some(event) } @@ -240,6 +239,7 @@ impl Drop for TimingScopeGuard { } } +#[derive(Clone)] enum EventArgument { Span(NonZeroU64), Value(serde_json::Value), @@ -250,45 +250,45 @@ impl EventArgument { &'a self, mut source: impl FnMut(NonZeroU64) -> (String, u32), key: &'static str, - out: &mut IndexMap, Cow<'a, serde_json::Value>>, + 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.insert("file".into(), Cow::Owned(serde_json::json!(file))); - out.insert("line".into(), Cow::Owned(serde_json::json!(line))); + 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.insert( + out.push(( "callsite_file".into(), Cow::Owned(serde_json::json!(file)), - ); - out.insert( + )); + out.push(( "callsite_line".into(), Cow::Owned(serde_json::json!(line)), - ); + )); return Ok(()); } - out.insert( + out.push(( format!("{key}_file").into(), Cow::Owned(serde_json::json!(file)), - ); + )); - out.insert( + out.push(( format!("{key}_line").into(), Cow::Owned(serde_json::json!(line)), - ); + )); } EventArgument::Value(value) => { - out.insert(key.into(), Cow::Borrowed(value)); + out.push((key.into(), Cow::Borrowed(value))); } } @@ -306,7 +306,7 @@ struct Event { /// The name of this event. name: &'static str, /// The additional arguments of this event. - arguments: Arc>, + arguments: EcoVec<(&'static str, EventArgument)>, /// The function being called (if any). func: Option, /// The thread ID of this event. From 02495899ec4f361452daf56ffc3b1923911c9e35 Mon Sep 17 00:00:00 2001 From: Dherse Date: Mon, 14 Jul 2025 14:55:15 +0200 Subject: [PATCH 5/6] Added deduplication of keys in macro --- crates/typst-macros/src/time.rs | 26 ++++++++++++++++++++++---- 1 file changed, 22 insertions(+), 4 deletions(-) diff --git a/crates/typst-macros/src/time.rs b/crates/typst-macros/src/time.rs index 3ae4d217d..d160cbf87 100644 --- a/crates/typst-macros/src/time.rs +++ b/crates/typst-macros/src/time.rs @@ -1,3 +1,5 @@ +use std::collections::HashSet; + use proc_macro2::TokenStream; use quote::{format_ident, quote, ToTokens}; use syn::parse::{Parse, ParseStream}; @@ -17,12 +19,12 @@ pub struct Meta { pub span: Option, pub callsite: Option, pub func: Option, - pub extras: Vec<(String, Mode, syn::Expr)>, + 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)?, @@ -39,11 +41,26 @@ impl Parse for Meta { let value = input.parse()?; eat_comma(input); - pairs.push((key.to_string(), mode, value)); + 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) } } @@ -98,6 +115,7 @@ fn create(meta: Meta, mut item: syn::ItemFn) -> Result { 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}"); From 490327597bfe8388c4844153fcafe6e6b66bb806 Mon Sep 17 00:00:00 2001 From: Dherse Date: Mon, 14 Jul 2025 15:05:35 +0200 Subject: [PATCH 6/6] Fixed export to JSON --- crates/typst-timing/src/lib.rs | 30 +++++++++++++++++++++++++++--- 1 file changed, 27 insertions(+), 3 deletions(-) diff --git a/crates/typst-timing/src/lib.rs b/crates/typst-timing/src/lib.rs index 9f875b558..9738c303e 100644 --- a/crates/typst-timing/src/lib.rs +++ b/crates/typst-timing/src/lib.rs @@ -9,7 +9,7 @@ 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. @@ -104,7 +104,10 @@ pub fn export_json( ts: f64, pid: u64, tid: u64, - #[serde(skip_serializing_if = "Option::is_none")] + #[serde( + skip_serializing_if = "Option::is_none", + serialize_with = "serialize_vec_as_map" + )] args: Option, Cow<'a, serde_json::Value>)>>, } @@ -142,7 +145,7 @@ pub fn export_json( .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(()) } @@ -413,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() +}