Merge 490327597bfe8388c4844153fcafe6e6b66bb806 into b1c79b50d4253e7acb839a93450311c1fca12ac8

This commit is contained in:
Sébastien d'Herbais de Thun 2025-07-18 21:33:57 +08:00 committed by GitHub
commit f8feacb256
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
8 changed files with 301 additions and 59 deletions

1
Cargo.lock generated
View File

@ -3247,6 +3247,7 @@ dependencies = [
name = "typst-timing"
version = "0.13.1"
dependencies = [
"ecow",
"parking_lot",
"serde",
"serde_json",

View File

@ -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,

View File

@ -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(<name> = <value>)]`
/// - debug arguments `#[time(<name> = ?<value>)]`
/// - display arguments `#[time(<name> = #<value>)]`
/// - span arguments `#[time(<name> = $<value>)]`
///
/// 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.

View File

@ -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<TokenStream> {
let meta: Meta = syn::parse2(stream)?;
Ok(create(meta, item))
create(meta, item)
}
/// The `..` in `#[time(..)]`.
pub struct Meta {
pub span: Option<syn::Expr>,
pub name: Option<String>,
pub span: Option<syn::Expr>,
pub callsite: Option<syn::Expr>,
pub func: Option<syn::Expr>,
pub extras: Vec<(syn::Ident, Mode, syn::Expr)>,
}
impl Parse for Meta {
fn parse(input: ParseStream) -> Result<Self> {
Ok(Self {
let out = Self {
name: parse_string::<kw::name>(input)?,
span: parse_key_value::<kw::span, syn::Expr>(input)?,
})
callsite: parse_key_value::<kw::callsite, syn::Expr>(input)?,
func: parse_key_value::<kw::func, syn::Expr>(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);
}
}
fn create(meta: Meta, mut item: syn::ItemFn) -> TokenStream {
Ok(out)
}
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub enum Mode {
Span,
Serialize,
Debug,
Display,
}
impl Parse for Mode {
fn parse(input: ParseStream) -> Result<Self> {
if input.peek(syn::Token![$]) {
input.parse::<syn::Token![$]>()?;
Ok(Self::Span)
} else if input.peek(syn::Token![?]) {
input.parse::<syn::Token![?]>()?;
Ok(Self::Debug)
} else if input.peek(syn::Token![#]) {
input.parse::<syn::Token![#]>()?;
Ok(Self::Display)
} else {
Ok(Self::Serialize)
}
}
}
fn create(meta: Meta, mut item: syn::ItemFn) -> Result<TokenStream> {
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())
}

View File

@ -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);

View File

@ -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,

View File

@ -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 }

View File

@ -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<W: Write>(
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>,
}
#[derive(Serialize)]
struct Args {
file: String,
line: u32,
#[serde(
skip_serializing_if = "Option::is_none",
serialize_with = "serialize_vec_as_map"
)]
args: Option<EcoVec<(Cow<'a, str>, Cow<'a, serde_json::Value>)>>,
}
let lock = EVENTS.lock();
@ -118,6 +120,16 @@ pub fn export_json<W: Write>(
.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<W: Write>(
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<NonZeroU64>,
thread_id: u64,
func: Option<String>,
args: EcoVec<(&'static str, EventArgument)>,
}
impl TimingScope {
/// Create a new scope if timing is enabled.
#[inline]
pub fn new(name: &'static str) -> Option<Self> {
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<NonZeroU64>) -> Option<Self> {
if is_enabled() {
return Some(Self::new_impl(name, span));
pub fn with_func(mut self, func: impl ToString) -> Self {
self.func = Some(func.to_string());
self
}
None
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<Self, serde_json::Error> {
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<NonZeroU64>) -> 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<Event>,
}
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<NonZeroU64>,
/// The additional arguments of this event.
arguments: EcoVec<(&'static str, EventArgument)>,
/// The function being called (if any).
func: Option<String>,
/// 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<S>(
data: &Option<EcoVec<(Cow<str>, Cow<serde_json::Value>)>>,
serializer: S,
) -> Result<S::Ok, S::Error>
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()
}