diff --git a/Cargo.lock b/Cargo.lock index b2f458207..a978ea807 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -8,19 +8,6 @@ version = "1.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f26201604c87b1e01bd3d98f8d5d9a8fcbb815e8cedb41ffccbeb4bf593a35fe" -[[package]] -name = "ahash" -version = "0.8.6" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "91429305e9f0a25f6205c5b8e0d2db09e0708a7a6df0f42212bb56c32c8ac97a" -dependencies = [ - "cfg-if", - "getrandom", - "once_cell", - "version_check", - "zerocopy", -] - [[package]] name = "aho-corasick" version = "1.1.2" @@ -498,19 +485,6 @@ dependencies = [ "memchr", ] -[[package]] -name = "dashmap" -version = "5.5.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "978747c1d849a7d2ee5e8adc0159961c48fb7e5db2f06af6723b80123bb53856" -dependencies = [ - "cfg-if", - "hashbrown 0.14.3", - "lock_api", - "once_cell", - "parking_lot_core", -] - [[package]] name = "data-url" version = "0.3.1" @@ -596,15 +570,6 @@ dependencies = [ "syn", ] -[[package]] -name = "env_logger" -version = "0.10.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "95b3f3e67048839cb0d0781f445682a35113da7121f7c949db0e2be96a4fbece" -dependencies = [ - "log", -] - [[package]] name = "env_proxy" version = "0.4.1" @@ -827,12 +792,6 @@ version = "0.4.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "95505c38b4572b2d910cecb0281560f54b440a19336cbbcb27bf6ce6adc6f5a8" -[[package]] -name = "hermit-abi" -version = "0.3.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d77f7ec81a6d05a3abb01ab6eb7590f6083d08449fe5a1c8b1e620283546ccb7" - [[package]] name = "hypher" version = "0.1.4" @@ -1103,29 +1062,6 @@ version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8e04e2fd2b8188ea827b32ef11de88377086d690286ab35747ef7f9bf3ccb590" -[[package]] -name = "inferno" -version = "0.11.19" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "321f0f839cd44a4686e9504b0a62b4d69a50b62072144c71c68f5873c167b8d9" -dependencies = [ - "ahash", - "clap", - "crossbeam-channel", - "crossbeam-utils", - "dashmap", - "env_logger", - "indexmap 2.1.0", - "is-terminal", - "itoa", - "log", - "num-format", - "once_cell", - "quick-xml 0.26.0", - "rgb", - "str_stack", -] - [[package]] name = "inotify" version = "0.9.6" @@ -1164,17 +1100,6 @@ dependencies = [ "once_cell", ] -[[package]] -name = "is-terminal" -version = "0.4.9" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "cb0889898416213fab133e1d33a0e5858a48177452750691bde3666d0fdbaf8b" -dependencies = [ - "hermit-abi", - "rustix", - "windows-sys 0.48.0", -] - [[package]] name = "is-wsl" version = "0.4.0" @@ -1244,12 +1169,6 @@ dependencies = [ "arrayvec", ] -[[package]] -name = "lazy_static" -version = "1.4.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "e2abad23fbc42b3700f2f279844dc832adb2b2eb069b2df918f455c4e18cc646" - [[package]] name = "libc" version = "0.2.151" @@ -1434,16 +1353,6 @@ dependencies = [ "windows-sys 0.48.0", ] -[[package]] -name = "nu-ansi-term" -version = "0.46.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" -dependencies = [ - "overload", - "winapi", -] - [[package]] name = "num-bigint" version = "0.4.4" @@ -1455,16 +1364,6 @@ dependencies = [ "num-traits", ] -[[package]] -name = "num-format" -version = "0.4.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a652d9771a63711fd3c3deb670acfbe5c30a4072e664d7a3bf5a9e1056ac72c3" -dependencies = [ - "arrayvec", - "itoa", -] - [[package]] name = "num-integer" version = "0.1.45" @@ -1524,12 +1423,6 @@ version = "0.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "04744f49eae99ab78e0d5c0b603ab218f515ea8cfe5a456d7629ad883a3b6e7d" -[[package]] -name = "overload" -version = "0.1.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" - [[package]] name = "oxipng" version = "9.0.0" @@ -1669,12 +1562,6 @@ version = "0.5.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "5be167a7af36ee22fe3115051bc51f6e6c7054c9348e28deb4f49bd6f705a315" -[[package]] -name = "pin-project-lite" -version = "0.2.13" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8afb450f006bf6385ca15ef45d71d2288452bc3683ce2e2cacc0d18e4be60b58" - [[package]] name = "pixglyph" version = "0.3.0" @@ -1764,15 +1651,6 @@ dependencies = [ "unicase", ] -[[package]] -name = "quick-xml" -version = "0.26.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7f50b1c63b38611e7d4d7f68b82d3ad0cc71a2ad2e7f61fc10f1328d917c93cd" -dependencies = [ - "memchr", -] - [[package]] name = "quick-xml" version = "0.28.2" @@ -2179,15 +2057,6 @@ dependencies = [ "unsafe-libyaml", ] -[[package]] -name = "sharded-slab" -version = "0.1.7" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" -dependencies = [ - "lazy_static", -] - [[package]] name = "simd-adler32" version = "0.3.7" @@ -2255,12 +2124,6 @@ dependencies = [ "winapi", ] -[[package]] -name = "str_stack" -version = "0.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9091b6114800a5f2141aee1d1b9d6ca3592ac062dc5decb3764ec5895a47b4eb" - [[package]] name = "strict-num" version = "0.1.1" @@ -2429,16 +2292,6 @@ dependencies = [ "syn", ] -[[package]] -name = "thread_local" -version = "1.1.7" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3fdd6f064ccff2d6567adcb3873ca630700f00b5ad3f060c25b5dcfd9a4ce152" -dependencies = [ - "cfg-if", - "once_cell", -] - [[package]] name = "time" version = "0.3.20" @@ -2552,84 +2405,6 @@ dependencies = [ "winnow", ] -[[package]] -name = "tracing" -version = "0.1.40" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef" -dependencies = [ - "pin-project-lite", - "tracing-attributes", - "tracing-core", -] - -[[package]] -name = "tracing-attributes" -version = "0.1.27" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7" -dependencies = [ - "proc-macro2", - "quote", - "syn", -] - -[[package]] -name = "tracing-core" -version = "0.1.32" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54" -dependencies = [ - "once_cell", - "valuable", -] - -[[package]] -name = "tracing-error" -version = "0.2.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d686ec1c0f384b1277f097b2f279a2ecc11afe8c133c1aabf036a27cb4cd206e" -dependencies = [ - "tracing", - "tracing-subscriber", -] - -[[package]] -name = "tracing-flame" -version = "0.2.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0bae117ee14789185e129aaee5d93750abe67fdc5a9a62650452bfe4e122a3a9" -dependencies = [ - "lazy_static", - "tracing", - "tracing-subscriber", -] - -[[package]] -name = "tracing-log" -version = "0.2.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" -dependencies = [ - "log", - "once_cell", - "tracing-core", -] - -[[package]] -name = "tracing-subscriber" -version = "0.3.18" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b" -dependencies = [ - "nu-ansi-term", - "sharded-slab", - "smallvec", - "thread_local", - "tracing-core", - "tracing-log", -] - [[package]] name = "ttf-parser" version = "0.20.0" @@ -2692,12 +2467,12 @@ dependencies = [ "syntect", "time", "toml", - "tracing", "ttf-parser", "two-face", "typed-arena", "typst-macros", "typst-syntax", + "typst-timing", "unicode-bidi", "unicode-math-class", "unicode-script", @@ -2721,7 +2496,6 @@ dependencies = [ "env_proxy", "flate2", "fontdb", - "inferno", "notify", "once_cell", "open", @@ -2739,14 +2513,12 @@ dependencies = [ "siphasher 1.0.0", "tar", "tempfile", - "tracing", - "tracing-error", - "tracing-flame", - "tracing-subscriber", "typst", + "typst-macros", "typst-pdf", "typst-render", "typst-svg", + "typst-timing", "ureq", "xz2", "zip", @@ -2820,9 +2592,10 @@ dependencies = [ "pdf-writer", "subsetter", "svg2pdf", - "tracing", "ttf-parser", "typst", + "typst-macros", + "typst-timing", "unicode-properties", "unscanny", "xmp-writer", @@ -2842,6 +2615,8 @@ dependencies = [ "tiny-skia", "ttf-parser", "typst", + "typst-macros", + "typst-timing", "usvg", ] @@ -2853,9 +2628,10 @@ dependencies = [ "comemo", "ecow", "flate2", - "tracing", "ttf-parser", "typst", + "typst-macros", + "typst-timing", "xmlparser", "xmlwriter", ] @@ -2868,7 +2644,6 @@ dependencies = [ "ecow", "once_cell", "serde", - "tracing", "unicode-ident", "unicode-math-class", "unicode-script", @@ -2897,6 +2672,16 @@ dependencies = [ "walkdir", ] +[[package]] +name = "typst-timing" +version = "0.10.0" +dependencies = [ + "parking_lot", + "serde", + "serde_json", + "typst-syntax", +] + [[package]] name = "unic-langid" version = "0.9.4" @@ -3144,12 +2929,6 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "711b9620af191e0cdc7468a8d14e709c3dcdb115b36f838e601583af800a370a" -[[package]] -name = "valuable" -version = "0.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" - [[package]] name = "version_check" version = "0.9.4" @@ -3555,26 +3334,6 @@ dependencies = [ "synstructure", ] -[[package]] -name = "zerocopy" -version = "0.7.31" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1c4061bedbb353041c12f413700357bec76df2c7e2ca8e4df8bac24c6bf68e3d" -dependencies = [ - "zerocopy-derive", -] - -[[package]] -name = "zerocopy-derive" -version = "0.7.31" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b3c129550b3e6de3fd0ba67ba5c81818f9805e58b8d7fee80a3a59d2c9fc601a" -dependencies = [ - "proc-macro2", - "quote", - "syn", -] - [[package]] name = "zerofrom" version = "0.1.3" diff --git a/Cargo.toml b/Cargo.toml index 625543268..ad1d416a5 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -25,6 +25,7 @@ typst-pdf = { path = "crates/typst-pdf" } typst-render = { path = "crates/typst-render" } typst-svg = { path = "crates/typst-svg" } typst-syntax = { path = "crates/typst-syntax" } +typst-timing = { path = "crates/typst-timing" } az = "1.2" base64 = "0.21.2" bitflags = { version = "2", features = ["serde"] } @@ -56,7 +57,6 @@ if_chain = "1" image = { version = "0.24", default-features = false, features = ["png", "jpeg", "gif"] } include_dir = "0.7" indexmap = { version = "2", features = ["serde"] } -inferno = "0.11.15" kurbo = "0.9" # in sync with usvg libfuzzer-sys = "0.4" lipsum = "0.9" @@ -99,10 +99,6 @@ tempfile = "3.7.0" time = { version = "0.3.20", features = ["formatting", "macros", "parsing"] } tiny-skia = "0.11" toml = { version = "0.8", default-features = false, features = ["parse", "display"] } -tracing = "0.1.37" -tracing-error = "0.2" -tracing-flame = "0.2.0" -tracing-subscriber = "0.3.17" ttf-parser = "0.20.0" two-face = { version = "0.3.0", default-features = false, features = ["syntect-fancy"] } typed-arena = "2" @@ -137,3 +133,4 @@ strip = true [workspace.lints.clippy] uninlined_format_args = "warn" +blocks_in_if_conditions = "allow" diff --git a/crates/typst-cli/Cargo.toml b/crates/typst-cli/Cargo.toml index 702746f5e..286af7f77 100644 --- a/crates/typst-cli/Cargo.toml +++ b/crates/typst-cli/Cargo.toml @@ -21,9 +21,11 @@ doc = false [dependencies] typst = { workspace = true } +typst-macros = { workspace = true } typst-pdf = { workspace = true } typst-render = { workspace = true } typst-svg = { workspace = true } +typst-timing = { workspace = true } chrono = { workspace = true } clap = { workspace = true } codespan-reporting = { workspace = true } @@ -33,7 +35,6 @@ ecow = { workspace = true } env_proxy = { workspace = true } flate2 = { workspace = true } fontdb = { workspace = true, features = ["memmap", "fontconfig"] } -inferno = { workspace = true } notify = { workspace = true } once_cell = { workspace = true } open = { workspace = true } @@ -51,10 +52,6 @@ serde_yaml = { workspace = true } siphasher = { workspace = true } tar = { workspace = true } tempfile = { workspace = true } -tracing = { workspace = true } -tracing-error = { workspace = true } -tracing-flame = { workspace = true } -tracing-subscriber = { workspace = true } ureq = { workspace = true } xz2 = { workspace = true, optional = true } zip = { workspace = true, optional = true } diff --git a/crates/typst-cli/src/args.rs b/crates/typst-cli/src/args.rs index 8f0261f1d..ec5e8ed11 100644 --- a/crates/typst-cli/src/args.rs +++ b/crates/typst-cli/src/args.rs @@ -17,11 +17,6 @@ pub struct CliArguments { #[command(subcommand)] pub command: Command, - /// Sets the level of logging verbosity: - /// -v = warning & error, -vv = info, -vvv = debug, -vvvv = trace - #[clap(short, long, action = ArgAction::Count)] - pub verbosity: u8, - /// Path to a custom CA certificate to use when making network requests. #[clap(long = "cert", env = "TYPST_CERT")] pub cert: Option, @@ -72,9 +67,13 @@ pub struct CompileCommand { #[arg(long = "ppi", default_value_t = 144.0)] pub ppi: f32, - /// Produces a flamegraph of the compilation process - #[arg(long = "flamegraph", value_name = "OUTPUT_SVG")] - pub flamegraph: Option>, + /// Produces performance timings of the compilation process (experimental) + /// + /// The resulting JSON file can be loaded into a tracing tool such as + /// https://ui.perfetto.dev. It does not contain any sensitive information + /// apart from file names and line numbers. + #[arg(long = "timings", value_name = "OUTPUT_JSON")] + pub timings: Option>, } /// Processes an input file to extract provided metadata diff --git a/crates/typst-cli/src/compile.rs b/crates/typst-cli/src/compile.rs index 5916f18bd..ea6126308 100644 --- a/crates/typst-cli/src/compile.rs +++ b/crates/typst-cli/src/compile.rs @@ -18,6 +18,7 @@ use typst::visualize::Color; use typst::{World, WorldExt}; use crate::args::{CompileCommand, DiagnosticFormat, OutputFormat}; +use crate::timings::Timer; use crate::watch::Status; use crate::world::SystemWorld; use crate::{color_stream, set_failed}; @@ -59,23 +60,21 @@ impl CompileCommand { } /// Execute a compilation command. -pub fn compile(mut command: CompileCommand) -> StrResult<()> { +pub fn compile(mut timer: Timer, mut command: CompileCommand) -> StrResult<()> { let mut world = SystemWorld::new(&command.common)?; - compile_once(&mut world, &mut command, false)?; + timer.record(&mut world, |world| compile_once(world, &mut command, false))??; Ok(()) } /// Compile a single time. /// /// Returns whether it compiled without errors. -#[tracing::instrument(skip_all)] +#[typst_macros::time(name = "compile once")] pub fn compile_once( world: &mut SystemWorld, command: &mut CompileCommand, watching: bool, ) -> StrResult<()> { - tracing::info!("Starting compilation"); - let start = std::time::Instant::now(); if watching { Status::Compiling.print(command).unwrap(); @@ -84,8 +83,6 @@ pub fn compile_once( // Check if main file can be read and opened. if let Err(errors) = world.source(world.main()).at(Span::detached()) { set_failed(); - tracing::info!("Failed to open and decode main file"); - if watching { Status::Error.print(command).unwrap(); } @@ -106,7 +103,6 @@ pub fn compile_once( export(world, &document, command, watching)?; let duration = start.elapsed(); - tracing::info!("Compilation succeeded in {duration:?}"); if watching { if warnings.is_empty() { Status::Success(duration).print(command).unwrap(); @@ -126,7 +122,6 @@ pub fn compile_once( // Print diagnostics. Err(errors) => { set_failed(); - tracing::info!("Compilation failed"); if watching { Status::Error.print(command).unwrap(); diff --git a/crates/typst-cli/src/fonts.rs b/crates/typst-cli/src/fonts.rs index 7793840c0..4ea9f446a 100644 --- a/crates/typst-cli/src/fonts.rs +++ b/crates/typst-cli/src/fonts.rs @@ -5,6 +5,7 @@ use std::sync::OnceLock; use fontdb::{Database, Source}; use typst::diag::StrResult; use typst::text::{Font, FontBook, FontInfo, FontVariant}; +use typst_timing::TimingScope; use crate::args::FontsCommand; @@ -50,6 +51,7 @@ impl FontSlot { pub fn get(&self) -> Option { self.font .get_or_init(|| { + let _scope = TimingScope::new("load font", None); let data = fs::read(&self.path).ok()?.into(); Font::new(data, self.index) }) diff --git a/crates/typst-cli/src/main.rs b/crates/typst-cli/src/main.rs index bab1a07b9..15a758af8 100644 --- a/crates/typst-cli/src/main.rs +++ b/crates/typst-cli/src/main.rs @@ -4,7 +4,7 @@ mod download; mod fonts; mod package; mod query; -mod tracing; +mod timings; #[cfg(feature = "self-update")] mod update; mod watch; @@ -20,6 +20,7 @@ use once_cell::sync::Lazy; use termcolor::{ColorChoice, WriteColor}; use crate::args::{CliArguments, Command}; +use crate::timings::Timer; thread_local! { /// The CLI's exit code. @@ -31,17 +32,10 @@ static ARGS: Lazy = Lazy::new(CliArguments::parse); /// Entry point. fn main() -> ExitCode { - let _guard = match crate::tracing::setup_tracing(&ARGS) { - Ok(guard) => guard, - Err(err) => { - eprintln!("failed to initialize tracing ({err})"); - None - } - }; - + let timer = Timer::new(&ARGS); let res = match &ARGS.command { - Command::Compile(command) => crate::compile::compile(command.clone()), - Command::Watch(command) => crate::watch::watch(command.clone()), + Command::Compile(command) => crate::compile::compile(timer, command.clone()), + Command::Watch(command) => crate::watch::watch(timer, command.clone()), Command::Query(command) => crate::query::query(command), Command::Fonts(command) => crate::fonts::fonts(command), Command::Update(command) => crate::update::update(command), diff --git a/crates/typst-cli/src/query.rs b/crates/typst-cli/src/query.rs index dadcd9787..f2257bdf3 100644 --- a/crates/typst-cli/src/query.rs +++ b/crates/typst-cli/src/query.rs @@ -16,8 +16,6 @@ use crate::world::SystemWorld; /// Execute a query command. pub fn query(command: &QueryCommand) -> StrResult<()> { let mut world = SystemWorld::new(&command.common)?; - tracing::info!("Starting querying"); - // Reset everything and ensure that the main file is present. world.reset(); world.source(world.main()).map_err(|err| err.to_string())?; diff --git a/crates/typst-cli/src/timings.rs b/crates/typst-cli/src/timings.rs new file mode 100644 index 000000000..df7665b7a --- /dev/null +++ b/crates/typst-cli/src/timings.rs @@ -0,0 +1,89 @@ +use std::fs::File; +use std::io::BufWriter; +use std::path::{Path, PathBuf}; + +use typst::diag::{bail, StrResult}; +use typst::syntax::Span; +use typst::World; + +use crate::args::{CliArguments, Command}; +use crate::world::SystemWorld; + +/// Allows to record timings of function executions. +pub struct Timer { + /// Where to save the recorded timings of each compilation step. + path: Option, + /// The current watch iteration. + index: usize, +} + +impl Timer { + /// Initializes the timing system and returns a timer that can be used to + /// record timings for a specific function invocation. + pub fn new(args: &CliArguments) -> Timer { + let record = match &args.command { + Command::Compile(command) => command.timings.clone(), + Command::Watch(command) => command.timings.clone(), + _ => None, + }; + + // Enable event collection. + if record.is_some() { + typst_timing::enable(); + } + + let path = + record.map(|path| path.unwrap_or_else(|| PathBuf::from("record-{n}.json"))); + + Timer { path, index: 0 } + } + + /// Records all timings in `f` and writes them to disk. + pub fn record( + &mut self, + world: &mut SystemWorld, + f: impl FnOnce(&mut SystemWorld) -> T, + ) -> StrResult { + let Some(path) = &self.path else { + return Ok(f(world)); + }; + + typst_timing::clear(); + + let string = path.to_str().unwrap_or_default(); + let numbered = string.contains("{n}"); + if !numbered && self.index > 0 { + bail!("cannot export multiple recordings without `{{n}}` in path"); + } + + let storage; + let path = if numbered { + storage = string.replace("{n}", &self.index.to_string()); + Path::new(&storage) + } else { + path.as_path() + }; + + let output = f(world); + self.index += 1; + + let file = + File::create(path).map_err(|e| format!("failed to create file: {e}"))?; + let writer = BufWriter::with_capacity(1 << 20, file); + + typst_timing::export_json(writer, |span| { + resolve_span(world, span).unwrap_or_else(|| ("unknown".to_string(), 0)) + })?; + + Ok(output) + } +} + +/// Turns a span into a (file, line) pair. +fn resolve_span(world: &SystemWorld, span: Span) -> Option<(String, u32)> { + let id = span.id()?; + let source = world.source(id).ok()?; + let range = source.range(span)?; + let line = source.byte_to_line(range.start)?; + Some((format!("{id:?}"), line as u32 + 1)) +} diff --git a/crates/typst-cli/src/tracing.rs b/crates/typst-cli/src/tracing.rs deleted file mode 100644 index 331c6327f..000000000 --- a/crates/typst-cli/src/tracing.rs +++ /dev/null @@ -1,139 +0,0 @@ -use std::fs::File; -use std::io::{self, BufReader, BufWriter, Seek, SeekFrom}; -use std::path::PathBuf; - -use inferno::flamegraph::Options; -use tracing::metadata::LevelFilter; -use tracing_error::ErrorLayer; -use tracing_flame::{FlameLayer, FlushGuard}; -use tracing_subscriber::layer::SubscriberExt; -use tracing_subscriber::util::SubscriberInitExt; -use tracing_subscriber::{fmt, Layer}; - -use crate::args::{CliArguments, Command}; - -/// Initializes the tracing system and returns a guard that will flush the -/// flamegraph to disk when dropped. -pub fn setup_tracing(args: &CliArguments) -> io::Result> { - let flamegraph = match &args.command { - Command::Compile(command) => command.flamegraph.as_ref(), - Command::Watch(command) if command.flamegraph.is_some() => { - return Err(io::Error::new( - io::ErrorKind::InvalidInput, - "cannot use --flamegraph with watch command", - )); - } - _ => None, - }; - - // Short circuit if we don't need to initialize flamegraph or debugging. - if flamegraph.is_none() && args.verbosity == 0 { - tracing_subscriber::fmt() - .without_time() - .with_max_level(level_filter(args)) - .init(); - - return Ok(None); - } - - // Build the FMT layer printing to the console. - let fmt_layer = fmt::Layer::default().without_time().with_filter(level_filter(args)); - - // Error layer for building backtraces - let error_layer = ErrorLayer::default(); - - // Build the registry. - let registry = tracing_subscriber::registry().with(fmt_layer).with(error_layer); - - let Some(path) = flamegraph else { - registry.init(); - return Ok(None); - }; - - // Create a temporary file to store the flamegraph data. - let temp_file = tempfile::tempfile()?; - let writer = BufWriter::new(temp_file.try_clone()?); - - // Build the flamegraph layer. - let flame_layer = FlameLayer::new(writer) - .with_empty_samples(false) - .with_threads_collapsed(true) - .with_module_path(false) - .with_file_and_line(true); - let flush_guard = flame_layer.flush_on_drop(); - - // Build the subscriber. - registry.with(flame_layer).init(); - - tracing::warn!( - "Flamegraph is enabled, this can create a large temporary \ - file and slow down the compilation process." - ); - - Ok(Some(TracingGuard { - flush_guard: Some(flush_guard), - temp_file, - output_svg: path.clone().unwrap_or_else(|| "flamegraph.svg".into()), - })) -} - -/// Returns the log level filter for the given verbosity level. -fn level_filter(args: &CliArguments) -> LevelFilter { - match args.verbosity { - 0 => LevelFilter::OFF, - 1 => LevelFilter::WARN, - 2 => LevelFilter::INFO, - 3 => LevelFilter::DEBUG, - _ => LevelFilter::TRACE, - } -} - -/// Will flush the flamegraph to disk when dropped. -struct TracingGuard { - flush_guard: Option>>, - temp_file: File, - output_svg: PathBuf, -} - -impl TracingGuard { - fn finish(&mut self) -> io::Result<()> { - if self.flush_guard.is_none() { - return Ok(()); - } - - tracing::info!("Flushing tracing flamegraph..."); - - // At this point, we're done tracing, so we can drop the guard. - // This will flush the tracing output to disk. - // We can then read the file and generate the flamegraph. - drop(self.flush_guard.take()); - - // Reset the file pointer to the beginning. - self.temp_file.seek(SeekFrom::Start(0))?; - - // Create the readers and writers. - let reader = BufReader::new(&mut self.temp_file); - let output = BufWriter::new(File::create(&self.output_svg)?); - - // Create the options: default in flame chart mode - let mut options = Options::default(); - options.flame_chart = true; - - inferno::flamegraph::from_reader(&mut options, reader, output) - .map_err(|e| io::Error::new(io::ErrorKind::Other, e))?; - - Ok(()) - } -} - -impl Drop for TracingGuard { - fn drop(&mut self) { - if !std::thread::panicking() { - if let Err(err) = self.finish() { - // Since we are finished, we cannot rely on tracing to log the - // error. - eprintln!("failed to flush tracing flamegraph ({err})"); - } - } - } -} diff --git a/crates/typst-cli/src/watch.rs b/crates/typst-cli/src/watch.rs index aea3ca48b..ee3a8f5bc 100644 --- a/crates/typst-cli/src/watch.rs +++ b/crates/typst-cli/src/watch.rs @@ -12,15 +12,16 @@ use typst::diag::StrResult; use crate::args::CompileCommand; use crate::color_stream; use crate::compile::compile_once; +use crate::timings::Timer; use crate::world::SystemWorld; /// Execute a watching compilation command. -pub fn watch(mut command: CompileCommand) -> StrResult<()> { +pub fn watch(mut timer: Timer, mut command: CompileCommand) -> StrResult<()> { // Create the world that serves sources, files, and fonts. let mut world = SystemWorld::new(&command.common)?; // Perform initial compilation. - compile_once(&mut world, &mut command, true)?; + timer.record(&mut world, |world| compile_once(world, &mut command, true))??; // Setup file watching. let (tx, rx) = std::sync::mpsc::channel(); @@ -67,7 +68,9 @@ pub fn watch(mut command: CompileCommand) -> StrResult<()> { world.reset(); // Recompile. - compile_once(&mut world, &mut command, true)?; + timer + .record(&mut world, |world| compile_once(world, &mut command, true))??; + comemo::evict(10); // Adjust the file watching. @@ -78,7 +81,6 @@ pub fn watch(mut command: CompileCommand) -> StrResult<()> { /// Adjust the file watching. Watches all new dependencies and unwatches /// all previously `watched` files that are no relevant anymore. -#[tracing::instrument(skip_all)] fn watch_dependencies( world: &mut SystemWorld, watcher: &mut dyn Watcher, @@ -95,7 +97,6 @@ fn watch_dependencies( // unfortunately, so we filter those out. for path in world.dependencies().filter(|path| path.exists()) { if !watched.contains_key(&path) { - tracing::info!("Watching {}", path.display()); watcher .watch(&path, RecursiveMode::NonRecursive) .map_err(|err| eco_format!("failed to watch {path:?} ({err})"))?; @@ -108,7 +109,6 @@ fn watch_dependencies( // Unwatch old paths that don't need to be watched anymore. watched.retain(|path, &mut seen| { if !seen { - tracing::info!("Unwatching {}", path.display()); watcher.unwatch(path).ok(); } seen diff --git a/crates/typst-cli/src/world.rs b/crates/typst-cli/src/world.rs index 095458df7..fee6b7db1 100644 --- a/crates/typst-cli/src/world.rs +++ b/crates/typst-cli/src/world.rs @@ -12,6 +12,7 @@ use typst::foundations::{Bytes, Datetime, Dict, IntoValue}; use typst::syntax::{FileId, Source, VirtualPath}; use typst::text::{Font, FontBook}; use typst::{Library, World}; +use typst_timing::{timed, TimingScope}; use crate::args::SharedArgs; use crate::compile::ExportCache; @@ -232,6 +233,8 @@ impl FileSlot { self.source.get_or_init( || system_path(project_root, self.id), |data, prev| { + let name = if prev.is_some() { "reparsing file" } else { "parsing file" }; + let _scope = TimingScope::new(name, None); let text = decode_utf8(&data)?; if let Some(mut prev) = prev { prev.replace(text); @@ -291,8 +294,8 @@ impl SlotCell { } // Read and hash the file. - let result = path().and_then(|p| read(&p)); - let fingerprint = typst::util::hash128(&result); + let result = timed!("loading file", path().and_then(|p| read(&p))); + let fingerprint = timed!("hashing file", typst::util::hash128(&result)); // If the file contents didn't change, yield the old processed data. if mem::replace(&mut self.fingerprint, fingerprint) == fingerprint { diff --git a/crates/typst-macros/src/lib.rs b/crates/typst-macros/src/lib.rs index 28d02a6e4..8ca7bcac3 100644 --- a/crates/typst-macros/src/lib.rs +++ b/crates/typst-macros/src/lib.rs @@ -10,6 +10,7 @@ mod elem; mod func; mod scope; mod symbols; +mod time; mod ty; use proc_macro::TokenStream as BoundaryStream; @@ -342,3 +343,43 @@ pub fn symbols(stream: BoundaryStream) -> BoundaryStream { .unwrap_or_else(|err| err.to_compile_error()) .into() } + +/// Times the function invokations. +/// +/// When tracing is enabled in the typst-cli, this macro will record the +/// invokations 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 invokation: +/// - `#[time(span = ..)]` to record the span, which will be used for the +/// `EventKey`. +/// +/// By default, all tracing is ommited using the `wasm32` target flag. +/// This is done to avoid bloating the web app which doesn't need tracing. +/// +/// ```ignore +/// #[time] +/// fn fibonacci(n: u64) -> u64 { +/// if n <= 1 { +/// 1 +/// } else { +/// fibonacci(n - 1) + fibonacci(n - 2) +/// } +/// } +/// +/// #[time(span = span)] +/// fn fibonacci_spanned(n: u64, span: Span) -> u64 { +/// if n <= 1 { +/// 1 +/// } else { +/// fibonacci(n - 1) + fibonacci(n - 2) +/// } +/// } +/// ``` +#[proc_macro_attribute] +pub fn time(stream: BoundaryStream, item: BoundaryStream) -> BoundaryStream { + let item = syn::parse_macro_input!(item as syn::ItemFn); + time::time(stream.into(), &item) + .unwrap_or_else(|err| err.to_compile_error()) + .into() +} diff --git a/crates/typst-macros/src/time.rs b/crates/typst-macros/src/time.rs new file mode 100644 index 000000000..fbe1ebc67 --- /dev/null +++ b/crates/typst-macros/src/time.rs @@ -0,0 +1,51 @@ +use proc_macro2::TokenStream; +use quote::quote; +use syn::parse::{Parse, ParseStream}; +use syn::Result; + +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)) +} + +/// The `..` in `#[time(..)]`. +pub struct Meta { + pub span: Option, + pub name: Option, +} + +impl Parse for Meta { + fn parse(input: ParseStream) -> Result { + Ok(Self { + name: parse_string::(input)?, + span: parse_key_value::(input)?, + }) + } +} + +fn create(meta: Meta, item: &syn::ItemFn) -> TokenStream { + let name = meta.name.unwrap_or_else(|| item.sig.ident.to_string()); + let span = meta + .span + .as_ref() + .map(|span| quote! { Some(#span) }) + .unwrap_or_else(|| quote! { None }); + + let sig = &item.sig; + let vis = &item.vis; + let block = &item.block; + quote! { + #vis #sig { + #[cfg(not(target_arch = "wasm32"))] + let __scope = ::typst_timing::TimingScope::new(#name, { + use ::typst::foundations::NativeElement; + #span + }); + + #block + } + } +} diff --git a/crates/typst-macros/src/util.rs b/crates/typst-macros/src/util.rs index 32c0aa4e6..4f7cc5fb5 100644 --- a/crates/typst-macros/src/util.rs +++ b/crates/typst-macros/src/util.rs @@ -252,6 +252,7 @@ impl Parse for BareType { pub mod kw { syn::custom_keyword!(name); + syn::custom_keyword!(span); syn::custom_keyword!(title); syn::custom_keyword!(scope); syn::custom_keyword!(constructor); diff --git a/crates/typst-pdf/Cargo.toml b/crates/typst-pdf/Cargo.toml index ae838f3bb..3dcddbb0d 100644 --- a/crates/typst-pdf/Cargo.toml +++ b/crates/typst-pdf/Cargo.toml @@ -17,6 +17,8 @@ bench = false [dependencies] typst = { workspace = true } +typst-macros = { workspace = true } +typst-timing = { workspace = true } base64 = { workspace = true } bytemuck = { workspace = true } comemo = { workspace = true } @@ -27,7 +29,6 @@ once_cell = { workspace = true } pdf-writer = { workspace = true } subsetter = { workspace = true } svg2pdf = { workspace = true } -tracing = { workspace = true } ttf-parser = { workspace = true } unicode-properties = { workspace = true } unscanny = { workspace = true } diff --git a/crates/typst-pdf/src/extg.rs b/crates/typst-pdf/src/extg.rs index d95b91c40..f3ad3815c 100644 --- a/crates/typst-pdf/src/extg.rs +++ b/crates/typst-pdf/src/extg.rs @@ -22,7 +22,6 @@ impl ExtGState { } /// Embed all used external graphics states into the PDF. -#[tracing::instrument(skip_all)] pub(crate) fn write_external_graphics_states(ctx: &mut PdfContext) { for external_gs in ctx.extg_map.items() { let id = ctx.alloc.bump(); diff --git a/crates/typst-pdf/src/font.rs b/crates/typst-pdf/src/font.rs index ce3913f7c..cc116613c 100644 --- a/crates/typst-pdf/src/font.rs +++ b/crates/typst-pdf/src/font.rs @@ -21,7 +21,7 @@ const SYSTEM_INFO: SystemInfo = SystemInfo { }; /// Embed all used fonts into the PDF. -#[tracing::instrument(skip_all)] +#[typst_macros::time(name = "write fonts")] pub(crate) fn write_fonts(ctx: &mut PdfContext) { for font in ctx.font_map.items() { let type0_ref = ctx.alloc.bump(); @@ -168,6 +168,7 @@ pub(crate) fn write_fonts(ctx: &mut PdfContext) { /// - For a font with TrueType outlines, this returns the whole OpenType font. /// - For a font with CFF outlines, this returns just the CFF font program. #[comemo::memoize] +#[typst_macros::time(name = "subset font")] fn subset_font(font: &Font, glyphs: &[u16]) -> Arc> { let data = font.data(); let profile = subsetter::Profile::pdf(glyphs); diff --git a/crates/typst-pdf/src/image.rs b/crates/typst-pdf/src/image.rs index 2e99eef59..3857e68f4 100644 --- a/crates/typst-pdf/src/image.rs +++ b/crates/typst-pdf/src/image.rs @@ -32,7 +32,7 @@ pub fn deferred_image(image: Image) -> Deferred { } /// Embed all used images into the PDF. -#[tracing::instrument(skip_all)] +#[typst_macros::time(name = "write images")] pub(crate) fn write_images(ctx: &mut PdfContext) { for (i, _) in ctx.image_map.items().enumerate() { let handle = ctx.image_deferred_map.get(&i).unwrap(); @@ -111,7 +111,6 @@ pub(crate) fn write_images(ctx: &mut PdfContext) { /// whether the image has color. /// /// Skips the alpha channel as that's encoded separately. -#[tracing::instrument(skip_all)] fn encode_raster_image(image: &RasterImage) -> (Vec, Filter, bool) { let dynamic = image.dynamic(); match (image.format(), dynamic) { @@ -154,7 +153,6 @@ fn encode_raster_image(image: &RasterImage) -> (Vec, Filter, bool) { } /// Encode an image's alpha channel if present. -#[tracing::instrument(skip_all)] fn encode_alpha(raster: &RasterImage) -> (Vec, Filter) { let pixels: Vec<_> = raster .dynamic() @@ -167,7 +165,6 @@ fn encode_alpha(raster: &RasterImage) -> (Vec, Filter) { /// Encode an SVG into a chunk of PDF objects. /// /// The main XObject will have ID 1. -#[tracing::instrument(skip_all)] fn encode_svg(svg: &SvgImage) -> Chunk { let mut chunk = Chunk::new(); diff --git a/crates/typst-pdf/src/lib.rs b/crates/typst-pdf/src/lib.rs index dba4e3dc1..63a9dd978 100644 --- a/crates/typst-pdf/src/lib.rs +++ b/crates/typst-pdf/src/lib.rs @@ -47,7 +47,7 @@ use crate::pattern::PdfPattern; /// The `timestamp`, if given, is expected to be the creation date of the /// document as a UTC datetime. It will only be used if `set document(date: ..)` /// is `auto`. -#[tracing::instrument(skip_all)] +#[typst_macros::time(name = "pdf")] pub fn pdf( document: &Document, ident: Option<&str>, @@ -147,7 +147,6 @@ impl<'a> PdfContext<'a> { } /// Write the document catalog. -#[tracing::instrument(skip_all)] fn write_catalog(ctx: &mut PdfContext, ident: Option<&str>, timestamp: Option) { let lang = ctx .languages @@ -278,7 +277,6 @@ fn write_catalog(ctx: &mut PdfContext, ident: Option<&str>, timestamp: Option Vec { const COMPRESSION_LEVEL: u8 = 6; miniz_oxide::deflate::compress_to_vec_zlib(data, COMPRESSION_LEVEL) diff --git a/crates/typst-pdf/src/outline.rs b/crates/typst-pdf/src/outline.rs index 9c9ef4139..78698cf8c 100644 --- a/crates/typst-pdf/src/outline.rs +++ b/crates/typst-pdf/src/outline.rs @@ -8,7 +8,6 @@ use typst::model::HeadingElem; use crate::{AbsExt, PdfContext}; /// Construct the outline for the document. -#[tracing::instrument(skip_all)] pub(crate) fn write_outline(ctx: &mut PdfContext) -> Option { let mut tree: Vec = vec![]; @@ -130,7 +129,6 @@ impl HeadingNode { } /// Write an outline item and all its children. -#[tracing::instrument(skip_all)] fn write_outline_item( ctx: &mut PdfContext, node: &HeadingNode, diff --git a/crates/typst-pdf/src/page.rs b/crates/typst-pdf/src/page.rs index 89b0ba5f4..d3bbcb74d 100644 --- a/crates/typst-pdf/src/page.rs +++ b/crates/typst-pdf/src/page.rs @@ -26,7 +26,7 @@ use crate::image::deferred_image; use crate::{deflate_deferred, AbsExt, EmExt, PdfContext}; /// Construct page objects. -#[tracing::instrument(skip_all)] +#[typst_macros::time(name = "construct pages")] pub(crate) fn construct_pages(ctx: &mut PdfContext, frames: &[Frame]) { for frame in frames { let (page_ref, page) = construct_page(ctx, frame); @@ -36,7 +36,7 @@ pub(crate) fn construct_pages(ctx: &mut PdfContext, frames: &[Frame]) { } /// Construct a page object. -#[tracing::instrument(skip_all)] +#[typst_macros::time(name = "construct page")] pub(crate) fn construct_page(ctx: &mut PdfContext, frame: &Frame) -> (Ref, Page) { let page_ref = ctx.alloc.bump(); @@ -83,7 +83,6 @@ pub(crate) fn construct_page(ctx: &mut PdfContext, frame: &Frame) -> (Ref, Page) } /// Write the page tree. -#[tracing::instrument(skip_all)] pub(crate) fn write_page_tree(ctx: &mut PdfContext) { for i in 0..ctx.pages.len() { write_page(ctx, i); @@ -142,7 +141,6 @@ pub(crate) fn write_page_tree(ctx: &mut PdfContext) { } /// Write a page tree node. -#[tracing::instrument(skip_all)] fn write_page(ctx: &mut PdfContext, i: usize) { let page = &ctx.pages[i]; let content_id = ctx.alloc.bump(); @@ -204,7 +202,6 @@ fn write_page(ctx: &mut PdfContext, i: usize) { } /// Write the page labels. -#[tracing::instrument(skip_all)] pub(crate) fn write_page_labels(ctx: &mut PdfContext) -> Vec<(NonZeroUsize, Ref)> { let mut result = vec![]; let mut prev: Option<&PdfPageLabel> = None; diff --git a/crates/typst-render/Cargo.toml b/crates/typst-render/Cargo.toml index 546afccb0..28033b3ef 100644 --- a/crates/typst-render/Cargo.toml +++ b/crates/typst-render/Cargo.toml @@ -17,6 +17,8 @@ bench = false [dependencies] typst = { workspace = true } +typst-macros = { workspace = true } +typst-timing = { workspace = true } bytemuck = { workspace = true } comemo = { workspace = true } flate2 = { workspace = true } diff --git a/crates/typst-render/src/lib.rs b/crates/typst-render/src/lib.rs index b906ac53d..34e9b7b3d 100644 --- a/crates/typst-render/src/lib.rs +++ b/crates/typst-render/src/lib.rs @@ -24,6 +24,7 @@ use usvg::{NodeExt, TreeParsing}; /// /// This renders the frame at the given number of pixels per point and returns /// the resulting `tiny-skia` pixel buffer. +#[typst_macros::time(name = "render")] pub fn render(frame: &Frame, pixel_per_pt: f32, fill: Color) -> sk::Pixmap { let size = frame.size(); let pxw = (pixel_per_pt * size.x.to_f32()).round().max(1.0) as u32; diff --git a/crates/typst-svg/Cargo.toml b/crates/typst-svg/Cargo.toml index 030f493be..163d85573 100644 --- a/crates/typst-svg/Cargo.toml +++ b/crates/typst-svg/Cargo.toml @@ -17,11 +17,12 @@ bench = false [dependencies] typst = { workspace = true } +typst-macros = { workspace = true } +typst-timing = { workspace = true } base64 = { workspace = true } comemo = { workspace = true } ecow = { workspace = true} flate2 = { workspace = true } -tracing = { workspace = true } ttf-parser = { workspace = true } xmlparser = { workspace = true } xmlwriter = { workspace = true } diff --git a/crates/typst-svg/src/lib.rs b/crates/typst-svg/src/lib.rs index 62f217f59..bb451cbe9 100644 --- a/crates/typst-svg/src/lib.rs +++ b/crates/typst-svg/src/lib.rs @@ -25,7 +25,7 @@ use xmlwriter::XmlWriter; const CONIC_SEGMENT: usize = 360; /// Export a frame into a SVG file. -#[tracing::instrument(skip_all)] +#[typst_macros::time(name = "svg")] pub fn svg(frame: &Frame) -> String { let mut renderer = SVGRenderer::new(); renderer.write_header(frame.size()); @@ -38,7 +38,6 @@ pub fn svg(frame: &Frame) -> String { /// Export multiple frames into a single SVG file. /// /// The padding will be added around and between the individual frames. -#[tracing::instrument(skip_all)] pub fn svg_merged(frames: &[Frame], padding: Abs) -> String { let width = 2.0 * padding + frames.iter().map(|frame| frame.width()).max().unwrap_or_default(); diff --git a/crates/typst-syntax/Cargo.toml b/crates/typst-syntax/Cargo.toml index b2c721eb0..708f7de88 100644 --- a/crates/typst-syntax/Cargo.toml +++ b/crates/typst-syntax/Cargo.toml @@ -20,7 +20,6 @@ comemo = { workspace = true } ecow = { workspace = true } once_cell = { workspace = true } serde = { workspace = true } -tracing = { workspace = true } unicode-ident = { workspace = true } unicode-math-class = { workspace = true } unicode-script = { workspace = true } diff --git a/crates/typst-syntax/src/node.rs b/crates/typst-syntax/src/node.rs index d70f39b7e..fed7049ca 100644 --- a/crates/typst-syntax/src/node.rs +++ b/crates/typst-syntax/src/node.rs @@ -202,7 +202,6 @@ impl SyntaxNode { } /// Assign spans to each node. - #[tracing::instrument(skip_all)] pub(super) fn numberize( &mut self, id: FileId, diff --git a/crates/typst-syntax/src/parser.rs b/crates/typst-syntax/src/parser.rs index 1d8875ddd..9e718b300 100644 --- a/crates/typst-syntax/src/parser.rs +++ b/crates/typst-syntax/src/parser.rs @@ -7,7 +7,6 @@ use unicode_math_class::MathClass; use crate::{ast, is_ident, is_newline, LexMode, Lexer, SyntaxKind, SyntaxNode}; /// Parse a source file. -#[tracing::instrument(skip_all)] pub fn parse(text: &str) -> SyntaxNode { let mut p = Parser::new(text, 0, LexMode::Markup); markup(&mut p, true, 0, |_| false); @@ -15,7 +14,6 @@ pub fn parse(text: &str) -> SyntaxNode { } /// Parse top-level code. -#[tracing::instrument(skip_all)] pub fn parse_code(text: &str) -> SyntaxNode { let mut p = Parser::new(text, 0, LexMode::Code); let m = p.marker(); @@ -26,7 +24,6 @@ pub fn parse_code(text: &str) -> SyntaxNode { } /// Parse top-level math. -#[tracing::instrument(skip_all)] pub fn parse_math(text: &str) -> SyntaxNode { let mut p = Parser::new(text, 0, LexMode::Math); math(&mut p, |_| false); diff --git a/crates/typst-syntax/src/source.rs b/crates/typst-syntax/src/source.rs index 3631a2ea7..b4a80d318 100644 --- a/crates/typst-syntax/src/source.rs +++ b/crates/typst-syntax/src/source.rs @@ -30,7 +30,6 @@ struct Repr { impl Source { /// Create a new source file. - #[tracing::instrument(skip_all)] pub fn new(id: FileId, text: String) -> Self { let mut root = parse(&text); root.numberize(id, Span::FULL).unwrap(); diff --git a/crates/typst-timing/Cargo.toml b/crates/typst-timing/Cargo.toml new file mode 100644 index 000000000..557561ea0 --- /dev/null +++ b/crates/typst-timing/Cargo.toml @@ -0,0 +1,21 @@ +[package] +name = "typst-timing" +description = "Performance timing for Typst." +version = { workspace = true } +rust-version = { workspace = true } +authors = { workspace = true } +edition = { workspace = true } +homepage = { workspace = true } +repository = { workspace = true } +license = { workspace = true } +categories = { workspace = true } +keywords = { workspace = true } + +[dependencies] +typst-syntax = { workspace = true } +parking_lot = { workspace = true } +serde = { workspace = true } +serde_json = { workspace = true } + +[lints] +workspace = true diff --git a/crates/typst-timing/src/lib.rs b/crates/typst-timing/src/lib.rs new file mode 100644 index 000000000..fe9abb513 --- /dev/null +++ b/crates/typst-timing/src/lib.rs @@ -0,0 +1,233 @@ +//! Performance timing for Typst. + +use std::hash::Hash; +use std::io::Write; +use std::thread::ThreadId; +use std::time::{Duration, SystemTime}; + +use parking_lot::Mutex; +use serde::ser::SerializeSeq; +use serde::{Serialize, Serializer}; +use typst_syntax::Span; + +/// Whether the timer is enabled. Defaults to `false`. +/// +/// # Safety +/// This is unsafe because it is a global variable that is not thread-safe. +/// But at worst, if we have a race condition, we will just be missing some +/// events. So it's not a big deal. And it avoids needing to do an atomic +/// operation every time we want to check if the timer is enabled. +static mut ENABLED: bool = false; + +/// The global event recorder. +static RECORDER: Mutex = Mutex::new(Recorder::new()); + +/// The recorder of events. +struct Recorder { + /// The events that have been recorded. + events: Vec, + /// The discriminator of the next event. + discriminator: u64, +} + +impl Recorder { + /// Create a new recorder. + const fn new() -> Self { + Self { events: Vec::new(), discriminator: 0 } + } +} + +/// An event that has been recorded. +#[derive(Clone, Copy, Eq, PartialEq, Hash)] +struct Event { + /// Whether this is a start or end event. + kind: EventKind, + /// The start time of this event. + timestamp: SystemTime, + /// The discriminator of this event. + id: u64, + /// The name of this event. + name: &'static str, + /// The span of code that this event was recorded in. + span: Option, + /// The thread ID of this event. + thread_id: ThreadId, +} + +/// Whether an event marks the start or end of a scope. +#[derive(Debug, Clone, Copy, Eq, PartialEq, Hash)] +enum EventKind { + Start, + End, +} + +/// Enable the timer. +#[inline] +pub fn enable() { + unsafe { + ENABLED = true; + } +} + +/// Whether the timer is enabled. +#[inline] +pub fn is_enabled() -> bool { + unsafe { ENABLED } +} + +/// Clears the recorded events. +#[inline] +pub fn clear() { + RECORDER.lock().events.clear(); +} + +/// A scope that records an event when it is dropped. +pub struct TimingScope { + name: &'static str, + span: Option, + id: u64, + thread_id: ThreadId, +} + +impl TimingScope { + /// Create a new scope if timing is enabled. + pub fn new(name: &'static str, span: Option) -> Option { + if !is_enabled() { + return None; + } + + let timestamp = SystemTime::now(); + let thread_id = std::thread::current().id(); + + let mut recorder = RECORDER.lock(); + let id = recorder.discriminator; + recorder.discriminator += 1; + recorder.events.push(Event { + kind: EventKind::Start, + timestamp, + id, + name, + span, + thread_id, + }); + + Some(TimingScope { name, span, id, thread_id }) + } +} + +impl Drop for TimingScope { + fn drop(&mut self) { + let event = Event { + kind: EventKind::End, + timestamp: SystemTime::now(), + id: self.id, + name: self.name, + span: self.span, + thread_id: self.thread_id, + }; + + RECORDER.lock().events.push(event); + } +} + +/// Creates a timing scope around an expression. +/// +/// The output of the expression is returned. +/// +/// The scope will be named `name` and will have the span `span`. The span is +/// optional. +/// +/// ## Example +/// +/// ```rs +/// // With a scope name and span. +/// timed!( +/// "my scope", +/// span = Span::detached(), +/// std::thread::sleep(std::time::Duration::from_secs(1)), +/// ); +/// +/// // With a scope name and no span. +/// timed!( +/// "my scope", +/// std::thread::sleep(std::time::Duration::from_secs(1)), +/// ); +/// ``` +#[macro_export] +macro_rules! timed { + ($name:expr, span = $span:expr, $body:expr $(,)?) => {{ + let __scope = $crate::TimingScope::new($name, Some($span)); + $body + }}; + ($name:expr, $body:expr $(,)?) => {{ + let __scope = $crate::TimingScope::new($name, None); + $body + }}; +} + +/// Export data as JSON for Chrome's tracing tool. +/// +/// The `source` function is called for each span to get the source code +/// location of the span. The first element of the tuple is the file path and +/// the second element is the line number. +pub fn export_json( + writer: W, + mut source: impl FnMut(Span) -> (String, u32), +) -> Result<(), String> { + #[derive(Serialize)] + struct Entry { + 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, + } + + let recorder = RECORDER.lock(); + let run_start = recorder + .events + .first() + .map(|event| event.timestamp) + .unwrap_or_else(SystemTime::now); + + let mut serializer = serde_json::Serializer::new(writer); + let mut seq = serializer + .serialize_seq(Some(recorder.events.len())) + .map_err(|e| format!("failed to serialize events: {e}"))?; + + for event in recorder.events.iter() { + seq.serialize_element(&Entry { + name: event.name, + cat: "typst", + ph: match event.kind { + EventKind::Start => "B", + EventKind::End => "E", + }, + ts: event + .timestamp + .duration_since(run_start) + .unwrap_or(Duration::ZERO) + .as_nanos() as f64 + / 1_000.0, + pid: 1, + tid: unsafe { + // Safety: `thread_id` is a `ThreadId` which is a `u64`. + std::mem::transmute_copy(&event.thread_id) + }, + args: event.span.map(&mut source).map(|(file, line)| Args { file, line }), + }) + .map_err(|e| format!("failed to serialize event: {e}"))?; + } + + seq.end().map_err(|e| format!("failed to serialize events: {e}"))?; + + Ok(()) +} diff --git a/crates/typst/Cargo.toml b/crates/typst/Cargo.toml index a22bb7927..f04110acb 100644 --- a/crates/typst/Cargo.toml +++ b/crates/typst/Cargo.toml @@ -18,6 +18,7 @@ bench = false [dependencies] typst-macros = { workspace = true } typst-syntax = { workspace = true } +typst-timing = { workspace = true } az = { workspace = true } bitflags = { workspace = true } chinese-number = { workspace = true } @@ -52,7 +53,6 @@ smallvec = { workspace = true } syntect = { workspace = true } time = { workspace = true } toml = { workspace = true } -tracing = { workspace = true } ttf-parser = { workspace = true } two-face = { workspace = true } typed-arena = { workspace = true } diff --git a/crates/typst/src/eval/binding.rs b/crates/typst/src/eval/binding.rs index eac35924d..abb2f4bcd 100644 --- a/crates/typst/src/eval/binding.rs +++ b/crates/typst/src/eval/binding.rs @@ -8,7 +8,6 @@ use crate::syntax::ast::{self, AstNode}; impl Eval for ast::LetBinding<'_> { type Output = Value; - #[tracing::instrument(name = "LetBinding::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let value = match self.init() { Some(expr) => expr.eval(vm)?, @@ -57,7 +56,6 @@ pub(crate) fn destructure( } /// Destruct the given value into the pattern and apply the function to each binding. -#[tracing::instrument(skip_all)] fn destructure_impl( vm: &mut Vm, pattern: ast::Pattern, diff --git a/crates/typst/src/eval/call.rs b/crates/typst/src/eval/call.rs index a4b057773..e15f2c335 100644 --- a/crates/typst/src/eval/call.rs +++ b/crates/typst/src/eval/call.rs @@ -19,7 +19,6 @@ use crate::World; impl Eval for ast::FuncCall<'_> { type Output = Value; - #[tracing::instrument(name = "FuncCall::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let span = self.span(); let callee = self.callee(); @@ -227,7 +226,6 @@ impl Eval for ast::Args<'_> { impl Eval for ast::Closure<'_> { type Output = Value; - #[tracing::instrument(name = "Closure::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { // Evaluate default values of named parameters. let mut defaults = Vec::new(); @@ -257,7 +255,6 @@ impl Eval for ast::Closure<'_> { /// Call the function in the context with the arguments. #[comemo::memoize] -#[tracing::instrument(skip_all)] #[allow(clippy::too_many_arguments)] pub(crate) fn call_closure( func: &Func, @@ -395,7 +392,6 @@ impl<'a> CapturesVisitor<'a> { } /// Visit any node and collect all captured variables. - #[tracing::instrument(skip_all)] pub fn visit(&mut self, node: &SyntaxNode) { match node.cast() { // Every identifier is a potential variable that we need to capture. diff --git a/crates/typst/src/eval/code.rs b/crates/typst/src/eval/code.rs index 06b2f2263..d41b593c2 100644 --- a/crates/typst/src/eval/code.rs +++ b/crates/typst/src/eval/code.rs @@ -62,7 +62,6 @@ fn eval_code<'a>( impl Eval for ast::Expr<'_> { type Output = Value; - #[tracing::instrument(name = "Expr::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let span = self.span(); let forbidden = |name| { @@ -140,7 +139,6 @@ impl Eval for ast::Expr<'_> { impl Eval for ast::Ident<'_> { type Output = Value; - #[tracing::instrument(name = "Ident::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { vm.scopes.get(&self).cloned().at(self.span()) } @@ -149,7 +147,6 @@ impl Eval for ast::Ident<'_> { impl Eval for ast::None<'_> { type Output = Value; - #[tracing::instrument(name = "None::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(Value::None) } @@ -158,7 +155,6 @@ impl Eval for ast::None<'_> { impl Eval for ast::Auto<'_> { type Output = Value; - #[tracing::instrument(name = "Auto::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(Value::Auto) } @@ -167,7 +163,6 @@ impl Eval for ast::Auto<'_> { impl Eval for ast::Bool<'_> { type Output = Value; - #[tracing::instrument(name = "Bool::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(Value::Bool(self.get())) } @@ -176,7 +171,6 @@ impl Eval for ast::Bool<'_> { impl Eval for ast::Int<'_> { type Output = Value; - #[tracing::instrument(name = "Int::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(Value::Int(self.get())) } @@ -185,7 +179,6 @@ impl Eval for ast::Int<'_> { impl Eval for ast::Float<'_> { type Output = Value; - #[tracing::instrument(name = "Float::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(Value::Float(self.get())) } @@ -194,7 +187,6 @@ impl Eval for ast::Float<'_> { impl Eval for ast::Numeric<'_> { type Output = Value; - #[tracing::instrument(name = "Numeric::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(Value::numeric(self.get())) } @@ -203,7 +195,6 @@ impl Eval for ast::Numeric<'_> { impl Eval for ast::Str<'_> { type Output = Value; - #[tracing::instrument(name = "Str::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(Value::Str(self.get().into())) } @@ -212,7 +203,6 @@ impl Eval for ast::Str<'_> { impl Eval for ast::Array<'_> { type Output = Array; - #[tracing::instrument(skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let items = self.items(); @@ -235,7 +225,6 @@ impl Eval for ast::Array<'_> { impl Eval for ast::Dict<'_> { type Output = Dict; - #[tracing::instrument(skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let mut map = indexmap::IndexMap::new(); @@ -275,7 +264,6 @@ impl Eval for ast::Dict<'_> { impl Eval for ast::CodeBlock<'_> { type Output = Value; - #[tracing::instrument(name = "CodeBlock::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { vm.scopes.enter(); let output = self.body().eval(vm)?; @@ -287,7 +275,6 @@ impl Eval for ast::CodeBlock<'_> { impl Eval for ast::ContentBlock<'_> { type Output = Content; - #[tracing::instrument(name = "ContentBlock::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { vm.scopes.enter(); let content = self.body().eval(vm)?; @@ -299,7 +286,6 @@ impl Eval for ast::ContentBlock<'_> { impl Eval for ast::Parenthesized<'_> { type Output = Value; - #[tracing::instrument(name = "Parenthesized::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { self.expr().eval(vm) } @@ -308,7 +294,6 @@ impl Eval for ast::Parenthesized<'_> { impl Eval for ast::FieldAccess<'_> { type Output = Value; - #[tracing::instrument(name = "FieldAccess::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let value = self.target().eval(vm)?; let field = self.field(); diff --git a/crates/typst/src/eval/flow.rs b/crates/typst/src/eval/flow.rs index ff1f1c8c1..720b8bcdd 100644 --- a/crates/typst/src/eval/flow.rs +++ b/crates/typst/src/eval/flow.rs @@ -41,7 +41,6 @@ impl FlowEvent { impl Eval for ast::Conditional<'_> { type Output = Value; - #[tracing::instrument(name = "Conditional::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let condition = self.condition(); if condition.eval(vm)?.cast::().at(condition.span())? { @@ -57,7 +56,7 @@ impl Eval for ast::Conditional<'_> { impl Eval for ast::WhileLoop<'_> { type Output = Value; - #[tracing::instrument(name = "WhileLoop::eval", skip_all)] + #[typst_macros::time(name = "while loop", span = self.span())] fn eval(self, vm: &mut Vm) -> SourceResult { let flow = vm.flow.take(); let mut output = Value::None; @@ -103,7 +102,7 @@ impl Eval for ast::WhileLoop<'_> { impl Eval for ast::ForLoop<'_> { type Output = Value; - #[tracing::instrument(name = "ForLoop::eval", skip_all)] + #[typst_macros::time(name = "for loop", span = self.span())] fn eval(self, vm: &mut Vm) -> SourceResult { let flow = vm.flow.take(); let mut output = Value::None; @@ -170,7 +169,6 @@ impl Eval for ast::ForLoop<'_> { impl Eval for ast::LoopBreak<'_> { type Output = Value; - #[tracing::instrument(name = "LoopBreak::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { if vm.flow.is_none() { vm.flow = Some(FlowEvent::Break(self.span())); @@ -182,7 +180,6 @@ impl Eval for ast::LoopBreak<'_> { impl Eval for ast::LoopContinue<'_> { type Output = Value; - #[tracing::instrument(name = "LoopContinue::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { if vm.flow.is_none() { vm.flow = Some(FlowEvent::Continue(self.span())); @@ -194,7 +191,6 @@ impl Eval for ast::LoopContinue<'_> { impl Eval for ast::FuncReturn<'_> { type Output = Value; - #[tracing::instrument(name = "FuncReturn::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let value = self.body().map(|body| body.eval(vm)).transpose()?; if vm.flow.is_none() { diff --git a/crates/typst/src/eval/import.rs b/crates/typst/src/eval/import.rs index aa3388a10..63bb469c3 100644 --- a/crates/typst/src/eval/import.rs +++ b/crates/typst/src/eval/import.rs @@ -14,7 +14,6 @@ use crate::World; impl Eval for ast::ModuleImport<'_> { type Output = Value; - #[tracing::instrument(name = "ModuleImport::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let source = self.source(); let source_span = source.span(); @@ -98,7 +97,6 @@ impl Eval for ast::ModuleImport<'_> { impl Eval for ast::ModuleInclude<'_> { type Output = Content; - #[tracing::instrument(name = "ModuleInclude::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let span = self.source().span(); let source = self.source().eval(vm)?; diff --git a/crates/typst/src/eval/markup.rs b/crates/typst/src/eval/markup.rs index ad9cd9c15..aefb34367 100644 --- a/crates/typst/src/eval/markup.rs +++ b/crates/typst/src/eval/markup.rs @@ -72,7 +72,6 @@ fn eval_markup<'a>( impl Eval for ast::Text<'_> { type Output = Content; - #[tracing::instrument(name = "Text::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(TextElem::packed(self.get().clone())) } @@ -81,7 +80,6 @@ impl Eval for ast::Text<'_> { impl Eval for ast::Space<'_> { type Output = Content; - #[tracing::instrument(name = "Space::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(SpaceElem::new().pack()) } @@ -90,7 +88,6 @@ impl Eval for ast::Space<'_> { impl Eval for ast::Linebreak<'_> { type Output = Content; - #[tracing::instrument(name = "Linebreak::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(LinebreakElem::new().pack()) } @@ -99,7 +96,6 @@ impl Eval for ast::Linebreak<'_> { impl Eval for ast::Parbreak<'_> { type Output = Content; - #[tracing::instrument(name = "Parbreak::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(ParbreakElem::new().pack()) } @@ -108,7 +104,6 @@ impl Eval for ast::Parbreak<'_> { impl Eval for ast::Escape<'_> { type Output = Value; - #[tracing::instrument(name = "Escape::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(Value::Symbol(Symbol::single(self.get()))) } @@ -117,7 +112,6 @@ impl Eval for ast::Escape<'_> { impl Eval for ast::Shorthand<'_> { type Output = Value; - #[tracing::instrument(name = "Shorthand::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(Value::Symbol(Symbol::single(self.get()))) } @@ -126,7 +120,6 @@ impl Eval for ast::Shorthand<'_> { impl Eval for ast::SmartQuote<'_> { type Output = Content; - #[tracing::instrument(name = "SmartQuote::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(SmartQuoteElem::new().with_double(self.double()).pack()) } @@ -135,7 +128,6 @@ impl Eval for ast::SmartQuote<'_> { impl Eval for ast::Strong<'_> { type Output = Content; - #[tracing::instrument(name = "Strong::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let body = self.body(); if body.exprs().next().is_none() { @@ -154,7 +146,6 @@ impl Eval for ast::Strong<'_> { impl Eval for ast::Emph<'_> { type Output = Content; - #[tracing::instrument(name = "Emph::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let body = self.body(); if body.exprs().next().is_none() { @@ -173,7 +164,6 @@ impl Eval for ast::Emph<'_> { impl Eval for ast::Raw<'_> { type Output = Content; - #[tracing::instrument(name = "Raw::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { let mut elem = RawElem::new(self.text()).with_block(self.block()); if let Some(lang) = self.lang() { @@ -186,7 +176,6 @@ impl Eval for ast::Raw<'_> { impl Eval for ast::Link<'_> { type Output = Content; - #[tracing::instrument(name = "Link::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(LinkElem::from_url(self.get().clone()).pack()) } @@ -195,7 +184,6 @@ impl Eval for ast::Link<'_> { impl Eval for ast::Label<'_> { type Output = Value; - #[tracing::instrument(name = "Label::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(Value::Label(Label::new(self.get()))) } @@ -204,7 +192,6 @@ impl Eval for ast::Label<'_> { impl Eval for ast::Ref<'_> { type Output = Content; - #[tracing::instrument(name = "Ref::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let target = Label::new(self.target()); let mut elem = RefElem::new(target); @@ -220,7 +207,6 @@ impl Eval for ast::Ref<'_> { impl Eval for ast::Heading<'_> { type Output = Content; - #[tracing::instrument(name = "Heading::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let level = self.level(); let body = self.body().eval(vm)?; @@ -231,7 +217,6 @@ impl Eval for ast::Heading<'_> { impl Eval for ast::ListItem<'_> { type Output = Content; - #[tracing::instrument(name = "ListItem::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { Ok(ListItem::new(self.body().eval(vm)?).pack()) } @@ -240,7 +225,6 @@ impl Eval for ast::ListItem<'_> { impl Eval for ast::EnumItem<'_> { type Output = Content; - #[tracing::instrument(name = "EnumItem::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let body = self.body().eval(vm)?; let mut elem = EnumItem::new(body); @@ -254,7 +238,6 @@ impl Eval for ast::EnumItem<'_> { impl Eval for ast::TermItem<'_> { type Output = Content; - #[tracing::instrument(name = "TermItem::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let term = self.term().eval(vm)?; let description = self.description().eval(vm)?; @@ -265,7 +248,6 @@ impl Eval for ast::TermItem<'_> { impl Eval for ast::Equation<'_> { type Output = Content; - #[tracing::instrument(name = "Equation::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let body = self.body().eval(vm)?; let block = self.block(); diff --git a/crates/typst/src/eval/math.rs b/crates/typst/src/eval/math.rs index 2e9a7eadc..62314fc23 100644 --- a/crates/typst/src/eval/math.rs +++ b/crates/typst/src/eval/math.rs @@ -9,8 +9,6 @@ use crate::text::TextElem; impl Eval for ast::Math<'_> { type Output = Content; - - #[tracing::instrument(name = "Math::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { Ok(Content::sequence( self.exprs() @@ -23,7 +21,6 @@ impl Eval for ast::Math<'_> { impl Eval for ast::MathIdent<'_> { type Output = Value; - #[tracing::instrument(name = "MathIdent::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { vm.scopes.get_in_math(&self).cloned().at(self.span()) } @@ -32,7 +29,6 @@ impl Eval for ast::MathIdent<'_> { impl Eval for ast::MathAlignPoint<'_> { type Output = Content; - #[tracing::instrument(name = "MathAlignPoint::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(AlignPointElem::new().pack()) } @@ -41,7 +37,6 @@ impl Eval for ast::MathAlignPoint<'_> { impl Eval for ast::MathDelimited<'_> { type Output = Content; - #[tracing::instrument(name = "MathDelimited::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let open = self.open().eval_display(vm)?; let body = self.body().eval(vm)?; @@ -53,7 +48,6 @@ impl Eval for ast::MathDelimited<'_> { impl Eval for ast::MathAttach<'_> { type Output = Content; - #[tracing::instrument(name = "MathAttach::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let base = self.base().eval_display(vm)?; let mut elem = AttachElem::new(base); @@ -75,7 +69,6 @@ impl Eval for ast::MathAttach<'_> { impl Eval for ast::MathPrimes<'_> { type Output = Content; - #[tracing::instrument(name = "MathPrimes::eval", skip_all)] fn eval(self, _: &mut Vm) -> SourceResult { Ok(PrimesElem::new(self.count()).pack()) } @@ -84,7 +77,6 @@ impl Eval for ast::MathPrimes<'_> { impl Eval for ast::MathFrac<'_> { type Output = Content; - #[tracing::instrument(name = "MathFrac::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let num = self.num().eval_display(vm)?; let denom = self.denom().eval_display(vm)?; diff --git a/crates/typst/src/eval/mod.rs b/crates/typst/src/eval/mod.rs index d16f32047..2a17cf348 100644 --- a/crates/typst/src/eval/mod.rs +++ b/crates/typst/src/eval/mod.rs @@ -35,7 +35,7 @@ use crate::World; /// Evaluate a source file and return the resulting module. #[comemo::memoize] -#[tracing::instrument(skip_all)] +#[typst_macros::time(name = "eval", span = source.root().span())] pub fn eval( world: Tracked, route: Tracked, diff --git a/crates/typst/src/eval/ops.rs b/crates/typst/src/eval/ops.rs index 8e8b6d293..b4803ab4b 100644 --- a/crates/typst/src/eval/ops.rs +++ b/crates/typst/src/eval/ops.rs @@ -16,7 +16,6 @@ use crate::visualize::Stroke; impl Eval for ast::Unary<'_> { type Output = Value; - #[tracing::instrument(name = "Unary::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { let value = self.expr().eval(vm)?; let result = match self.op() { @@ -31,7 +30,6 @@ impl Eval for ast::Unary<'_> { impl Eval for ast::Binary<'_> { type Output = Value; - #[tracing::instrument(name = "Binary::eval", skip_all)] fn eval(self, vm: &mut Vm) -> SourceResult { match self.op() { ast::BinOp::Add => apply_binary(self, vm, add), diff --git a/crates/typst/src/eval/vm.rs b/crates/typst/src/eval/vm.rs index 8cedb906b..29deaf09a 100644 --- a/crates/typst/src/eval/vm.rs +++ b/crates/typst/src/eval/vm.rs @@ -35,7 +35,6 @@ impl<'a> Vm<'a> { } /// Define a variable in the current scope. - #[tracing::instrument(skip_all)] pub fn define(&mut self, var: ast::Ident, value: impl IntoValue) { let value = value.into_value(); if self.inspected == Some(var.span()) { diff --git a/crates/typst/src/foundations/content.rs b/crates/typst/src/foundations/content.rs index 56813f23a..9e7457ea7 100644 --- a/crates/typst/src/foundations/content.rs +++ b/crates/typst/src/foundations/content.rs @@ -350,7 +350,6 @@ impl Content { /// Queries the content tree for all elements that match the given selector. /// /// Elements produced in `show` rules will not be included in the results. - #[tracing::instrument(skip_all)] pub fn query(&self, selector: Selector) -> Vec { let mut results = Vec::new(); self.traverse(&mut |element| { @@ -365,7 +364,6 @@ impl Content { /// selector. /// /// Elements produced in `show` rules will not be included in the results. - #[tracing::instrument(skip_all)] pub fn query_first(&self, selector: Selector) -> Option { let mut result = None; self.traverse(&mut |element| { diff --git a/crates/typst/src/foundations/func.rs b/crates/typst/src/foundations/func.rs index 6729b39d7..9cfa4d6d0 100644 --- a/crates/typst/src/foundations/func.rs +++ b/crates/typst/src/foundations/func.rs @@ -250,19 +250,13 @@ impl Func { } /// Call the function with the given arguments. - #[tracing::instrument(skip_all)] pub fn call(&self, engine: &mut Engine, args: impl IntoArgs) -> SourceResult { self.call_impl(engine, args.into_args(self.span)) } /// Non-generic implementation of `call`. + #[typst_macros::time(name = "func call", span = self.span())] fn call_impl(&self, engine: &mut Engine, mut args: Args) -> SourceResult { - let _span = tracing::info_span!( - "call", - name = self.name().unwrap_or(""), - file = 0, - ); - match &self.repr { Repr::Native(native) => { let value = (native.function)(engine, &mut args)?; diff --git a/crates/typst/src/foundations/plugin.rs b/crates/typst/src/foundations/plugin.rs index b7e52e72e..898ac6f8c 100644 --- a/crates/typst/src/foundations/plugin.rs +++ b/crates/typst/src/foundations/plugin.rs @@ -167,6 +167,7 @@ impl Plugin { impl Plugin { /// Create a new plugin from raw WebAssembly bytes. #[comemo::memoize] + #[typst_macros::time(name = "load plugin")] pub fn new(bytes: Bytes) -> StrResult { let engine = wasmi::Engine::default(); let module = wasmi::Module::new(&engine, bytes.as_slice()) @@ -216,6 +217,7 @@ impl Plugin { /// Call the plugin function with the given `name`. #[comemo::memoize] + #[typst_macros::time(name = "call plugin")] pub fn call(&self, name: &str, args: Vec) -> StrResult { // Find the function with the given name. let func = self diff --git a/crates/typst/src/foundations/styles.rs b/crates/typst/src/foundations/styles.rs index c85cab413..3fa9e9fbd 100644 --- a/crates/typst/src/foundations/styles.rs +++ b/crates/typst/src/foundations/styles.rs @@ -35,6 +35,8 @@ use crate::text::{FontFamily, FontList, TextElem}; /// ``` #[func] pub fn style( + /// The call site span. + span: Span, /// A function to call with the styles. Its return value is displayed /// in the document. /// @@ -43,7 +45,7 @@ pub fn style( /// content that depends on the style context it appears in. func: Func, ) -> Content { - StyleElem::new(func).pack() + StyleElem::new(func).spanned(span).pack() } /// Executes a style access. @@ -55,7 +57,7 @@ struct StyleElem { } impl Show for StyleElem { - #[tracing::instrument(name = "StyleElem::show", skip_all)] + #[typst_macros::time(name = "style", span = self.span())] fn show(&self, engine: &mut Engine, styles: StyleChain) -> SourceResult { Ok(self.func().call(engine, [styles.to_map()])?.display()) } diff --git a/crates/typst/src/introspection/counter.rs b/crates/typst/src/introspection/counter.rs index 10960a853..0de1ecaed 100644 --- a/crates/typst/src/introspection/counter.rs +++ b/crates/typst/src/introspection/counter.rs @@ -17,6 +17,7 @@ use crate::introspection::{Introspector, Locatable, Location, Locator, Meta}; use crate::layout::{Frame, FrameItem, PageElem}; use crate::math::EquationElem; use crate::model::{FigureElem, HeadingElem, Numbering, NumberingPattern}; +use crate::syntax::Span; use crate::util::NonZeroExt; use crate::World; @@ -350,6 +351,8 @@ impl Counter { #[func] pub fn display( self, + /// The call span of the display. + span: Span, /// A [numbering pattern or a function]($numbering), which specifies how /// to display the counter. If given a function, that function receives /// each number of the counter as a separate argument. If the amount of @@ -369,7 +372,7 @@ impl Counter { #[default(false)] both: bool, ) -> Content { - DisplayElem::new(self, numbering, both).pack() + DisplayElem::new(self, numbering, both).spanned(span).pack() } /// Increases the value of the counter by one. @@ -383,12 +386,14 @@ impl Counter { #[func] pub fn step( self, + /// The call span of the update. + span: Span, /// The depth at which to step the counter. Defaults to `{1}`. #[named] #[default(NonZeroUsize::ONE)] level: NonZeroUsize, ) -> Content { - self.update(CounterUpdate::Step(level)) + self.update(span, CounterUpdate::Step(level)) } /// Updates the value of the counter. @@ -398,13 +403,15 @@ impl Counter { #[func] pub fn update( self, + /// The call span of the update. + span: Span, /// If given an integer or array of integers, sets the counter to that /// value. If given a function, that function receives the previous /// counter value (with each number as a separate argument) and has to /// return the new value (integer or array). update: CounterUpdate, ) -> Content { - UpdateElem::new(self.0, update).pack() + UpdateElem::new(self.0, update).spanned(span).pack() } /// Gets the value of the counter at the given location. Always returns an @@ -630,7 +637,7 @@ struct DisplayElem { } impl Show for DisplayElem { - #[tracing::instrument(name = "DisplayElem::show", skip_all)] + #[typst_macros::time(name = "counter.display", span = self.span())] fn show(&self, engine: &mut Engine, styles: StyleChain) -> SourceResult { Ok(engine.delayed(|engine| { let location = self.location().unwrap(); @@ -679,7 +686,6 @@ struct UpdateElem { } impl Show for UpdateElem { - #[tracing::instrument(name = "UpdateElem::show", skip(self))] fn show(&self, _: &mut Engine, _: StyleChain) -> SourceResult { Ok(Content::empty()) } diff --git a/crates/typst/src/introspection/introspector.rs b/crates/typst/src/introspection/introspector.rs index bbf43472f..9c3e73c60 100644 --- a/crates/typst/src/introspection/introspector.rs +++ b/crates/typst/src/introspection/introspector.rs @@ -37,7 +37,7 @@ pub struct Introspector { impl Introspector { /// Applies new frames in-place, reusing the existing allocations. - #[tracing::instrument(skip_all)] + #[typst_macros::time(name = "introspect")] pub fn rebuild(&mut self, frames: &[Frame]) { self.pages = frames.len(); self.elems.clear(); @@ -52,7 +52,6 @@ impl Introspector { } /// Extract metadata from a frame. - #[tracing::instrument(skip_all)] fn extract(&mut self, frame: &Frame, page: NonZeroUsize, ts: Transform) { for (pos, item) in frame.items() { match item { diff --git a/crates/typst/src/introspection/locate.rs b/crates/typst/src/introspection/locate.rs index 69dcadd8c..4cec04c90 100644 --- a/crates/typst/src/introspection/locate.rs +++ b/crates/typst/src/introspection/locate.rs @@ -2,6 +2,7 @@ use crate::diag::SourceResult; use crate::engine::Engine; use crate::foundations::{elem, func, Content, Func, NativeElement, Show, StyleChain}; use crate::introspection::Locatable; +use crate::syntax::Span; /// Provides access to the location of content. /// @@ -17,6 +18,8 @@ use crate::introspection::Locatable; /// ``` #[func] pub fn locate( + /// The span of the `locate` call. + span: Span, /// A function that receives a [`location`]($location). Its return value is /// displayed in the document. /// @@ -25,7 +28,7 @@ pub fn locate( /// content that depends on its own location in the document. func: Func, ) -> Content { - LocateElem::new(func).pack() + LocateElem::new(func).spanned(span).pack() } /// Executes a `locate` call. @@ -37,7 +40,7 @@ struct LocateElem { } impl Show for LocateElem { - #[tracing::instrument(name = "LocateElem::show", skip(self, engine))] + #[typst_macros::time(name = "locate", span = self.span())] fn show(&self, engine: &mut Engine, _: StyleChain) -> SourceResult { Ok(engine.delayed(|engine| { let location = self.location().unwrap(); diff --git a/crates/typst/src/introspection/state.rs b/crates/typst/src/introspection/state.rs index a1d8d6d05..c1264f1c7 100644 --- a/crates/typst/src/introspection/state.rs +++ b/crates/typst/src/introspection/state.rs @@ -9,6 +9,7 @@ use crate::foundations::{ Selector, Show, Str, StyleChain, Value, }; use crate::introspection::{Introspector, Locatable, Location, Locator}; +use crate::syntax::Span; use crate::World; /// Manages stateful parts of your document. @@ -271,13 +272,15 @@ impl State { #[func] pub fn display( self, + /// The span of the `display` call. + span: Span, /// A function which receives the value of the state and can return /// arbitrary content which is then displayed. If this is omitted, the /// value is directly displayed. #[default] func: Option, ) -> Content { - DisplayElem::new(self, func).pack() + DisplayElem::new(self, func).spanned(span).pack() } /// Update the value of the state. @@ -291,12 +294,14 @@ impl State { #[func] pub fn update( self, + /// The span of the `update` call. + span: Span, /// If given a non function-value, sets the state to that value. If /// given a function, that function receives the previous state and has /// to return the new state. update: StateUpdate, ) -> Content { - UpdateElem::new(self.key, update).pack() + UpdateElem::new(self.key, update).spanned(span).pack() } /// Get the value of the state at the given location. @@ -385,7 +390,7 @@ struct DisplayElem { } impl Show for DisplayElem { - #[tracing::instrument(name = "DisplayElem::show", skip(self, engine))] + #[typst_macros::time(name = "state.display", span = self.span())] fn show(&self, engine: &mut Engine, _: StyleChain) -> SourceResult { Ok(engine.delayed(|engine| { let location = self.location().unwrap(); @@ -411,7 +416,6 @@ struct UpdateElem { } impl Show for UpdateElem { - #[tracing::instrument(name = "UpdateElem::show")] fn show(&self, _: &mut Engine, _: StyleChain) -> SourceResult { Ok(Content::empty()) } diff --git a/crates/typst/src/layout/align.rs b/crates/typst/src/layout/align.rs index 3d4017f3a..d831292b6 100644 --- a/crates/typst/src/layout/align.rs +++ b/crates/typst/src/layout/align.rs @@ -46,7 +46,7 @@ pub struct AlignElem { } impl Show for AlignElem { - #[tracing::instrument(name = "AlignElem::show", skip_all)] + #[typst_macros::time(name = "align", span = self.span())] fn show(&self, _: &mut Engine, styles: StyleChain) -> SourceResult { Ok(self .body() diff --git a/crates/typst/src/layout/columns.rs b/crates/typst/src/layout/columns.rs index 275dbbeb7..4ec8e56eb 100644 --- a/crates/typst/src/layout/columns.rs +++ b/crates/typst/src/layout/columns.rs @@ -58,7 +58,7 @@ pub struct ColumnsElem { } impl Layout for ColumnsElem { - #[tracing::instrument(name = "ColumnsElem::layout", skip_all)] + #[typst_macros::time(name = "columns", span = self.span())] fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/layout/container.rs b/crates/typst/src/layout/container.rs index cdc5c489c..f2d182ae4 100644 --- a/crates/typst/src/layout/container.rs +++ b/crates/typst/src/layout/container.rs @@ -110,7 +110,7 @@ pub struct BoxElem { } impl Layout for BoxElem { - #[tracing::instrument(name = "BoxElem::layout", skip_all)] + #[typst_macros::time(name = "box", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -342,7 +342,7 @@ pub struct BlockElem { } impl Layout for BlockElem { - #[tracing::instrument(name = "BlockElem::layout", skip_all)] + #[typst_macros::time(name = "block", span = self.span())] fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/layout/flow.rs b/crates/typst/src/layout/flow.rs index 8983ccda0..6e678db4b 100644 --- a/crates/typst/src/layout/flow.rs +++ b/crates/typst/src/layout/flow.rs @@ -28,7 +28,7 @@ pub struct FlowElem { } impl Layout for FlowElem { - #[tracing::instrument(name = "FlowElem::layout", skip_all)] + #[typst_macros::time(name = "flow", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -204,7 +204,6 @@ impl<'a> FlowLayouter<'a> { } /// Layout vertical spacing. - #[tracing::instrument(name = "FlowLayouter::layout_spacing", skip_all)] fn layout_spacing( &mut self, engine: &mut Engine, @@ -224,7 +223,6 @@ impl<'a> FlowLayouter<'a> { } /// Layout a paragraph. - #[tracing::instrument(name = "FlowLayouter::layout_par", skip_all)] fn layout_par( &mut self, engine: &mut Engine, @@ -279,7 +277,6 @@ impl<'a> FlowLayouter<'a> { } /// Layout into a single region. - #[tracing::instrument(name = "FlowLayouter::layout_single", skip_all)] fn layout_single( &mut self, engine: &mut Engine, @@ -377,7 +374,6 @@ impl<'a> FlowLayouter<'a> { } /// Layout a finished frame. - #[tracing::instrument(name = "FlowLayouter::layout_item", skip_all)] fn layout_item( &mut self, engine: &mut Engine, @@ -645,7 +641,6 @@ impl FlowLayouter<'_> { } /// Processes all footnotes in the frame. - #[tracing::instrument(skip_all)] fn handle_footnotes( &mut self, engine: &mut Engine, @@ -722,7 +717,6 @@ impl FlowLayouter<'_> { } /// Layout and save the footnote separator, typically a line. - #[tracing::instrument(skip_all)] fn layout_footnote_separator(&mut self, engine: &mut Engine) -> SourceResult<()> { let expand = Axes::new(self.regions.expand.x, false); let pod = Regions::one(self.regions.base(), expand); @@ -741,7 +735,6 @@ impl FlowLayouter<'_> { } /// Finds all footnotes in the frame. -#[tracing::instrument(skip_all)] fn find_footnotes(notes: &mut Vec, frame: &Frame) { for (_, item) in frame.items() { match item { diff --git a/crates/typst/src/layout/grid.rs b/crates/typst/src/layout/grid.rs index bbe2ea21d..56f8190ba 100644 --- a/crates/typst/src/layout/grid.rs +++ b/crates/typst/src/layout/grid.rs @@ -203,7 +203,7 @@ pub struct GridElem { } impl Layout for GridElem { - #[tracing::instrument(name = "GridElem::layout", skip_all)] + #[typst_macros::time(name = "grid", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -589,7 +589,6 @@ impl<'a> GridLayouter<'a> { } /// Determine all column sizes. - #[tracing::instrument(name = "GridLayouter::measure_columns", skip_all)] fn measure_columns(&mut self, engine: &mut Engine) -> SourceResult<()> { // Sum of sizes of resolved relative tracks. let mut rel = Abs::zero(); diff --git a/crates/typst/src/layout/hide.rs b/crates/typst/src/layout/hide.rs index 50ce84670..1b8b0efd8 100644 --- a/crates/typst/src/layout/hide.rs +++ b/crates/typst/src/layout/hide.rs @@ -25,7 +25,7 @@ pub struct HideElem { } impl Show for HideElem { - #[tracing::instrument(name = "HideElem::show", skip(self))] + #[typst_macros::time(name = "hide", span = self.span())] fn show(&self, _: &mut Engine, _: StyleChain) -> SourceResult { Ok(self.body().clone().styled(MetaElem::set_data(smallvec![Meta::Hide]))) } diff --git a/crates/typst/src/layout/layout.rs b/crates/typst/src/layout/layout.rs index 45b7c54a9..126fe0677 100644 --- a/crates/typst/src/layout/layout.rs +++ b/crates/typst/src/layout/layout.rs @@ -2,6 +2,7 @@ use crate::diag::SourceResult; use crate::engine::Engine; use crate::foundations::{dict, elem, func, Content, Func, NativeElement, StyleChain}; use crate::layout::{Fragment, Layout, Regions, Size}; +use crate::syntax::Span; /// Provides access to the current outer container's (or page's, if none) size /// (width and height). @@ -43,6 +44,8 @@ use crate::layout::{Fragment, Layout, Regions, Size}; /// the page width or height is `auto`, respectively. #[func] pub fn layout( + /// The call span of this function. + span: Span, /// A function to call with the outer container's size. Its return value is /// displayed in the document. /// @@ -54,7 +57,7 @@ pub fn layout( /// content that depends on the size of the container it is inside of. func: Func, ) -> Content { - LayoutElem::new(func).pack() + LayoutElem::new(func).spanned(span).pack() } /// Executes a `layout` call. @@ -66,7 +69,7 @@ struct LayoutElem { } impl Layout for LayoutElem { - #[tracing::instrument(name = "LayoutElem::layout", skip_all)] + #[typst_macros::time(name = "layout", span = self.span())] fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/layout/mod.rs b/crates/typst/src/layout/mod.rs index 1af118566..d37e605e6 100644 --- a/crates/typst/src/layout/mod.rs +++ b/crates/typst/src/layout/mod.rs @@ -142,7 +142,6 @@ pub trait Layout { /// /// This element must be layouted again in the same order for the results to /// be valid. - #[tracing::instrument(name = "Layout::measure", skip_all)] fn measure( &self, engine: &mut Engine, @@ -162,7 +161,7 @@ pub trait Layout { } impl LayoutRoot for Content { - #[tracing::instrument(name = "Content::layout_root", skip_all)] + #[typst_macros::time(name = "layout root", span = self.span())] fn layout_root( &self, engine: &mut Engine, @@ -195,7 +194,6 @@ impl LayoutRoot for Content { .layout_root(&mut engine, styles) } - tracing::info!("Starting layout"); cached( self, engine.world, @@ -209,7 +207,6 @@ impl LayoutRoot for Content { } impl Layout for Content { - #[tracing::instrument(name = "Content::layout", skip_all)] fn layout( &self, engine: &mut Engine, @@ -253,8 +250,6 @@ impl Layout for Content { .layout(&mut engine, styles, regions) } - tracing::info!("Layouting `Content`"); - let fragment = cached( self, engine.world, diff --git a/crates/typst/src/layout/pad.rs b/crates/typst/src/layout/pad.rs index 35dfd0b46..0a880b3b7 100644 --- a/crates/typst/src/layout/pad.rs +++ b/crates/typst/src/layout/pad.rs @@ -59,7 +59,7 @@ pub struct PadElem { } impl Layout for PadElem { - #[tracing::instrument(name = "PadElem::layout", skip_all)] + #[typst_macros::time(name = "pad", span = self.span())] fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/layout/page.rs b/crates/typst/src/layout/page.rs index 96e6d96a7..888e63efb 100644 --- a/crates/typst/src/layout/page.rs +++ b/crates/typst/src/layout/page.rs @@ -340,7 +340,7 @@ impl PageElem { /// while we post-process the pages in this function. This function returns /// a fragment consisting of multiple frames, one per output page of this /// page run. - #[tracing::instrument(skip_all)] + #[typst_macros::time(name = "page", span = self.span())] pub fn layout( &self, engine: &mut Engine, @@ -348,8 +348,6 @@ impl PageElem { page_counter: &mut ManualPageCounter, extend_to: Option, ) -> SourceResult { - tracing::info!("Page layout"); - // When one of the lengths is infinite the page fits its content along // that axis. let width = self.width(styles).unwrap_or(Abs::inf()); @@ -386,7 +384,10 @@ impl PageElem { let mut child = self.body().clone(); let columns = self.columns(styles); if columns.get() > 1 { - child = ColumnsElem::new(child).with_count(columns).pack(); + child = ColumnsElem::new(child) + .spanned(self.span()) + .with_count(columns) + .pack(); } let area = size - margin.sum_by_axis(); @@ -424,8 +425,11 @@ impl PageElem { Numbering::Func(_) => true, }; - let mut counter = - Counter::new(CounterKey::Page).display(Some(numbering.clone()), both); + let mut counter = Counter::new(CounterKey::Page).display( + self.span(), + Some(numbering.clone()), + both, + ); // We interpret the Y alignment as selecting header or footer // and then ignore it for aligning the actual number. @@ -444,8 +448,6 @@ impl PageElem { // Post-process pages. for frame in frames.iter_mut() { - tracing::info!("Layouting page #{}", page_counter.physical()); - // The padded width of the page's content without margins. let pw = frame.width(); @@ -466,14 +468,7 @@ impl PageElem { let size = frame.size(); // Realize overlays. - for (name, marginal) in [ - ("header", &header), - ("footer", &footer), - ("background", &background), - ("foreground", &foreground), - ] { - tracing::info!("Layouting {name}"); - + for marginal in [&header, &footer, &background, &foreground] { let Some(content) = &**marginal else { continue }; let (pos, area, align); diff --git a/crates/typst/src/layout/place.rs b/crates/typst/src/layout/place.rs index 3c0012aac..b06bffa71 100644 --- a/crates/typst/src/layout/place.rs +++ b/crates/typst/src/layout/place.rs @@ -87,7 +87,7 @@ pub struct PlaceElem { } impl Layout for PlaceElem { - #[tracing::instrument(name = "PlaceElem::layout", skip_all)] + #[typst_macros::time(name = "place", span = self.span())] fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/layout/repeat.rs b/crates/typst/src/layout/repeat.rs index c733ea7d1..f30185731 100644 --- a/crates/typst/src/layout/repeat.rs +++ b/crates/typst/src/layout/repeat.rs @@ -35,7 +35,7 @@ pub struct RepeatElem { } impl Layout for RepeatElem { - #[tracing::instrument(name = "RepeatElem::layout", skip_all)] + #[typst_macros::time(name = "repeat", span = self.span())] fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/layout/stack.rs b/crates/typst/src/layout/stack.rs index fe36cc63d..be97e667d 100644 --- a/crates/typst/src/layout/stack.rs +++ b/crates/typst/src/layout/stack.rs @@ -52,7 +52,7 @@ pub struct StackElem { } impl Layout for StackElem { - #[tracing::instrument(name = "StackElem::layout", skip_all)] + #[typst_macros::time(name = "stack", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -173,7 +173,6 @@ impl<'a> StackLayouter<'a> { } /// Add spacing along the spacing direction. - #[tracing::instrument(name = "StackLayouter::layout_spacing", skip_all)] fn layout_spacing(&mut self, spacing: Spacing) { match spacing { Spacing::Rel(v) => { @@ -197,7 +196,6 @@ impl<'a> StackLayouter<'a> { } /// Layout an arbitrary block. - #[tracing::instrument(name = "StackLayouter::layout_block", skip_all)] fn layout_block( &mut self, engine: &mut Engine, diff --git a/crates/typst/src/layout/transform.rs b/crates/typst/src/layout/transform.rs index 92cba120c..4d2878a93 100644 --- a/crates/typst/src/layout/transform.rs +++ b/crates/typst/src/layout/transform.rs @@ -38,7 +38,7 @@ pub struct MoveElem { } impl Layout for MoveElem { - #[tracing::instrument(name = "MoveElem::layout", skip_all)] + #[typst_macros::time(name = "move", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -116,7 +116,7 @@ pub struct RotateElem { } impl Layout for RotateElem { - #[tracing::instrument(name = "RotateElem::layout", skip_all)] + #[typst_macros::time(name = "rotate", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -204,7 +204,7 @@ pub struct ScaleElem { } impl Layout for ScaleElem { - #[tracing::instrument(name = "ScaleElem::layout", skip_all)] + #[typst_macros::time(name = "scale", span = self.span())] fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/lib.rs b/crates/typst/src/lib.rs index ffe550408..447b8b449 100644 --- a/crates/typst/src/lib.rs +++ b/crates/typst/src/lib.rs @@ -61,6 +61,7 @@ use std::ops::Range; use comemo::{Prehashed, Track, Tracked, Validate}; use ecow::{EcoString, EcoVec}; +use typst_timing::{timed, TimingScope}; use crate::diag::{warning, FileResult, SourceDiagnostic, SourceResult}; use crate::engine::{Engine, Route}; @@ -83,7 +84,7 @@ use crate::visualize::Color; /// Requires a mutable reference to a tracer. Such a tracer can be created with /// `Tracer::new()`. Independently of whether compilation succeeded, calling /// `tracer.warnings()` after compilation will return all compiler warnings. -#[tracing::instrument(skip_all)] +#[typst_macros::time(name = "compile")] pub fn compile(world: &dyn World, tracer: &mut Tracer) -> SourceResult { // Call `track` on the world just once to keep comemo's ID stable. let world = world.track(); @@ -107,6 +108,10 @@ fn typeset( tracer: &mut Tracer, content: &Content, ) -> SourceResult { + // The name of the iterations for timing scopes. + const ITER_NAMES: &[&str] = + &["typeset (1)", "typeset (2)", "typeset (3)", "typeset (4)", "typeset (5)"]; + let library = world.library(); let styles = StyleChain::new(&library.styles); @@ -116,7 +121,7 @@ fn typeset( // Relayout until all introspections stabilize. // If that doesn't happen within five attempts, we give up. loop { - tracing::info!("Layout iteration {iter}"); + let _scope = TimingScope::new(ITER_NAMES[iter], None); // Clear delayed errors. tracer.delayed(); @@ -136,7 +141,7 @@ fn typeset( document.introspector.rebuild(&document.pages); iter += 1; - if document.introspector.validate(&constraint) { + if timed!("check stabilized", document.introspector.validate(&constraint)) { break; } @@ -290,7 +295,6 @@ impl LibraryBuilder { } /// Construct the module with global definitions. -#[tracing::instrument(skip_all)] fn global(math: Module, inputs: Dict) -> Module { let mut global = Scope::deduplicating(); self::foundations::define(&mut global, inputs); diff --git a/crates/typst/src/math/accent.rs b/crates/typst/src/math/accent.rs index ba0307787..9ebbfc349 100644 --- a/crates/typst/src/math/accent.rs +++ b/crates/typst/src/math/accent.rs @@ -62,7 +62,7 @@ pub struct AccentElem { } impl LayoutMath for AccentElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.accent", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { ctx.style(ctx.style.with_cramped(true)); let base = ctx.layout_fragment(self.base())?; diff --git a/crates/typst/src/math/align.rs b/crates/typst/src/math/align.rs index 5147134e5..41f043b42 100644 --- a/crates/typst/src/math/align.rs +++ b/crates/typst/src/math/align.rs @@ -8,7 +8,6 @@ use crate::math::{LayoutMath, MathContext, MathFragment, MathRow}; pub struct AlignPointElem {} impl LayoutMath for AlignPointElem { - #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { ctx.push(MathFragment::Align); Ok(()) diff --git a/crates/typst/src/math/attach.rs b/crates/typst/src/math/attach.rs index b641c878d..67f77001c 100644 --- a/crates/typst/src/math/attach.rs +++ b/crates/typst/src/math/attach.rs @@ -49,7 +49,7 @@ pub struct AttachElem { } impl LayoutMath for AttachElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.attach", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { type GetAttachment = fn(&AttachElem, styles: StyleChain) -> Option; let layout_attachment = |ctx: &mut MathContext, getter: GetAttachment| { @@ -97,7 +97,7 @@ pub struct PrimesElem { } impl LayoutMath for PrimesElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.primes", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { match *self.count() { count @ 1..=4 => { @@ -143,7 +143,7 @@ pub struct ScriptsElem { } impl LayoutMath for ScriptsElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.scripts", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let mut fragment = ctx.layout_fragment(self.body())?; fragment.set_limits(Limits::Never); @@ -172,7 +172,7 @@ pub struct LimitsElem { } impl LayoutMath for LimitsElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.limits", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let mut fragment = ctx.layout_fragment(self.body())?; fragment.set_limits(if self.inline(ctx.styles()) { diff --git a/crates/typst/src/math/cancel.rs b/crates/typst/src/math/cancel.rs index 6d3026b80..bf1e6d758 100644 --- a/crates/typst/src/math/cancel.rs +++ b/crates/typst/src/math/cancel.rs @@ -106,6 +106,7 @@ pub struct CancelElem { } impl LayoutMath for CancelElem { + #[typst_macros::time(name = "math.cancel", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let body = ctx.layout_fragment(self.body())?; // Use the same math class as the body, in order to preserve automatic spacing around it. diff --git a/crates/typst/src/math/class.rs b/crates/typst/src/math/class.rs index 88424eedc..1b229fce5 100644 --- a/crates/typst/src/math/class.rs +++ b/crates/typst/src/math/class.rs @@ -30,6 +30,7 @@ pub struct ClassElem { } impl LayoutMath for ClassElem { + #[typst_macros::time(name = "math.class", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { ctx.style(ctx.style.with_class(*self.class())); let mut fragment = ctx.layout_fragment(self.body())?; diff --git a/crates/typst/src/math/equation.rs b/crates/typst/src/math/equation.rs index 18ad7bcba..dee7fef34 100644 --- a/crates/typst/src/math/equation.rs +++ b/crates/typst/src/math/equation.rs @@ -112,11 +112,11 @@ impl Synthesize for EquationElem { } impl Show for EquationElem { - #[tracing::instrument(name = "EquationElem::show", skip_all)] + #[typst_macros::time(name = "math.equation", span = self.span())] fn show(&self, _: &mut Engine, styles: StyleChain) -> SourceResult { let mut realized = self.clone().pack().guarded(Guard::Base(Self::elem())); if self.block(styles) { - realized = AlignElem::new(realized).pack(); + realized = AlignElem::new(realized).spanned(self.span()).pack(); } Ok(realized) } @@ -137,7 +137,7 @@ impl Finalize for EquationElem { } impl Layout for EquationElem { - #[tracing::instrument(name = "EquationElem::layout", skip_all)] + #[typst_macros::time(name = "math.equation", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -167,7 +167,7 @@ impl Layout for EquationElem { if let Some(numbering) = self.numbering(styles) { let pod = Regions::one(regions.base(), Axes::splat(false)); let counter = Counter::of(Self::elem()) - .display(Some(numbering), false) + .display(self.span(), Some(numbering), false) .layout(engine, styles, pod)? .into_frame(); @@ -311,7 +311,7 @@ impl Outlinable for EquationElem { } impl LayoutMath for EquationElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.equation", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { self.body().layout_math(ctx) } diff --git a/crates/typst/src/math/frac.rs b/crates/typst/src/math/frac.rs index 442cc18e4..4d0e5dc7d 100644 --- a/crates/typst/src/math/frac.rs +++ b/crates/typst/src/math/frac.rs @@ -36,7 +36,7 @@ pub struct FracElem { } impl LayoutMath for FracElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.frac", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout(ctx, self.num(), std::slice::from_ref(self.denom()), false, self.span()) } @@ -70,6 +70,7 @@ pub struct BinomElem { } impl LayoutMath for BinomElem { + #[typst_macros::time(name = "math.binom", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout(ctx, self.upper(), self.lower(), true, self.span()) } diff --git a/crates/typst/src/math/lr.rs b/crates/typst/src/math/lr.rs index c6b3c9944..35012050f 100644 --- a/crates/typst/src/math/lr.rs +++ b/crates/typst/src/math/lr.rs @@ -34,7 +34,7 @@ pub struct LrElem { } impl LayoutMath for LrElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.lr", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let mut body = self.body(); if let Some(elem) = body.to::() { @@ -96,7 +96,7 @@ pub struct MidElem { } impl LayoutMath for MidElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.mid", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let mut fragments = ctx.layout_fragments(self.body())?; @@ -235,11 +235,13 @@ fn delimited( right: char, size: Option>>, ) -> Content { + let span = body.span(); let mut elem = LrElem::new(Content::sequence([ TextElem::packed(left), body, TextElem::packed(right), - ])); + ])) + .spanned(span); // Push size only if size is provided if let Some(size) = size { elem.push_size(size); diff --git a/crates/typst/src/math/matrix.rs b/crates/typst/src/math/matrix.rs index 35a9ce552..fe0a188c2 100644 --- a/crates/typst/src/math/matrix.rs +++ b/crates/typst/src/math/matrix.rs @@ -58,7 +58,7 @@ pub struct VecElem { } impl LayoutMath for VecElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.vec", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let delim = self.delim(ctx.styles()); let frame = layout_vec_body( @@ -211,7 +211,7 @@ pub struct MatElem { } impl LayoutMath for MatElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.mat", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { // validate inputs @@ -312,7 +312,7 @@ pub struct CasesElem { } impl LayoutMath for CasesElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.cases", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let delim = self.delim(ctx.styles()); let frame = layout_vec_body( diff --git a/crates/typst/src/math/mod.rs b/crates/typst/src/math/mod.rs index 46449ec8d..596c86cc9 100644 --- a/crates/typst/src/math/mod.rs +++ b/crates/typst/src/math/mod.rs @@ -218,7 +218,7 @@ pub trait LayoutMath { } impl LayoutMath for Content { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { // Directly layout the body of nested equations instead of handling it // like a normal equation so that things like this work: diff --git a/crates/typst/src/math/op.rs b/crates/typst/src/math/op.rs index 2670e26d4..bf455903f 100644 --- a/crates/typst/src/math/op.rs +++ b/crates/typst/src/math/op.rs @@ -34,7 +34,7 @@ pub struct OpElem { } impl LayoutMath for OpElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.op", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let fragment = ctx.layout_fragment(self.text())?; ctx.push( diff --git a/crates/typst/src/math/root.rs b/crates/typst/src/math/root.rs index 68df6b24e..9a162b60e 100644 --- a/crates/typst/src/math/root.rs +++ b/crates/typst/src/math/root.rs @@ -15,10 +15,12 @@ use crate::visualize::{FixedStroke, Geometry}; /// ``` #[func(title = "Square Root")] pub fn sqrt( + /// The call span of this function. + span: Span, /// The expression to take the square root of. radicand: Content, ) -> Content { - RootElem::new(radicand).pack() + RootElem::new(radicand).spanned(span).pack() } /// A general root. @@ -38,7 +40,7 @@ pub struct RootElem { } impl LayoutMath for RootElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.root", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout(ctx, self.index(ctx.styles()).as_ref(), self.radicand(), self.span()) } diff --git a/crates/typst/src/math/style.rs b/crates/typst/src/math/style.rs index 631fe967f..00c7bef0b 100644 --- a/crates/typst/src/math/style.rs +++ b/crates/typst/src/math/style.rs @@ -3,6 +3,7 @@ use unicode_math_class::MathClass; use crate::diag::SourceResult; use crate::foundations::{elem, func, Cast, Content, NativeElement, Smart, StyleChain}; use crate::math::{LayoutMath, MathContext}; +use crate::syntax::Span; /// Bold font style in math. /// @@ -11,10 +12,12 @@ use crate::math::{LayoutMath, MathContext}; /// ``` #[func] pub fn bold( + /// The call span of this function. + span: Span, /// The content to style. body: Content, ) -> Content { - MathStyleElem::new(body).with_bold(Some(true)).pack() + MathStyleElem::new(body).spanned(span).with_bold(Some(true)).pack() } /// Upright (non-italic) font style in math. @@ -24,10 +27,12 @@ pub fn bold( /// ``` #[func] pub fn upright( + /// The call span of this function. + span: Span, /// The content to style. body: Content, ) -> Content { - MathStyleElem::new(body).with_italic(Some(false)).pack() + MathStyleElem::new(body).spanned(span).with_italic(Some(false)).pack() } /// Italic font style in math. @@ -35,20 +40,27 @@ pub fn upright( /// For roman letters and greek lowercase letters, this is already the default. #[func] pub fn italic( + /// The call span of this function. + span: Span, /// The content to style. body: Content, ) -> Content { - MathStyleElem::new(body).with_italic(Some(true)).pack() + MathStyleElem::new(body).spanned(span).with_italic(Some(true)).pack() } /// Serif (roman) font style in math. /// /// This is already the default. #[func] pub fn serif( + /// The call span of this function. + span: Span, /// The content to style. body: Content, ) -> Content { - MathStyleElem::new(body).with_variant(Some(MathVariant::Serif)).pack() + MathStyleElem::new(body) + .spanned(span) + .with_variant(Some(MathVariant::Serif)) + .pack() } /// Sans-serif font style in math. @@ -58,10 +70,15 @@ pub fn serif( /// ``` #[func(title = "Sans Serif")] pub fn sans( + /// The call span of this function. + span: Span, /// The content to style. body: Content, ) -> Content { - MathStyleElem::new(body).with_variant(Some(MathVariant::Sans)).pack() + MathStyleElem::new(body) + .spanned(span) + .with_variant(Some(MathVariant::Sans)) + .pack() } /// Calligraphic font style in math. @@ -71,10 +88,15 @@ pub fn sans( /// ``` #[func(title = "Calligraphic")] pub fn cal( + /// The call span of this function. + span: Span, /// The content to style. body: Content, ) -> Content { - MathStyleElem::new(body).with_variant(Some(MathVariant::Cal)).pack() + MathStyleElem::new(body) + .spanned(span) + .with_variant(Some(MathVariant::Cal)) + .pack() } /// Fraktur font style in math. @@ -84,10 +106,15 @@ pub fn cal( /// ``` #[func(title = "Fraktur")] pub fn frak( + /// The call span of this function. + span: Span, /// The content to style. body: Content, ) -> Content { - MathStyleElem::new(body).with_variant(Some(MathVariant::Frak)).pack() + MathStyleElem::new(body) + .spanned(span) + .with_variant(Some(MathVariant::Frak)) + .pack() } /// Monospace font style in math. @@ -97,10 +124,15 @@ pub fn frak( /// ``` #[func(title = "Monospace")] pub fn mono( + /// The call span of this function. + span: Span, /// The content to style. body: Content, ) -> Content { - MathStyleElem::new(body).with_variant(Some(MathVariant::Mono)).pack() + MathStyleElem::new(body) + .spanned(span) + .with_variant(Some(MathVariant::Mono)) + .pack() } /// Blackboard bold (double-struck) font style in math. @@ -115,10 +147,15 @@ pub fn mono( /// ``` #[func(title = "Blackboard Bold")] pub fn bb( + /// The call span of this function. + span: Span, /// The content to style. body: Content, ) -> Content { - MathStyleElem::new(body).with_variant(Some(MathVariant::Bb)).pack() + MathStyleElem::new(body) + .spanned(span) + .with_variant(Some(MathVariant::Bb)) + .pack() } /// Forced display style in math. @@ -130,6 +167,8 @@ pub fn bb( /// ``` #[func(title = "Display Size")] pub fn display( + /// The call span of this function. + span: Span, /// The content to size. body: Content, /// Whether to impose a height restriction for exponents, like regular sub- @@ -139,6 +178,7 @@ pub fn display( cramped: bool, ) -> Content { MathStyleElem::new(body) + .spanned(span) .with_size(Some(MathSize::Display)) .with_cramped(Some(cramped)) .pack() @@ -154,6 +194,8 @@ pub fn display( /// ``` #[func(title = "Inline Size")] pub fn inline( + /// The call span of this function. + span: Span, /// The content to size. body: Content, /// Whether to impose a height restriction for exponents, like regular sub- @@ -163,6 +205,7 @@ pub fn inline( cramped: bool, ) -> Content { MathStyleElem::new(body) + .spanned(span) .with_size(Some(MathSize::Text)) .with_cramped(Some(cramped)) .pack() @@ -177,6 +220,8 @@ pub fn inline( /// ``` #[func(title = "Script Size")] pub fn script( + /// The call span of this function. + span: Span, /// The content to size. body: Content, /// Whether to impose a height restriction for exponents, like regular sub- @@ -186,6 +231,7 @@ pub fn script( cramped: bool, ) -> Content { MathStyleElem::new(body) + .spanned(span) .with_size(Some(MathSize::Script)) .with_cramped(Some(cramped)) .pack() @@ -201,6 +247,8 @@ pub fn script( /// ``` #[func(title = "Script-Script Size")] pub fn sscript( + /// The call span of this function. + span: Span, /// The content to size. body: Content, /// Whether to impose a height restriction for exponents, like regular sub- @@ -210,6 +258,7 @@ pub fn sscript( cramped: bool, ) -> Content { MathStyleElem::new(body) + .spanned(span) .with_size(Some(MathSize::ScriptScript)) .with_cramped(Some(cramped)) .pack() @@ -239,7 +288,7 @@ pub struct MathStyleElem { } impl LayoutMath for MathStyleElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.style", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let mut style = ctx.style; if let Some(variant) = self.variant(StyleChain::default()) { diff --git a/crates/typst/src/math/underover.rs b/crates/typst/src/math/underover.rs index f94549eab..c3a2a5735 100644 --- a/crates/typst/src/math/underover.rs +++ b/crates/typst/src/math/underover.rs @@ -33,7 +33,7 @@ pub struct UnderlineElem { } impl LayoutMath for UnderlineElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.underline", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout_underoverline(ctx, self.body(), self.span(), LineKind::Under) } @@ -52,7 +52,7 @@ pub struct OverlineElem { } impl LayoutMath for OverlineElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.overline", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout_underoverline(ctx, self.body(), self.span(), LineKind::Over) } @@ -137,7 +137,7 @@ pub struct UnderbraceElem { } impl LayoutMath for UnderbraceElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.underbrace", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout_underoverspreader( ctx, @@ -168,7 +168,7 @@ pub struct OverbraceElem { } impl LayoutMath for OverbraceElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.overbrace", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout_underoverspreader( ctx, @@ -199,7 +199,7 @@ pub struct UnderbracketElem { } impl LayoutMath for UnderbracketElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.underbrace", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout_underoverspreader( ctx, @@ -230,7 +230,7 @@ pub struct OverbracketElem { } impl LayoutMath for OverbracketElem { - #[tracing::instrument(skip(ctx))] + #[typst_macros::time(name = "math.overbracket", span = self.span())] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout_underoverspreader( ctx, diff --git a/crates/typst/src/model/bibliography.rs b/crates/typst/src/model/bibliography.rs index a23ce8217..936c44fed 100644 --- a/crates/typst/src/model/bibliography.rs +++ b/crates/typst/src/model/bibliography.rs @@ -207,7 +207,7 @@ impl Synthesize for BibliographyElem { } impl Show for BibliographyElem { - #[tracing::instrument(name = "BibliographyElem::show", skip_all)] + #[typst_macros::time(name = "bibliography", span = self.span())] fn show(&self, engine: &mut Engine, styles: StyleChain) -> SourceResult { const COLUMN_GUTTER: Em = Em::new(0.65); const INDENT: Em = Em::new(1.5); @@ -218,7 +218,12 @@ impl Show for BibliographyElem { TextElem::packed(Self::local_name_in(styles)).spanned(self.span()) }); - seq.push(HeadingElem::new(title).with_level(NonZeroUsize::ONE).pack()); + seq.push( + HeadingElem::new(title) + .spanned(self.span()) + .with_level(NonZeroUsize::ONE) + .pack(), + ); } Ok(engine.delayed(|engine| { @@ -241,6 +246,7 @@ impl Show for BibliographyElem { seq.push(VElem::new(row_gutter).with_weakness(3).pack()); seq.push( GridElem::new(cells) + .spanned(self.span()) .with_columns(TrackSizings(smallvec![Sizing::Auto; 2])) .with_column_gutter(TrackSizings(smallvec![COLUMN_GUTTER.into()])) .with_row_gutter(TrackSizings(smallvec![(row_gutter).into()])) @@ -344,6 +350,7 @@ impl Bibliography { /// Load bibliography entries from paths. #[comemo::memoize] + #[typst_macros::time(name = "load bibliography")] fn load(paths: &BibliographyPaths, data: &[Bytes]) -> StrResult { let mut map = IndexMap::new(); let mut duplicates = Vec::::new(); @@ -941,6 +948,7 @@ impl ElemRenderer<'_> { if let Some(prefix) = suf_prefix { const COLUMN_GUTTER: Em = Em::new(0.65); content = GridElem::new(vec![prefix, content]) + .spanned(self.span) .with_columns(TrackSizings(smallvec![Sizing::Auto; 2])) .with_column_gutter(TrackSizings(smallvec![COLUMN_GUTTER.into()])) .pack(); @@ -948,10 +956,11 @@ impl ElemRenderer<'_> { match elem.display { Some(Display::Block) => { - content = BlockElem::new().with_body(Some(content)).pack(); + content = + BlockElem::new().spanned(self.span).with_body(Some(content)).pack(); } Some(Display::Indent) => { - content = PadElem::new(content).pack(); + content = PadElem::new(content).spanned(self.span).pack(); } Some(Display::LeftMargin) => { *prefix.get_or_insert_with(Default::default) += content; @@ -980,7 +989,9 @@ impl ElemRenderer<'_> { /// Display a link. fn display_link(&self, text: &hayagriva::Formatted, url: &str) -> Content { let dest = Destination::Url(url.into()); - LinkElem::new(dest.into(), self.display_formatted(text)).pack() + LinkElem::new(dest.into(), self.display_formatted(text)) + .spanned(self.span) + .pack() } /// Display transparent pass-through content. @@ -1029,15 +1040,16 @@ fn apply_formatting(mut content: Content, format: &hayagriva::Formatting) -> Con } } + let span = content.span(); match format.vertical_align { citationberg::VerticalAlign::None => {} citationberg::VerticalAlign::Baseline => {} citationberg::VerticalAlign::Sup => { // Add zero-width weak spacing to make the superscript "sticky". - content = HElem::hole().pack() + SuperElem::new(content).pack(); + content = HElem::hole().pack() + SuperElem::new(content).spanned(span).pack(); } citationberg::VerticalAlign::Sub => { - content = HElem::hole().pack() + SubElem::new(content).pack(); + content = HElem::hole().pack() + SubElem::new(content).spanned(span).pack(); } } diff --git a/crates/typst/src/model/cite.rs b/crates/typst/src/model/cite.rs index 3657e83d8..d2b50790c 100644 --- a/crates/typst/src/model/cite.rs +++ b/crates/typst/src/model/cite.rs @@ -143,7 +143,7 @@ pub struct CiteGroup { } impl Show for CiteGroup { - #[tracing::instrument(name = "CiteGroup::show", skip(self, engine))] + #[typst_macros::time(name = "cite", span = self.span())] fn show(&self, engine: &mut Engine, _: StyleChain) -> SourceResult { Ok(engine.delayed(|engine| { let location = self.location().unwrap(); diff --git a/crates/typst/src/model/document.rs b/crates/typst/src/model/document.rs index 39fb2ac3f..65b4280b5 100644 --- a/crates/typst/src/model/document.rs +++ b/crates/typst/src/model/document.rs @@ -67,14 +67,12 @@ impl Construct for DocumentElem { impl LayoutRoot for DocumentElem { /// Layout the document into a sequence of frames, one per page. - #[tracing::instrument(name = "DocumentElem::layout_root", skip_all)] + #[typst_macros::time(name = "document", span = self.span())] fn layout_root( &self, engine: &mut Engine, styles: StyleChain, ) -> SourceResult { - tracing::info!("Document layout"); - let mut pages = Vec::with_capacity(self.children().len()); let mut page_counter = ManualPageCounter::new(); diff --git a/crates/typst/src/model/emph.rs b/crates/typst/src/model/emph.rs index 1224246e5..46fa0ca94 100644 --- a/crates/typst/src/model/emph.rs +++ b/crates/typst/src/model/emph.rs @@ -34,7 +34,7 @@ pub struct EmphElem { } impl Show for EmphElem { - #[tracing::instrument(name = "EmphElem::show", skip(self))] + #[typst_macros::time(name = "emph", span = self.span())] fn show(&self, _: &mut Engine, _: StyleChain) -> SourceResult { Ok(self.body().clone().styled(TextElem::set_emph(ItalicToggle))) } diff --git a/crates/typst/src/model/enum.rs b/crates/typst/src/model/enum.rs index 1d37f89cf..bb44f438a 100644 --- a/crates/typst/src/model/enum.rs +++ b/crates/typst/src/model/enum.rs @@ -209,7 +209,7 @@ impl EnumElem { } impl Layout for EnumElem { - #[tracing::instrument(name = "EnumElem::layout", skip_all)] + #[typst_macros::time(name = "enum", span = self.span())] fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/model/figure.rs b/crates/typst/src/model/figure.rs index 1fffc5024..1b57ea2c7 100644 --- a/crates/typst/src/model/figure.rs +++ b/crates/typst/src/model/figure.rs @@ -300,7 +300,7 @@ impl Synthesize for FigureElem { } impl Show for FigureElem { - #[tracing::instrument(name = "FigureElem::show", skip_all)] + #[typst_macros::time(name = "figure", span = self.span())] fn show(&self, _: &mut Engine, styles: StyleChain) -> SourceResult { let mut realized = self.body().clone(); @@ -317,12 +317,14 @@ impl Show for FigureElem { // Wrap the contents in a block. realized = BlockElem::new() .with_body(Some(realized)) + .spanned(self.span()) .pack() .aligned(Align::CENTER); // Wrap in a float. if let Some(align) = self.placement(styles) { realized = PlaceElem::new(realized) + .spanned(self.span()) .with_float(true) .with_alignment(align.map(|align| HAlign::Center + align)) .pack(); @@ -551,7 +553,7 @@ impl Synthesize for FigureCaption { } impl Show for FigureCaption { - #[tracing::instrument(name = "FigureCaption::show", skip_all)] + #[typst_macros::time(name = "figure.caption", span = self.span())] fn show(&self, engine: &mut Engine, styles: StyleChain) -> SourceResult { let mut realized = self.body().clone(); diff --git a/crates/typst/src/model/footnote.rs b/crates/typst/src/model/footnote.rs index 6a0a7c15b..1f9ce7048 100644 --- a/crates/typst/src/model/footnote.rs +++ b/crates/typst/src/model/footnote.rs @@ -128,14 +128,14 @@ impl Synthesize for FootnoteElem { } impl Show for FootnoteElem { - #[tracing::instrument(name = "FootnoteElem::show", skip_all)] + #[typst_macros::time(name = "footnote", span = self.span())] fn show(&self, engine: &mut Engine, styles: StyleChain) -> SourceResult { Ok(engine.delayed(|engine| { let loc = self.declaration_location(engine).at(self.span())?; let numbering = self.numbering(styles); let counter = Counter::of(Self::elem()); let num = counter.at(engine, loc)?.display(engine, numbering)?; - let sup = SuperElem::new(num).pack(); + let sup = SuperElem::new(num).spanned(self.span()).pack(); let loc = loc.variant(1); // Add zero-width weak spacing to make the footnote "sticky". Ok(HElem::hole().pack() + sup.linked(Destination::Location(loc))) @@ -270,6 +270,7 @@ pub struct FootnoteEntry { } impl Show for FootnoteEntry { + #[typst_macros::time(name = "footnote.entry", span = self.span())] fn show(&self, engine: &mut Engine, styles: StyleChain) -> SourceResult { let note = self.note(); let number_gap = Em::new(0.05); @@ -285,6 +286,7 @@ impl Show for FootnoteEntry { let num = counter.at(engine, loc)?.display(engine, numbering)?; let sup = SuperElem::new(num) + .spanned(self.span()) .pack() .linked(Destination::Location(loc)) .backlinked(loc.variant(1)); diff --git a/crates/typst/src/model/heading.rs b/crates/typst/src/model/heading.rs index 7b73b8b56..e5fc04cf9 100644 --- a/crates/typst/src/model/heading.rs +++ b/crates/typst/src/model/heading.rs @@ -152,17 +152,21 @@ impl Synthesize for HeadingElem { } impl Show for HeadingElem { - #[tracing::instrument(name = "HeadingElem::show", skip_all)] + #[typst_macros::time(name = "heading", span = self.span())] fn show(&self, _: &mut Engine, styles: StyleChain) -> SourceResult { let mut realized = self.body().clone(); if let Some(numbering) = self.numbering(styles).as_ref() { realized = Counter::of(Self::elem()) - .display(Some(numbering.clone()), false) + .display(self.span(), Some(numbering.clone()), false) .spanned(self.span()) + HElem::new(Em::new(0.3).into()).with_weak(true).pack() + realized; } - Ok(BlockElem::new().with_body(Some(realized)).pack()) + Ok(BlockElem::new() + .spanned(self.span()) + .spanned(self.span()) + .with_body(Some(realized)) + .pack()) } } diff --git a/crates/typst/src/model/link.rs b/crates/typst/src/model/link.rs index 5d1b4f191..7c68b7115 100644 --- a/crates/typst/src/model/link.rs +++ b/crates/typst/src/model/link.rs @@ -90,7 +90,7 @@ impl LinkElem { } impl Show for LinkElem { - #[tracing::instrument(name = "LinkElem::show", skip(self, engine))] + #[typst_macros::time(name = "link", span = self.span())] fn show(&self, engine: &mut Engine, _: StyleChain) -> SourceResult { let body = self.body().clone(); let linked = match self.dest() { diff --git a/crates/typst/src/model/list.rs b/crates/typst/src/model/list.rs index a0a2609c4..48913fc77 100644 --- a/crates/typst/src/model/list.rs +++ b/crates/typst/src/model/list.rs @@ -135,7 +135,7 @@ impl ListElem { } impl Layout for ListElem { - #[tracing::instrument(name = "ListElem::layout", skip_all)] + #[typst_macros::time(name = "list", span = self.span())] fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/model/outline.rs b/crates/typst/src/model/outline.rs index 3531bdecd..951e3254b 100644 --- a/crates/typst/src/model/outline.rs +++ b/crates/typst/src/model/outline.rs @@ -186,7 +186,7 @@ impl OutlineElem { } impl Show for OutlineElem { - #[tracing::instrument(name = "OutlineElem::show", skip_all)] + #[typst_macros::time(name = "outline", span = self.span())] fn show(&self, engine: &mut Engine, styles: StyleChain) -> SourceResult { let mut seq = vec![ParbreakElem::new().pack()]; // Build the outline title. @@ -195,7 +195,12 @@ impl Show for OutlineElem { TextElem::packed(Self::local_name_in(styles)).spanned(self.span()) }); - seq.push(HeadingElem::new(title).with_level(NonZeroUsize::ONE).pack()); + seq.push( + HeadingElem::new(title) + .spanned(self.span()) + .with_level(NonZeroUsize::ONE) + .pack(), + ); } let indent = self.indent(styles); @@ -487,6 +492,7 @@ impl OutlineEntry { } impl Show for OutlineEntry { + #[typst_macros::time(name = "outline.entry", span = self.span())] fn show(&self, _: &mut Engine, _: StyleChain) -> SourceResult { let mut seq = vec![]; let elem = self.element(); @@ -511,6 +517,7 @@ impl Show for OutlineEntry { seq.push(SpaceElem::new().pack()); seq.push( BoxElem::new() + .spanned(self.span()) .with_body(Some(filler.clone())) .with_width(Fr::one().into()) .pack(), diff --git a/crates/typst/src/model/par.rs b/crates/typst/src/model/par.rs index c9f64efb4..f00c39f0c 100644 --- a/crates/typst/src/model/par.rs +++ b/crates/typst/src/model/par.rs @@ -124,7 +124,7 @@ impl Construct for ParElem { impl ParElem { /// Layout the paragraph into a collection of lines. - #[tracing::instrument(name = "ParElement::layout", skip_all)] + #[typst_macros::time(name = "par", span = self.span())] pub fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/model/quote.rs b/crates/typst/src/model/quote.rs index 2a7090713..4324280ae 100644 --- a/crates/typst/src/model/quote.rs +++ b/crates/typst/src/model/quote.rs @@ -154,6 +154,7 @@ impl Synthesize for QuoteElem { } impl Show for QuoteElem { + #[typst_macros::time(name = "quote", span = self.span())] fn show(&self, _: &mut Engine, styles: StyleChain) -> SourceResult { let mut realized = self.body().clone(); let block = self.block(styles); @@ -167,7 +168,8 @@ impl Show for QuoteElem { } if block { - realized = BlockElem::new().with_body(Some(realized)).pack(); + realized = + BlockElem::new().spanned(self.span()).with_body(Some(realized)).pack(); if let Some(attribution) = self.attribution(styles).as_ref() { let mut seq = vec![TextElem::packed('—'), SpaceElem::new().pack()]; @@ -179,6 +181,7 @@ impl Show for QuoteElem { Attribution::Label(label) => { seq.push( CiteElem::new(*label) + .spanned(self.span()) .with_form(Some(CitationForm::Prose)) .pack(), ); @@ -193,7 +196,8 @@ impl Show for QuoteElem { realized = PadElem::new(realized).pack(); } else if let Some(Attribution::Label(label)) = self.attribution(styles) { - realized += SpaceElem::new().pack() + CiteElem::new(*label).pack(); + realized += SpaceElem::new().pack() + + CiteElem::new(*label).spanned(self.span()).pack(); } Ok(realized) diff --git a/crates/typst/src/model/reference.rs b/crates/typst/src/model/reference.rs index 6928896a3..756c83fa9 100644 --- a/crates/typst/src/model/reference.rs +++ b/crates/typst/src/model/reference.rs @@ -159,7 +159,7 @@ impl Synthesize for RefElem { } impl Show for RefElem { - #[tracing::instrument(name = "RefElem::show", skip_all)] + #[typst_macros::time(name = "ref", span = self.span())] fn show(&self, engine: &mut Engine, styles: StyleChain) -> SourceResult { Ok(engine.delayed(|engine| { let target = *self.target(); @@ -243,7 +243,7 @@ impl RefElem { engine: &mut Engine, styles: StyleChain, ) -> SourceResult { - let mut elem = CiteElem::new(*self.target()); + let mut elem = CiteElem::new(*self.target()).spanned(self.span()); elem.set_location(self.location().unwrap()); elem.synthesize(engine, styles)?; elem.push_supplement(match self.supplement(styles).clone() { diff --git a/crates/typst/src/model/strong.rs b/crates/typst/src/model/strong.rs index 666a4aa01..f6d75fb51 100644 --- a/crates/typst/src/model/strong.rs +++ b/crates/typst/src/model/strong.rs @@ -38,7 +38,7 @@ pub struct StrongElem { } impl Show for StrongElem { - #[tracing::instrument(name = "StrongElem::show", skip_all)] + #[typst_macros::time(name = "strong", span = self.span())] fn show(&self, _: &mut Engine, styles: StyleChain) -> SourceResult { Ok(self .body() diff --git a/crates/typst/src/model/table.rs b/crates/typst/src/model/table.rs index 12a977d3a..339204455 100644 --- a/crates/typst/src/model/table.rs +++ b/crates/typst/src/model/table.rs @@ -153,7 +153,7 @@ pub struct TableElem { } impl Layout for TableElem { - #[tracing::instrument(name = "TableElem::layout", skip_all)] + #[typst_macros::time(name = "table", span = self.span())] fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/model/terms.rs b/crates/typst/src/model/terms.rs index bbb6129ab..53310f077 100644 --- a/crates/typst/src/model/terms.rs +++ b/crates/typst/src/model/terms.rs @@ -108,7 +108,7 @@ impl TermsElem { } impl Layout for TermsElem { - #[tracing::instrument(name = "TermsElem::layout", skip_all)] + #[typst_macros::time(name = "terms", span = self.span())] fn layout( &self, engine: &mut Engine, diff --git a/crates/typst/src/realize/mod.rs b/crates/typst/src/realize/mod.rs index 1b2047210..a17f82bb5 100644 --- a/crates/typst/src/realize/mod.rs +++ b/crates/typst/src/realize/mod.rs @@ -13,8 +13,8 @@ use typed_arena::Arena; use crate::diag::{bail, SourceResult}; use crate::engine::{Engine, Route}; use crate::foundations::{ - Content, Finalize, Guard, NativeElement, Recipe, Selector, Show, StyleChain, - StyleVecBuilder, Styles, Synthesize, + Behave, Behaviour, Content, Finalize, Guard, NativeElement, Recipe, Selector, Show, + StyleChain, StyleVec, StyleVecBuilder, Styles, Synthesize, }; use crate::introspection::{Locatable, Meta, MetaElem}; use crate::layout::{ @@ -35,7 +35,7 @@ use crate::visualize::{ }; /// Realize into an element that is capable of root-level layout. -#[tracing::instrument(skip_all)] +#[typst_macros::time(name = "realize root")] pub fn realize_root<'a>( engine: &mut Engine, scratch: &'a Scratch<'a>, @@ -50,11 +50,12 @@ pub fn realize_root<'a>( builder.accept(content, styles)?; builder.interrupt_page(Some(styles), true)?; let (pages, shared) = builder.doc.unwrap().pages.finish(); - Ok((Cow::Owned(DocumentElem::new(pages.to_vec()).pack()), shared)) + let span = first_span(&pages); + Ok((Cow::Owned(DocumentElem::new(pages.to_vec()).spanned(span).pack()), shared)) } /// Realize into an element that is capable of block-level layout. -#[tracing::instrument(skip_all)] +#[typst_macros::time(name = "realize block")] pub fn realize_block<'a>( engine: &mut Engine, scratch: &'a Scratch<'a>, @@ -82,8 +83,10 @@ pub fn realize_block<'a>( let mut builder = Builder::new(engine, scratch, false); builder.accept(content, styles)?; builder.interrupt_par()?; + let (children, shared) = builder.flow.0.finish(); - Ok((Cow::Owned(FlowElem::new(children.to_vec()).pack()), shared)) + let span = first_span(&children); + Ok((Cow::Owned(FlowElem::new(children.to_vec()).spanned(span).pack()), shared)) } /// Whether the target is affected by show rules in the given style chain. @@ -301,8 +304,10 @@ impl<'a, 'v, 't> Builder<'a, 'v, 't> { styles: StyleChain<'a>, ) -> SourceResult<()> { if content.can::() && !content.is::() { - content = - self.scratch.content.alloc(EquationElem::new(content.clone()).pack()); + content = self + .scratch + .content + .alloc(EquationElem::new(content.clone()).spanned(content.span()).pack()); } if let Some(realized) = realize(self.engine, content, styles)? { @@ -470,13 +475,15 @@ impl<'a, 'v, 't> Builder<'a, 'v, 't> { self.interrupt_par()?; let Some(doc) = &mut self.doc else { return Ok(()) }; if (doc.keep_next && styles.is_some()) || self.flow.0.has_strong_elements(last) { - let (flow, shared) = mem::take(&mut self.flow).0.finish(); + let (children, shared) = mem::take(&mut self.flow).0.finish(); let styles = if shared == StyleChain::default() { styles.unwrap_or_default() } else { shared }; - let page = PageElem::new(FlowElem::new(flow.to_vec()).pack()); + let span = first_span(&children); + let flow = FlowElem::new(children.to_vec()).spanned(span); + let page = PageElem::new(flow.pack()).spanned(span); let stored = self.scratch.content.alloc(page.pack()); self.accept(stored, styles)?; } @@ -614,14 +621,7 @@ impl<'a> ParBuilder<'a> { fn finish(self) -> (Content, StyleChain<'a>) { let (children, shared) = self.0.finish(); - - // Find the first span that isn't detached. - let span = children - .iter() - .map(|(cnt, _)| cnt.span()) - .find(|span| !span.is_detached()) - .unwrap_or_else(Span::detached); - + let span = first_span(&children); (ParElem::new(children.to_vec()).spanned(span).pack(), shared) } } @@ -664,6 +664,7 @@ impl<'a> ListBuilder<'a> { fn finish(self) -> (Content, StyleChain<'a>) { let (items, shared) = self.items.finish(); + let span = first_span(&items); let item = items.items().next().unwrap(); let output = if item.is::() { ListElem::new( @@ -677,6 +678,7 @@ impl<'a> ListBuilder<'a> { .collect::>(), ) .with_tight(self.tight) + .spanned(span) .pack() } else if item.is::() { EnumElem::new( @@ -690,6 +692,7 @@ impl<'a> ListBuilder<'a> { .collect::>(), ) .with_tight(self.tight) + .spanned(span) .pack() } else if item.is::() { TermsElem::new( @@ -706,6 +709,7 @@ impl<'a> ListBuilder<'a> { .collect::>(), ) .with_tight(self.tight) + .spanned(span) .pack() } else { unreachable!() @@ -761,3 +765,16 @@ impl<'a> CiteGroupBuilder<'a> { (CiteGroup::new(self.items).spanned(span).pack(), self.styles) } } + +/// Find the first span that isn't detached. +fn first_span(children: &StyleVec>) -> Span { + children + .iter() + .filter(|(elem, _)| { + elem.with::() + .map_or(true, |b| b.behaviour() != Behaviour::Invisible) + }) + .map(|(elem, _)| elem.span()) + .find(|span| !span.is_detached()) + .unwrap_or_else(Span::detached) +} diff --git a/crates/typst/src/text/deco.rs b/crates/typst/src/text/deco.rs index 348ddf343..bb85f54ef 100644 --- a/crates/typst/src/text/deco.rs +++ b/crates/typst/src/text/deco.rs @@ -85,7 +85,7 @@ pub struct UnderlineElem { } impl Show for UnderlineElem { - #[tracing::instrument(name = "UnderlineElem::show", skip_all)] + #[typst_macros::time(name = "underline", span = self.span())] fn show(&self, _: &mut Engine, styles: StyleChain) -> SourceResult { Ok(self.body().clone().styled(TextElem::set_deco(Decoration { line: DecoLine::Underline { @@ -177,7 +177,7 @@ pub struct OverlineElem { } impl Show for OverlineElem { - #[tracing::instrument(name = "OverlineElem::show", skip_all)] + #[typst_macros::time(name = "overline", span = self.span())] fn show(&self, _: &mut Engine, styles: StyleChain) -> SourceResult { Ok(self.body().clone().styled(TextElem::set_deco(Decoration { line: DecoLine::Overline { @@ -254,7 +254,7 @@ pub struct StrikeElem { } impl Show for StrikeElem { - #[tracing::instrument(name = "StrikeElem::show", skip_all)] + #[typst_macros::time(name = "strike", span = self.span())] fn show(&self, _: &mut Engine, styles: StyleChain) -> SourceResult { Ok(self.body().clone().styled(TextElem::set_deco(Decoration { // Note that we do not support evade option for strikethrough. @@ -324,7 +324,7 @@ pub struct HighlightElem { } impl Show for HighlightElem { - #[tracing::instrument(name = "HighlightElem::show", skip_all)] + #[typst_macros::time(name = "highlight", span = self.span())] fn show(&self, _: &mut Engine, styles: StyleChain) -> SourceResult { Ok(self.body().clone().styled(TextElem::set_deco(Decoration { line: DecoLine::Highlight { diff --git a/crates/typst/src/text/raw.rs b/crates/typst/src/text/raw.rs index 2bcf566a9..583155cd0 100644 --- a/crates/typst/src/text/raw.rs +++ b/crates/typst/src/text/raw.rs @@ -392,7 +392,7 @@ impl Synthesize for RawElem { } impl Show for RawElem { - #[tracing::instrument(name = "RawElem::show", skip_all)] + #[typst_macros::time(name = "raw", span = self.span())] fn show(&self, _: &mut Engine, styles: StyleChain) -> SourceResult { let mut lines = EcoVec::with_capacity((2 * self.lines().len()).saturating_sub(1)); for (i, line) in self.lines().iter().enumerate() { @@ -407,7 +407,8 @@ impl Show for RawElem { if self.block(styles) { // Align the text before inserting it into the block. realized = realized.aligned(self.align(styles).into()); - realized = BlockElem::new().with_body(Some(realized)).pack(); + realized = + BlockElem::new().spanned(self.span()).with_body(Some(realized)).pack(); } Ok(realized) @@ -497,6 +498,7 @@ pub struct RawLine { } impl Show for RawLine { + #[typst_macros::time(name = "raw.line", span = self.span())] fn show(&self, _: &mut Engine, _styles: StyleChain) -> SourceResult { Ok(self.body().clone()) } @@ -661,6 +663,7 @@ impl Fold for SyntaxPaths { /// Load a syntax set from a list of syntax file paths. #[comemo::memoize] +#[typst_macros::time(name = "load syntaxes")] fn load_syntaxes(paths: &SyntaxPaths, bytes: &[Bytes]) -> StrResult> { let mut out = SyntaxSetBuilder::new(); @@ -704,6 +707,7 @@ fn parse_syntaxes( } #[comemo::memoize] +#[typst_macros::time(name = "load theme")] fn load_theme(path: &str, bytes: &Bytes) -> StrResult> { let mut cursor = std::io::Cursor::new(bytes.as_slice()); diff --git a/crates/typst/src/text/shift.rs b/crates/typst/src/text/shift.rs index e467d6c02..47a186fed 100644 --- a/crates/typst/src/text/shift.rs +++ b/crates/typst/src/text/shift.rs @@ -48,7 +48,7 @@ pub struct SubElem { } impl Show for SubElem { - #[tracing::instrument(name = "SubElem::show", skip_all)] + #[typst_macros::time(name = "sub", span = self.span())] fn show(&self, engine: &mut Engine, styles: StyleChain) -> SourceResult { let body = self.body().clone(); let mut transformed = None; @@ -108,7 +108,7 @@ pub struct SuperElem { } impl Show for SuperElem { - #[tracing::instrument(name = "SuperElem::show", skip_all)] + #[typst_macros::time(name = "super", span = self.span())] fn show(&self, engine: &mut Engine, styles: StyleChain) -> SourceResult { let body = self.body().clone(); let mut transformed = None; diff --git a/crates/typst/src/visualize/image/mod.rs b/crates/typst/src/visualize/image/mod.rs index ddfcc91c9..5bfda381e 100644 --- a/crates/typst/src/visualize/image/mod.rs +++ b/crates/typst/src/visualize/image/mod.rs @@ -25,7 +25,7 @@ use crate::layout::{ }; use crate::loading::Readable; use crate::model::Figurable; -use crate::syntax::Spanned; +use crate::syntax::{Span, Spanned}; use crate::text::{families, Lang, LocalName, Region}; use crate::util::{option_eq, Numeric}; use crate::visualize::Path; @@ -104,6 +104,8 @@ impl ImageElem { /// ``` #[func(title = "Decode Image")] pub fn decode( + /// The call span of this function. + span: Span, /// The data to decode as an image. Can be a string for SVGs. data: Readable, /// The image's format. Detected automatically by default. @@ -122,7 +124,7 @@ impl ImageElem { #[named] fit: Option, ) -> StrResult { - let mut elem = ImageElem::new(EcoString::new(), data); + let mut elem = ImageElem::new(EcoString::new(), data).spanned(span); if let Some(format) = format { elem.push_format(format); } @@ -143,7 +145,7 @@ impl ImageElem { } impl Layout for ImageElem { - #[tracing::instrument(name = "ImageElem::layout", skip_all)] + #[typst_macros::time(name = "image", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -322,6 +324,7 @@ pub enum ImageKind { impl Image { /// Create an image from a buffer and a format. #[comemo::memoize] + #[typst_macros::time(name = "load image")] pub fn new( data: Bytes, format: ImageFormat, @@ -341,6 +344,7 @@ impl Image { /// Create a possibly font-dependant image from a buffer and a format. #[comemo::memoize] + #[typst_macros::time(name = "load image")] pub fn with_fonts( data: Bytes, format: ImageFormat, diff --git a/crates/typst/src/visualize/line.rs b/crates/typst/src/visualize/line.rs index ece937276..12ec44733 100644 --- a/crates/typst/src/visualize/line.rs +++ b/crates/typst/src/visualize/line.rs @@ -59,7 +59,7 @@ pub struct LineElem { } impl Layout for LineElem { - #[tracing::instrument(name = "LineElem::layout", skip_all)] + #[typst_macros::time(name = "line", span = self.span())] fn layout( &self, _: &mut Engine, diff --git a/crates/typst/src/visualize/path.rs b/crates/typst/src/visualize/path.rs index 6ed07cb29..8b80f870c 100644 --- a/crates/typst/src/visualize/path.rs +++ b/crates/typst/src/visualize/path.rs @@ -71,7 +71,7 @@ pub struct PathElem { } impl Layout for PathElem { - #[tracing::instrument(name = "PathElem::layout", skip_all)] + #[typst_macros::time(name = "path", span = self.span())] fn layout( &self, _: &mut Engine, diff --git a/crates/typst/src/visualize/polygon.rs b/crates/typst/src/visualize/polygon.rs index 7436f63e1..14156ce19 100644 --- a/crates/typst/src/visualize/polygon.rs +++ b/crates/typst/src/visualize/polygon.rs @@ -8,6 +8,7 @@ use crate::foundations::{ use crate::layout::{ Axes, Em, Fragment, Frame, FrameItem, Layout, Length, Point, Regions, Rel, }; +use crate::syntax::Span; use crate::util::Numeric; use crate::visualize::{FixedStroke, Geometry, Paint, Path, Shape, Stroke}; @@ -65,6 +66,8 @@ impl PolygonElem { /// ``` #[func(title = "Regular Polygon")] pub fn regular( + /// The call span of this function. + span: Span, /// How to fill the polygon. See the general /// [polygon's documentation]($polygon.fill) for more details. #[named] @@ -111,7 +114,7 @@ impl PolygonElem { }) .collect(); - let mut elem = PolygonElem::new(vertices); + let mut elem = PolygonElem::new(vertices).spanned(span); if let Some(fill) = fill { elem.push_fill(fill); } @@ -123,7 +126,7 @@ impl PolygonElem { } impl Layout for PolygonElem { - #[tracing::instrument(name = "PolygonElem::layout", skip_all)] + #[typst_macros::time(name = "polygon", span = self.span())] fn layout( &self, _: &mut Engine, diff --git a/crates/typst/src/visualize/shape.rs b/crates/typst/src/visualize/shape.rs index b96507fbc..f378d3632 100644 --- a/crates/typst/src/visualize/shape.rs +++ b/crates/typst/src/visualize/shape.rs @@ -132,7 +132,7 @@ pub struct RectElem { } impl Layout for RectElem { - #[tracing::instrument(name = "RectElem::layout", skip_all)] + #[typst_macros::time(name = "rect", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -238,7 +238,7 @@ pub struct SquareElem { } impl Layout for SquareElem { - #[tracing::instrument(name = "SquareElem::layout", skip_all)] + #[typst_macros::time(name = "square", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -316,7 +316,7 @@ pub struct EllipseElem { } impl Layout for EllipseElem { - #[tracing::instrument(name = "EllipseElem::layout", skip_all)] + #[typst_macros::time(name = "ellipse", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -419,7 +419,7 @@ pub struct CircleElem { } impl Layout for CircleElem { - #[tracing::instrument(name = "CircleElem::layout", skip_all)] + #[typst_macros::time(name = "circle", span = self.span())] fn layout( &self, engine: &mut Engine, @@ -444,7 +444,6 @@ impl Layout for CircleElem { } /// Layout a shape. -#[tracing::instrument(name = "shape::layout", skip_all)] #[allow(clippy::too_many_arguments)] fn layout( engine: &mut Engine, diff --git a/tests/typ/bugs/layout-infinite-lengths.typ b/tests/typ/bugs/layout-infinite-lengths.typ index 501e517ed..7fbc62163 100644 --- a/tests/typ/bugs/layout-infinite-lengths.typ +++ b/tests/typ/bugs/layout-infinite-lengths.typ @@ -3,7 +3,7 @@ --- #set page(width: auto, height: auto) -// Error: cannot expand into infinite width +// Error: 58-59 cannot expand into infinite width #layout(size => grid(columns: (size.width, size.height))[a][b][c][d]) --- diff --git a/tests/typ/visualize/image.typ b/tests/typ/visualize/image.typ index 0e256eb86..093fecc1c 100644 --- a/tests/typ/visualize/image.typ +++ b/tests/typ/visualize/image.typ @@ -66,7 +66,7 @@ A #box(image("/files/tiger.jpg", height: 1cm, width: 80%)) B #image.decode(``.text, format: "svg") --- -// Error: 2-168 failed to parse SVG (missing root node) +// Error: 14-168 failed to parse SVG (missing root node) #image.decode(``.text, format: "svg") --- @@ -78,5 +78,5 @@ A #box(image("/files/tiger.jpg", height: 1cm, width: 80%)) B #image.decode(read("/files/tiger.jpg", encoding: none), format: "jpg", width: 80%) --- -// Error: 2-83 failed to decode image (Format error decoding Png: Invalid PNG signature.) +// Error: 14-83 failed to decode image (Format error decoding Png: Invalid PNG signature.) #image.decode(read("/files/tiger.jpg", encoding: none), format: "png", width: 80%)