From c97ce11dbb4591748e04328c5b75083f9fb0a82b Mon Sep 17 00:00:00 2001 From: Dherse Date: Fri, 28 Mar 2025 10:43:16 +0100 Subject: [PATCH 1/2] 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/2] 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, }