diff options
| author | Sébastien d'Herbais de Thun <sebastien.d.herbais@gmail.com> | 2023-04-23 14:33:56 +0200 |
|---|---|---|
| committer | GitHub <noreply@github.com> | 2023-04-23 14:33:56 +0200 |
| commit | 561ff979d574f496415c0499345d41da2e1f6e1e (patch) | |
| tree | 037479ac000bd87a1cb2149e5389b28f08d24051 | |
| parent | 2fbb14f712708188649181525813b3ac5a02e0fb (diff) | |
Add instrumentation (Part 1) (#761)
73 files changed, 723 insertions, 14 deletions
@@ -9,6 +9,18 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f26201604c87b1e01bd3d98f8d5d9a8fcbb815e8cedb41ffccbeb4bf593a35fe" [[package]] +name = "ahash" +version = "0.8.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2c99f64d1e06488f620f932677e24bc6e2897582980441ae90a671415bd7ec2f" +dependencies = [ + "cfg-if", + "getrandom", + "once_cell", + "version_check", +] + +[[package]] name = "aho-corasick" version = "0.7.20" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -484,6 +496,19 @@ dependencies = [ ] [[package]] +name = "dashmap" +version = "5.4.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "907076dfda823b0b36d2a1bb5f90c96660a5bbcd7729e10727f07858f22c4edc" +dependencies = [ + "cfg-if", + "hashbrown", + "lock_api", + "once_cell", + "parking_lot_core", +] + +[[package]] name = "data-url" version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -559,6 +584,15 @@ dependencies = [ ] [[package]] +name = "env_logger" +version = "0.10.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "85cdab6a89accf66733ad5a1693a4dcced6aeff64602b634530dd73c1f3ee9f0" +dependencies = [ + "log", +] + +[[package]] name = "errno" version = "0.3.1" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -590,6 +624,15 @@ dependencies = [ ] [[package]] +name = "fastrand" +version = "1.9.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e51093e27b0797c359783294ca4f0a911c270184cb10f85783b118614a1501be" +dependencies = [ + "instant", +] + +[[package]] name = "fdeflate" version = "0.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -606,7 +649,7 @@ checksum = "5cbc844cecaee9d4443931972e1289c8ff485cb4cc2767cb03ca139ed6885153" dependencies = [ "cfg-if", "libc", - "redox_syscall", + "redox_syscall 0.2.16", "windows-sys 0.48.0", ] @@ -871,6 +914,29 @@ dependencies = [ ] [[package]] +name = "inferno" +version = "0.11.15" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2fb7c1b80a1dfa604bb4a649a5c5aeef3d913f7c520cb42b40e534e8a61bcdfc" +dependencies = [ + "ahash", + "clap 4.2.4", + "crossbeam-channel", + "crossbeam-utils", + "dashmap", + "env_logger", + "indexmap", + "is-terminal", + "itoa", + "log", + "num-format", + "once_cell", + "quick-xml", + "rgb", + "str_stack", +] + +[[package]] name = "inotify" version = "0.9.6" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -891,6 +957,15 @@ dependencies = [ ] [[package]] +name = "instant" +version = "0.1.12" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7a5bbe824c507c5da5956355e86a746d82e0e1464f65d862cc5e71da70e94b2c" +dependencies = [ + "cfg-if", +] + +[[package]] name = "io-lifetimes" version = "1.0.10" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1068,6 +1143,16 @@ dependencies = [ ] [[package]] +name = "lock_api" +version = "0.4.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "435011366fe56583b16cf956f9df0095b405b82d76425bc8981c0e22e60ec4df" +dependencies = [ + "autocfg", + "scopeguard", +] + +[[package]] name = "log" version = "0.4.17" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1165,6 +1250,16 @@ dependencies = [ ] [[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.3" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1176,6 +1271,16 @@ dependencies = [ ] [[package]] +name = "num-format" +version = "0.4.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a652d9771a63711fd3c3deb670acfbe5c30a4072e664d7a3bf5a9e1056ac72c3" +dependencies = [ + "arrayvec 0.7.2", + "itoa", +] + +[[package]] name = "num-integer" version = "0.1.45" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1244,6 +1349,12 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ceedf44fb00f2d1984b0bc98102627ce622e083e49a5bacdb3e514fa4238e267" [[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + +[[package]] name = "oxipng" version = "8.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1268,6 +1379,19 @@ dependencies = [ ] [[package]] +name = "parking_lot_core" +version = "0.9.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9069cbb9f99e3a5083476ccb29ceb1de18b9118cafa53e90c9551235de2b9521" +dependencies = [ + "cfg-if", + "libc", + "redox_syscall 0.2.16", + "smallvec", + "windows-sys 0.45.0", +] + +[[package]] name = "paste" version = "1.0.12" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1321,6 +1445,12 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "db8bcd96cb740d03149cbad5518db9fd87126a10ab519c011893b1754134c468" [[package]] +name = "pin-project-lite" +version = "0.2.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e0a7ae3ac2f1173085d398531c705756c94a4c56843785df85a60c1a0afac116" + +[[package]] name = "pixglyph" version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1358,6 +1488,15 @@ dependencies = [ ] [[package]] +name = "psm" +version = "0.1.21" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5787f7cda34e3033a72192c018bc5883100330f362ef279a8cbccfce8bb4e874" +dependencies = [ + "cc", +] + +[[package]] name = "pulldown-cmark" version = "0.9.2" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1370,6 +1509,15 @@ dependencies = [ ] [[package]] +name = "quick-xml" +version = "0.26.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7f50b1c63b38611e7d4d7f68b82d3ad0cc71a2ad2e7f61fc10f1328d917c93cd" +dependencies = [ + "memchr", +] + +[[package]] name = "quote" version = "1.0.26" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1447,13 +1595,22 @@ dependencies = [ ] [[package]] +name = "redox_syscall" +version = "0.3.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "567664f262709473930a4bf9e51bf2ebf3348f2e748ccc50dea20646858f8f29" +dependencies = [ + "bitflags", +] + +[[package]] name = "redox_users" version = "0.4.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b033d837a7cf162d7993aded9304e30a83213c648b6e389db233191f891e5c2b" dependencies = [ "getrandom", - "redox_syscall", + "redox_syscall 0.2.16", "thiserror", ] @@ -1689,6 +1846,15 @@ dependencies = [ ] [[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + +[[package]] name = "simd-adler32" version = "0.3.5" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1728,6 +1894,19 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a8f112729512f8e442d81f95a8a7ddf2b7c6b8a1a6f509a95864142b30cab2d3" [[package]] +name = "stacker" +version = "0.1.15" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c886bd4480155fd3ef527d45e9ac8dd7118a898a46530b7b94c3e21866259fce" +dependencies = [ + "cc", + "cfg-if", + "libc", + "psm", + "winapi", +] + +[[package]] name = "stderrlog" version = "0.5.4" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1740,6 +1919,12 @@ dependencies = [ ] [[package]] +name = "str_stack" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9091b6114800a5f2141aee1d1b9d6ca3592ac062dc5decb3764ec5895a47b4eb" + +[[package]] name = "strsim" version = "0.10.0" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1844,6 +2029,19 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "55937e1799185b12863d447f42597ed69d9928686b8d88a1df17376a097d8369" [[package]] +name = "tempfile" +version = "3.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b9fbec84f381d5795b08656e4912bec604d162bff9291d6189a78f4c8ab87998" +dependencies = [ + "cfg-if", + "fastrand", + "redox_syscall 0.3.5", + "rustix", + "windows-sys 0.45.0", +] + +[[package]] name = "termcolor" version = "1.1.3" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1933,6 +2131,85 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1f3ccbac311fea05f86f61904b462b55fb3df8837a366dfc601a0161d0532f20" [[package]] +name = "tracing" +version = "0.1.37" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8ce8c33a8d48bd45d624a6e523445fd21ec13d3653cd51f681abf67418f54eb8" +dependencies = [ + "cfg-if", + "pin-project-lite", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4017f8f45139870ca7e672686113917c71c7a6e02d4924eda67186083c03081a" +dependencies = [ + "proc-macro2", + "quote", + "syn 1.0.109", +] + +[[package]] +name = "tracing-core" +version = "0.1.30" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "24eb03ba0eab1fd845050058ce5e616558e8f8d8fca633e6b163fe25c797213a" +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.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a6176eae26dd70d0c919749377897b54a9276bd7061339665dd68777926b5a70" +dependencies = [ + "nu-ansi-term", + "sharded-slab", + "smallvec", + "thread_local", + "tracing-core", + "tracing-log", +] + +[[package]] name = "ttf-parser" version = "0.15.2" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1980,10 +2257,12 @@ dependencies = [ "rustybuzz", "serde", "siphasher", + "stacker", "subsetter", "svg2pdf", "thin-vec", "tiny-skia", + "tracing", "ttf-parser 0.18.1", "typst-macros", "unicode-math-class", @@ -2006,12 +2285,18 @@ dependencies = [ "comemo", "dirs", "elsa", + "inferno", "memmap2", "notify", "once_cell", "open", "same-file", "siphasher", + "tempfile", + "tracing", + "tracing-error", + "tracing-flame", + "tracing-subscriber", "typst", "typst-library", "walkdir", @@ -2056,6 +2341,7 @@ dependencies = [ "serde_yaml", "smallvec", "syntect", + "tracing", "ttf-parser 0.18.1", "typed-arena", "typst", @@ -2277,6 +2563,12 @@ 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" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -51,10 +51,12 @@ unicode-xid = "0.2" unscanny = "0.1" usvg = { version = "0.22", default-features = false, features = ["text"] } xmp-writer = "0.1" +tracing = "0.1.37" indexmap = "1.9.3" +stacker = "0.1.15" [profile.dev] -debug = 0 +debug = false [profile.dev.package."*"] opt-level = 2 diff --git a/cli/Cargo.toml b/cli/Cargo.toml index 768c6053..7719874d 100644 --- a/cli/Cargo.toml +++ b/cli/Cargo.toml @@ -34,6 +34,12 @@ siphasher = "0.3" walkdir = "2" clap = { version = "4.2.1", features = ["derive", "env"] } open = "4.0.1" +tracing = "0.1.37" +tracing-subscriber = "0.3.16" +tracing-flame = "0.2.0" +tracing-error = "0.2" +inferno = "0.11.15" +tempfile = "3.5.0" [build-dependencies] clap = { version = "4.2.1", features = ["derive", "string"] } diff --git a/cli/build.rs b/cli/build.rs index 75e8492a..b6f7d6ee 100644 --- a/cli/build.rs +++ b/cli/build.rs @@ -24,9 +24,9 @@ pub fn typst_version() -> String { format!("{pkg} ({hash})") } -mod args { - include!("src/args.rs"); -} +#[path = "src/args.rs"] +#[allow(dead_code)] +mod args; fn main() { println!("cargo:rerun-if-env-changed=TYPST_VERSION"); diff --git a/cli/src/args.rs b/cli/src/args.rs index 42d52140..699dbb97 100644 --- a/cli/src/args.rs +++ b/cli/src/args.rs @@ -17,6 +17,10 @@ pub struct CliArguments { /// The typst command to run #[command(subcommand)] pub command: Command, + + /// Sets the level of verbosity: 0 = none, 1 = warning & error, 2 = info, 3 = debug, 4 = trace + #[clap(short, long, action = ArgAction::Count)] + pub verbosity: u8, } /// What to do. @@ -35,6 +39,22 @@ pub enum Command { Fonts(FontsCommand), } +impl Command { + /// Returns the compile command if this is a compile or watch command. + pub fn as_compile(&self) -> Option<&CompileCommand> { + match self { + Command::Compile(cmd) => Some(cmd), + Command::Watch(cmd) => Some(cmd), + Command::Fonts(_) => None, + } + } + + /// Returns whether this is a watch command. + pub fn is_watch(&self) -> bool { + matches!(self, Command::Watch(_)) + } +} + /// Compiles the input file into a PDF file #[derive(Debug, Clone, Parser)] pub struct CompileCommand { @@ -47,6 +67,11 @@ pub struct CompileCommand { /// Opens the output file after compilation using the default PDF viewer #[arg(long = "open")] pub open: Option<Option<String>>, + + /// Produces a flamegraph of the compilation process and saves it to the + /// given file or to `flamegraph.svg` in the current working directory. + #[arg(long = "flamegraph", value_name = "OUTPUT_SVG")] + pub flamegraph: Option<Option<PathBuf>>, } /// List all discovered fonts in system and custom font paths diff --git a/cli/src/main.rs b/cli/src/main.rs index 924ea9d7..476a82ee 100644 --- a/cli/src/main.rs +++ b/cli/src/main.rs @@ -1,4 +1,5 @@ mod args; +mod trace; use std::cell::{RefCell, RefMut}; use std::collections::HashMap; @@ -28,6 +29,7 @@ use typst::World; use walkdir::WalkDir; use crate::args::{CliArguments, Command, CompileCommand}; +use crate::trace::init_tracing; type CodespanResult<T> = Result<T, CodespanError>; type CodespanError = codespan_reporting::files::Error; @@ -80,7 +82,7 @@ impl CompileSettings { /// Panics if the command is not a compile or watch command. pub fn with_arguments(args: CliArguments) -> Self { let watch = matches!(args.command, Command::Watch(_)); - let CompileCommand { input, output, open } = match args.command { + let CompileCommand { input, output, open, .. } = match args.command { Command::Compile(command) => command, Command::Watch(command) => command, _ => unreachable!(), @@ -118,6 +120,13 @@ impl FontsSettings { /// Entry point. fn main() { let arguments = CliArguments::parse(); + let _guard = match init_tracing(&arguments) { + Ok(guard) => guard, + Err(err) => { + eprintln!("failed to initialize tracing, reason: {}", err); + return; + } + }; let res = match &arguments.command { Command::Compile(_) | Command::Watch(_) => { @@ -225,7 +234,10 @@ fn compile(mut command: CompileSettings) -> StrResult<()> { } /// Compile a single time. +#[tracing::instrument(skip_all)] fn compile_once(world: &mut SystemWorld, command: &CompileSettings) -> StrResult<bool> { + tracing::info!("Starting compilation"); + status(command, Status::Compiling).unwrap(); world.reset(); @@ -237,6 +249,8 @@ fn compile_once(world: &mut SystemWorld, command: &CompileSettings) -> StrResult let buffer = typst::export::pdf(&document); fs::write(&command.output, buffer).map_err(|_| "failed to write PDF file")?; status(command, Status::Success).unwrap(); + + tracing::info!("Compilation succeeded"); Ok(false) } @@ -245,12 +259,15 @@ fn compile_once(world: &mut SystemWorld, command: &CompileSettings) -> StrResult status(command, Status::Error).unwrap(); print_diagnostics(world, *errors) .map_err(|_| "failed to print diagnostics")?; + + tracing::info!("Compilation failed"); Ok(true) } } } /// Clear the terminal and render the status message. +#[tracing::instrument(skip_all)] fn status(command: &CompileSettings, status: Status) -> io::Result<()> { if !command.watch { return Ok(()); @@ -431,6 +448,7 @@ impl World for SystemWorld { self.source(self.main) } + #[tracing::instrument(skip_all)] fn resolve(&self, path: &Path) -> FileResult<SourceId> { self.slot(path)? .source @@ -469,6 +487,7 @@ impl World for SystemWorld { } impl SystemWorld { + #[tracing::instrument(skip_all)] fn slot(&self, path: &Path) -> FileResult<RefMut<PathSlot>> { let mut hashes = self.hashes.borrow_mut(); let hash = match hashes.get(path).cloned() { @@ -488,6 +507,7 @@ impl SystemWorld { })) } + #[tracing::instrument(skip_all)] fn insert(&self, path: &Path, text: String) -> SourceId { let id = SourceId::from_u16(self.sources.len() as u16); let source = Source::new(id, path, text); @@ -520,6 +540,7 @@ impl SystemWorld { .map_or(false, |hash| self.paths.borrow().contains_key(&hash)) } + #[tracing::instrument(skip_all)] fn reset(&mut self) { self.sources.as_mut().clear(); self.hashes.borrow_mut().clear(); @@ -542,6 +563,7 @@ impl PathHash { } /// Read a file. +#[tracing::instrument(skip_all)] fn read(path: &Path) -> FileResult<Vec<u8>> { let f = |e| FileError::from_io(e, path); if fs::metadata(path).map_err(f)?.is_dir() { diff --git a/cli/src/trace.rs b/cli/src/trace.rs new file mode 100644 index 00000000..0b37c5fc --- /dev/null +++ b/cli/src/trace.rs @@ -0,0 +1,135 @@ +use std::fs::File; +use std::io::{BufReader, BufWriter, Error, ErrorKind, 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::fmt; +use tracing_subscriber::prelude::*; + +use crate::args::CliArguments; + +/// Will flush the flamegraph to disk when dropped. +pub struct TracingGuard { + flush_guard: Option<FlushGuard<BufWriter<File>>>, + temp_file: File, + output_svg: PathBuf, +} + +impl TracingGuard { + pub fn finish(&mut self) -> Result<(), Error> { + 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| Error::new(ErrorKind::Other, e))?; + + Ok(()) + } +} + +impl Drop for TracingGuard { + fn drop(&mut self) { + if !std::thread::panicking() { + if let Err(e) = self.finish() { + // Since we are finished, we cannot rely on tracing to log the + // error. + eprintln!("Failed to flush tracing flamegraph: {e}"); + } + } + } +} + +/// Initializes the tracing system and returns a guard that will flush the +/// flamegraph to disk when dropped. +pub fn init_tracing(args: &CliArguments) -> Result<Option<TracingGuard>, Error> { + let flamegraph = args.command.as_compile().and_then(|c| c.flamegraph.as_ref()); + + if flamegraph.is_some() && args.command.is_watch() { + return Err(Error::new( + ErrorKind::InvalidInput, + "cannot use --flamegraph with watch command", + )); + } + + // 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::WARN, + 1 => LevelFilter::INFO, + 2 => LevelFilter::DEBUG, + _ => LevelFilter::TRACE, + } +} diff --git a/library/Cargo.toml b/library/Cargo.toml index aa752c75..d23a2f41 100644 --- a/library/Cargo.toml +++ b/library/Cargo.toml @@ -39,3 +39,4 @@ unicode-script = "0.5" unicode-segmentation = "1" xi-unicode = "0.3" chinese-number = { version = "0.7.1", default-features = false, features = ["number-to-chinese"] } +tracing = "0.1.37" diff --git a/library/src/layout/align.rs b/library/src/layout/align.rs index c2f8262e..b8f7a086 100644 --- a/library/src/layout/align.rs +++ b/library/src/layout/align.rs @@ -58,6 +58,7 @@ pub struct AlignElem { } impl Show for AlignElem { + #[tracing::instrument(name = "AlignElem::show", skip_all)] fn show(&self, _: &mut Vt, styles: StyleChain) -> SourceResult<Content> { Ok(self .body() diff --git a/library/src/layout/columns.rs b/library/src/layout/columns.rs index 3a1b012a..2a587907 100644 --- a/library/src/layout/columns.rs +++ b/library/src/layout/columns.rs @@ -50,6 +50,7 @@ pub struct ColumnsElem { } impl Layout for ColumnsElem { + #[tracing::instrument(name = "ColumnsElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/layout/container.rs b/library/src/layout/container.rs index 9bf1bf87..ae6a094c 100644 --- a/library/src/layout/container.rs +++ b/library/src/layout/container.rs @@ -99,6 +99,7 @@ pub struct BoxElem { } impl Layout for BoxElem { + #[tracing::instrument(name = "BoxElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -326,6 +327,7 @@ pub struct BlockElem { } impl Layout for BlockElem { + #[tracing::instrument(name = "BlockElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/layout/enum.rs b/library/src/layout/enum.rs index ce65b14c..76942c27 100644 --- a/library/src/layout/enum.rs +++ b/library/src/layout/enum.rs @@ -154,6 +154,7 @@ pub struct EnumElem { } impl Layout for EnumElem { + #[tracing::instrument(name = "EnumElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/layout/flow.rs b/library/src/layout/flow.rs index b45c39c2..64d1d509 100644 --- a/library/src/layout/flow.rs +++ b/library/src/layout/flow.rs @@ -19,6 +19,7 @@ pub struct FlowElem { } impl Layout for FlowElem { + #[tracing::instrument(name = "FlowElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -122,6 +123,7 @@ impl<'a> FlowLayouter<'a> { } /// Layout vertical spacing. + #[tracing::instrument(name = "FlowLayouter::layout_spacing", skip_all)] fn layout_spacing(&mut self, v: &VElem, styles: StyleChain) { self.layout_item(match v.amount() { Spacing::Rel(rel) => FlowItem::Absolute( @@ -133,6 +135,7 @@ impl<'a> FlowLayouter<'a> { } /// Layout a paragraph. + #[tracing::instrument(name = "FlowLayouter::layout_par", skip_all)] fn layout_par( &mut self, vt: &mut Vt, @@ -179,6 +182,7 @@ impl<'a> FlowLayouter<'a> { } /// Layout into a single region. + #[tracing::instrument(name = "FlowLayouter::layout_single", skip_all)] fn layout_single( &mut self, vt: &mut Vt, @@ -237,6 +241,7 @@ impl<'a> FlowLayouter<'a> { } /// Layout a finished frame. + #[tracing::instrument(name = "FlowLayouter::layout_item", skip_all)] fn layout_item(&mut self, item: FlowItem) { match item { FlowItem::Absolute(v, _) => self.regions.size.y -= v, diff --git a/library/src/layout/grid.rs b/library/src/layout/grid.rs index 01bf7e30..63183e1d 100644 --- a/library/src/layout/grid.rs +++ b/library/src/layout/grid.rs @@ -102,6 +102,7 @@ pub struct GridElem { } impl Layout for GridElem { + #[tracing::instrument(name = "GridElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -289,6 +290,7 @@ impl<'a, 'v> GridLayouter<'a, 'v> { } /// Determines the columns sizes and then layouts the grid row-by-row. + #[tracing::instrument(name = "grid layout", skip(self))] pub fn layout(mut self) -> SourceResult<GridLayout> { self.measure_columns()?; diff --git a/library/src/layout/hide.rs b/library/src/layout/hide.rs index d9bee317..a65616a0 100644 --- a/library/src/layout/hide.rs +++ b/library/src/layout/hide.rs @@ -23,6 +23,7 @@ pub struct HideElem { } impl Show for HideElem { + #[tracing::instrument(name = "HideElem::show", skip(self))] fn show(&self, _: &mut Vt, _: StyleChain) -> SourceResult<Content> { Ok(self.body().styled(MetaElem::set_data(vec![Meta::Hide]))) } diff --git a/library/src/layout/list.rs b/library/src/layout/list.rs index 6cb1bc7e..c8aeaa06 100644 --- a/library/src/layout/list.rs +++ b/library/src/layout/list.rs @@ -112,6 +112,7 @@ pub struct ListElem { } impl Layout for ListElem { + #[tracing::instrument(name = "ListElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/layout/mod.rs b/library/src/layout/mod.rs index e84e35fc..25014498 100644 --- a/library/src/layout/mod.rs +++ b/library/src/layout/mod.rs @@ -68,6 +68,7 @@ pub trait LayoutRoot { } impl LayoutRoot for Content { + #[tracing::instrument(name = "Content::layout_root", skip_all)] fn layout_root(&self, vt: &mut Vt, styles: StyleChain) -> SourceResult<Document> { #[comemo::memoize] fn cached( @@ -87,6 +88,8 @@ impl LayoutRoot for Content { .layout_root(&mut vt, styles) } + tracing::info!("Starting layout"); + cached( self, vt.world, @@ -126,6 +129,7 @@ pub trait Layout { } impl Layout for Content { + #[tracing::instrument(name = "Content::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -151,6 +155,8 @@ impl Layout for Content { .layout(&mut vt, styles, regions) } + tracing::info!("Layouting `Content`"); + cached( self, vt.world, @@ -164,6 +170,7 @@ impl Layout for Content { } /// Realize into an element that is capable of root-level layout. +#[tracing::instrument(skip_all)] fn realize_root<'a>( vt: &mut Vt, scratch: &'a Scratch<'a>, @@ -245,6 +252,7 @@ impl<'a, 'v, 't> Builder<'a, 'v, 't> { } } + #[tracing::instrument(skip_all)] fn accept( &mut self, mut content: &'a Content, @@ -310,6 +318,7 @@ impl<'a, 'v, 't> Builder<'a, 'v, 't> { } } + #[tracing::instrument(skip_all)] fn styled( &mut self, elem: &'a Content, @@ -324,6 +333,7 @@ impl<'a, 'v, 't> Builder<'a, 'v, 't> { Ok(()) } + #[tracing::instrument(skip(self, local, outer))] fn interrupt_style( &mut self, local: &Styles, @@ -358,6 +368,7 @@ impl<'a, 'v, 't> Builder<'a, 'v, 't> { Ok(()) } + #[tracing::instrument(skip(self))] fn interrupt_list(&mut self) -> SourceResult<()> { if !self.list.items.is_empty() { let staged = mem::take(&mut self.list.staged); @@ -371,6 +382,7 @@ impl<'a, 'v, 't> Builder<'a, 'v, 't> { Ok(()) } + #[tracing::instrument(skip(self))] fn interrupt_par(&mut self) -> SourceResult<()> { self.interrupt_list()?; if !self.par.0.is_empty() { @@ -382,6 +394,7 @@ impl<'a, 'v, 't> Builder<'a, 'v, 't> { Ok(()) } + #[tracing::instrument(skip_all)] fn interrupt_page(&mut self, styles: Option<StyleChain<'a>>) -> SourceResult<()> { self.interrupt_par()?; let Some(doc) = &mut self.doc else { return Ok(()) }; diff --git a/library/src/layout/pad.rs b/library/src/layout/pad.rs index 441aa211..a4e79e36 100644 --- a/library/src/layout/pad.rs +++ b/library/src/layout/pad.rs @@ -60,6 +60,7 @@ pub struct PadElem { } impl Layout for PadElem { + #[tracing::instrument(name = "PadElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/layout/page.rs b/library/src/layout/page.rs index 0c70282d..7fa0bc5e 100644 --- a/library/src/layout/page.rs +++ b/library/src/layout/page.rs @@ -272,7 +272,10 @@ pub struct PageElem { impl PageElem { /// Layout the page run into a sequence of frames, one per page. + #[tracing::instrument(skip_all)] pub fn layout(&self, vt: &mut Vt, styles: StyleChain) -> SourceResult<Fragment> { + 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()); @@ -330,12 +333,20 @@ impl PageElem { ); // Realize overlays. - for frame in &mut fragment { + for (i, frame) in fragment.iter_mut().enumerate() { + tracing::info!("Layouting page #{i}"); frame.prepend(Point::zero(), numbering_meta.clone()); let size = frame.size(); let pad = padding.resolve(styles).relative_to(size); let pw = size.x - pad.left - pad.right; - for marginal in [&header, &footer, &background, &foreground] { + for (name, marginal) in [ + ("header", &header), + ("footer", &footer), + ("background", &background), + ("foreground", &foreground), + ] { + tracing::info!("Layouting {name}"); + let Some(content) = marginal else { continue }; let (pos, area, align); diff --git a/library/src/layout/par.rs b/library/src/layout/par.rs index 8bede473..b186bb19 100644 --- a/library/src/layout/par.rs +++ b/library/src/layout/par.rs @@ -126,6 +126,7 @@ impl Construct for ParElem { impl ParElem { /// Layout the paragraph into a collection of lines. + #[tracing::instrument(name = "ParElement::layout", skip_all)] pub fn layout( &self, vt: &mut Vt, diff --git a/library/src/layout/place.rs b/library/src/layout/place.rs index 057278df..2a671628 100644 --- a/library/src/layout/place.rs +++ b/library/src/layout/place.rs @@ -54,6 +54,7 @@ pub struct PlaceElem { } impl Layout for PlaceElem { + #[tracing::instrument(name = "PlaceElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/layout/repeat.rs b/library/src/layout/repeat.rs index 4a05500e..384995a4 100644 --- a/library/src/layout/repeat.rs +++ b/library/src/layout/repeat.rs @@ -34,6 +34,7 @@ pub struct RepeatElem { } impl Layout for RepeatElem { + #[tracing::instrument(name = "RepeatElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/layout/stack.rs b/library/src/layout/stack.rs index b1f7f59d..80145567 100644 --- a/library/src/layout/stack.rs +++ b/library/src/layout/stack.rs @@ -38,6 +38,7 @@ pub struct StackElem { } impl Layout for StackElem { + #[tracing::instrument(name = "StackElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -161,6 +162,7 @@ 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) => { @@ -184,6 +186,7 @@ impl<'a> StackLayouter<'a> { } /// Layout an arbitrary block. + #[tracing::instrument(name = "StackLayouter::layout_block", skip_all)] fn layout_block( &mut self, vt: &mut Vt, diff --git a/library/src/layout/table.rs b/library/src/layout/table.rs index acababb8..9ca6a137 100644 --- a/library/src/layout/table.rs +++ b/library/src/layout/table.rs @@ -122,6 +122,7 @@ pub struct TableElem { } impl Layout for TableElem { + #[tracing::instrument(name = "TableElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/layout/terms.rs b/library/src/layout/terms.rs index 45ba82b5..ecda7668 100644 --- a/library/src/layout/terms.rs +++ b/library/src/layout/terms.rs @@ -92,6 +92,7 @@ pub struct TermsElem { } impl Layout for TermsElem { + #[tracing::instrument(name = "TermsElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/layout/transform.rs b/library/src/layout/transform.rs index b57ca41e..2fb9c191 100644 --- a/library/src/layout/transform.rs +++ b/library/src/layout/transform.rs @@ -37,6 +37,7 @@ pub struct MoveElem { } impl Layout for MoveElem { + #[tracing::instrument(name = "MoveElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -105,6 +106,7 @@ pub struct RotateElem { } impl Layout for RotateElem { + #[tracing::instrument(name = "RotateElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -173,6 +175,7 @@ pub struct ScaleElem { } impl Layout for ScaleElem { + #[tracing::instrument(name = "ScaleElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/lib.rs b/library/src/lib.rs index 3254dfd8..98ec121a 100644 --- a/library/src/lib.rs +++ b/library/src/lib.rs @@ -29,6 +29,7 @@ pub fn build() -> Library { } /// Construct the module with global definitions. +#[tracing::instrument(skip_all)] fn global(math: Module, calc: Module) -> Module { let mut global = Scope::deduplicating(); diff --git a/library/src/math/accent.rs b/library/src/math/accent.rs index 03263c3c..1cd84429 100644 --- a/library/src/math/accent.rs +++ b/library/src/math/accent.rs @@ -52,6 +52,7 @@ pub struct AccentElem { } impl LayoutMath for AccentElem { + #[tracing::instrument(skip(ctx))] 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/library/src/math/align.rs b/library/src/math/align.rs index 03abeac2..bbdda5fd 100644 --- a/library/src/math/align.rs +++ b/library/src/math/align.rs @@ -8,6 +8,7 @@ use super::*; 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/library/src/math/attach.rs b/library/src/math/attach.rs index c90b4945..dcf7fb78 100644 --- a/library/src/math/attach.rs +++ b/library/src/math/attach.rs @@ -27,6 +27,7 @@ pub struct AttachElem { } impl LayoutMath for AttachElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let base = self.base(); let display_limits = base.is::<LimitsElem>(); @@ -83,6 +84,7 @@ pub struct ScriptsElem { } impl LayoutMath for ScriptsElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { self.body().layout_math(ctx) } @@ -105,6 +107,7 @@ pub struct LimitsElem { } impl LayoutMath for LimitsElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { self.body().layout_math(ctx) } diff --git a/library/src/math/delimited.rs b/library/src/math/delimited.rs index fe7d2d1e..3726aa15 100644 --- a/library/src/math/delimited.rs +++ b/library/src/math/delimited.rs @@ -39,6 +39,7 @@ pub struct LrElem { } impl LayoutMath for LrElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let mut body = self.body(); if let Some(elem) = body.to::<LrElem>() { diff --git a/library/src/math/frac.rs b/library/src/math/frac.rs index 7520e10d..f93ee888 100644 --- a/library/src/math/frac.rs +++ b/library/src/math/frac.rs @@ -30,6 +30,7 @@ pub struct FracElem { } impl LayoutMath for FracElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout(ctx, &self.num(), &self.denom(), false, self.span()) } diff --git a/library/src/math/matrix.rs b/library/src/math/matrix.rs index 368cd5c4..2243eb38 100644 --- a/library/src/math/matrix.rs +++ b/library/src/math/matrix.rs @@ -33,6 +33,7 @@ pub struct VecElem { } impl LayoutMath for VecElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let delim = self.delim(ctx.styles()); let frame = layout_vec_body(ctx, &self.children(), Align::Center)?; @@ -115,6 +116,7 @@ pub struct MatElem { } impl LayoutMath for MatElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let delim = self.delim(ctx.styles()); let frame = layout_mat_body(ctx, &self.rows())?; @@ -161,6 +163,7 @@ pub struct CasesElem { } impl LayoutMath for CasesElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let delim = self.delim(ctx.styles()); let frame = layout_vec_body(ctx, &self.children(), Align::Left)?; diff --git a/library/src/math/mod.rs b/library/src/math/mod.rs index 48fe52d2..63bfdbbe 100644 --- a/library/src/math/mod.rs +++ b/library/src/math/mod.rs @@ -173,6 +173,7 @@ impl Synthesize for EquationElem { } impl Show for EquationElem { + #[tracing::instrument(name = "EquationElem::show", skip_all)] fn show(&self, _: &mut Vt, styles: StyleChain) -> SourceResult<Content> { let mut realized = self.clone().pack().guarded(Guard::Base(Self::func())); if self.block(styles) { @@ -193,6 +194,7 @@ impl Finalize for EquationElem { } impl Layout for EquationElem { + #[tracing::instrument(name = "EquationElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -340,12 +342,14 @@ pub trait LayoutMath { } impl LayoutMath for EquationElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { self.body().layout_math(ctx) } } impl LayoutMath for Content { + #[tracing::instrument(skip(ctx))] 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/library/src/math/op.rs b/library/src/math/op.rs index 5ea4519c..699d326a 100644 --- a/library/src/math/op.rs +++ b/library/src/math/op.rs @@ -34,6 +34,7 @@ pub struct OpElem { } impl LayoutMath for OpElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let fragment = ctx.layout_text(&TextElem::new(self.text()).spanned(self.span()))?; diff --git a/library/src/math/root.rs b/library/src/math/root.rs index cc48cd74..8b272160 100644 --- a/library/src/math/root.rs +++ b/library/src/math/root.rs @@ -39,6 +39,7 @@ pub struct RootElem { } impl LayoutMath for RootElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout(ctx, self.index(ctx.styles()).as_ref(), &self.radicand(), self.span()) } diff --git a/library/src/math/style.rs b/library/src/math/style.rs index 2cd29175..eb6472ee 100644 --- a/library/src/math/style.rs +++ b/library/src/math/style.rs @@ -199,6 +199,7 @@ pub struct MathStyleElem { } impl LayoutMath for MathStyleElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { let mut style = ctx.style; if let Some(variant) = self.variant(StyleChain::default()) { diff --git a/library/src/math/underover.rs b/library/src/math/underover.rs index a8d7b71c..5282c6dc 100644 --- a/library/src/math/underover.rs +++ b/library/src/math/underover.rs @@ -21,6 +21,7 @@ pub struct UnderlineElem { } impl LayoutMath for UnderlineElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout(ctx, &self.body(), &None, '\u{305}', LINE_GAP, false, self.span()) } @@ -43,6 +44,7 @@ pub struct OverlineElem { } impl LayoutMath for OverlineElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout(ctx, &self.body(), &None, '\u{332}', LINE_GAP, true, self.span()) } @@ -69,6 +71,7 @@ pub struct UnderbraceElem { } impl LayoutMath for UnderbraceElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout( ctx, @@ -103,6 +106,7 @@ pub struct OverbraceElem { } impl LayoutMath for OverbraceElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout( ctx, @@ -137,6 +141,7 @@ pub struct UnderbracketElem { } impl LayoutMath for UnderbracketElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout( ctx, @@ -171,6 +176,7 @@ pub struct OverbracketElem { } impl LayoutMath for OverbracketElem { + #[tracing::instrument(skip(ctx))] fn layout_math(&self, ctx: &mut MathContext) -> SourceResult<()> { layout( ctx, diff --git a/library/src/meta/bibliography.rs b/library/src/meta/bibliography.rs index 2f9a099e..f35264af 100644 --- a/library/src/meta/bibliography.rs +++ b/library/src/meta/bibliography.rs @@ -140,6 +140,7 @@ impl Synthesize for BibliographyElem { } impl Show for BibliographyElem { + #[tracing::instrument(name = "BibliographyElem::show", skip_all)] fn show(&self, vt: &mut Vt, styles: StyleChain) -> SourceResult<Content> { const COLUMN_GUTTER: Em = Em::new(0.65); const INDENT: Em = Em::new(1.5); @@ -336,6 +337,7 @@ impl Synthesize for CiteElem { } impl Show for CiteElem { + #[tracing::instrument(name = "CiteElem::show", skip(self, vt))] fn show(&self, vt: &mut Vt, _: StyleChain) -> SourceResult<Content> { if !vt.introspector.init() { return Ok(Content::empty()); diff --git a/library/src/meta/context.rs b/library/src/meta/context.rs index 710347f4..7bc57e97 100644 --- a/library/src/meta/context.rs +++ b/library/src/meta/context.rs @@ -72,6 +72,7 @@ struct LocateElem { } impl Show for LocateElem { + #[tracing::instrument(name = "LocateElem::show", skip(self, vt))] fn show(&self, vt: &mut Vt, _: StyleChain) -> SourceResult<Content> { if !vt.introspector.init() { return Ok(Content::empty()); @@ -127,6 +128,7 @@ struct StyleElem { } impl Show for StyleElem { + #[tracing::instrument(name = "StyleElem::show", skip_all)] fn show(&self, vt: &mut Vt, styles: StyleChain) -> SourceResult<Content> { Ok(self.func().call_vt(vt, [styles.to_map().into()])?.display()) } @@ -204,6 +206,7 @@ struct LayoutElem { } impl Layout for LayoutElem { + #[tracing::instrument(name = "LayoutElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/meta/counter.rs b/library/src/meta/counter.rs index b1d2e3bd..394c4656 100644 --- a/library/src/meta/counter.rs +++ b/library/src/meta/counter.rs @@ -302,6 +302,7 @@ impl Counter { } /// Call a method on counter. + #[tracing::instrument(skip(vm))] pub fn call_method( self, vm: &mut Vm, @@ -618,6 +619,7 @@ struct DisplayElem { } impl Show for DisplayElem { + #[tracing::instrument(name = "DisplayElem::show", skip_all)] fn show(&self, vt: &mut Vt, styles: StyleChain) -> SourceResult<Content> { if !vt.introspector.init() { return Ok(Content::empty()); @@ -669,6 +671,7 @@ struct UpdateElem { } impl Show for UpdateElem { + #[tracing::instrument(name = "UpdateElem::show", skip(self))] fn show(&self, _: &mut Vt, _: StyleChain) -> SourceResult<Content> { Ok(Content::empty()) } diff --git a/library/src/meta/document.rs b/library/src/meta/document.rs index bb42faaf..5319eefa 100644 --- a/library/src/meta/document.rs +++ b/library/src/meta/document.rs @@ -43,7 +43,10 @@ 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)] fn layout_root(&self, vt: &mut Vt, styles: StyleChain) -> SourceResult<Document> { + tracing::info!("Document layout"); + let mut pages = vec![]; for mut child in &self.children() { diff --git a/library/src/meta/figure.rs b/library/src/meta/figure.rs index 1f1499fc..d86625b7 100644 --- a/library/src/meta/figure.rs +++ b/library/src/meta/figure.rs @@ -237,6 +237,7 @@ impl Synthesize for FigureElem { } impl Show for FigureElem { + #[tracing::instrument(name = "FigureElem::show", skip_all)] fn show(&self, vt: &mut Vt, styles: StyleChain) -> SourceResult<Content> { // We build the body of the figure. let mut realized = self.body(); diff --git a/library/src/meta/heading.rs b/library/src/meta/heading.rs index f3d0e337..ad836363 100644 --- a/library/src/meta/heading.rs +++ b/library/src/meta/heading.rs @@ -108,6 +108,7 @@ impl Synthesize for HeadingElem { } impl Show for HeadingElem { + #[tracing::instrument(name = "HeadingElem::show", skip_all)] fn show(&self, _: &mut Vt, styles: StyleChain) -> SourceResult<Content> { let mut realized = self.body(); if let Some(numbering) = self.numbering(styles) { diff --git a/library/src/meta/link.rs b/library/src/meta/link.rs index 135ce0af..aaf2476a 100644 --- a/library/src/meta/link.rs +++ b/library/src/meta/link.rs @@ -88,6 +88,7 @@ impl LinkElem { } impl Show for LinkElem { + #[tracing::instrument(name = "LinkElem::show", skip(self, vt))] fn show(&self, vt: &mut Vt, _: StyleChain) -> SourceResult<Content> { let body = self.body(); let dest = match self.dest() { diff --git a/library/src/meta/outline.rs b/library/src/meta/outline.rs index f65168c7..a5c7a5de 100644 --- a/library/src/meta/outline.rs +++ b/library/src/meta/outline.rs @@ -131,6 +131,7 @@ pub struct OutlineElem { } impl Show for OutlineElem { + #[tracing::instrument(name = "OutlineElem::show", skip_all)] fn show(&self, vt: &mut Vt, styles: StyleChain) -> SourceResult<Content> { let mut seq = vec![ParbreakElem::new().pack()]; // Build the outline title. diff --git a/library/src/meta/reference.rs b/library/src/meta/reference.rs index 4e1cfa7f..adbc9f57 100644 --- a/library/src/meta/reference.rs +++ b/library/src/meta/reference.rs @@ -146,6 +146,7 @@ impl Synthesize for RefElem { } impl Show for RefElem { + #[tracing::instrument(name = "RefElem::show", skip_all)] fn show(&self, vt: &mut Vt, styles: StyleChain) -> SourceResult<Content> { if !vt.introspector.init() { return Ok(Content::empty()); diff --git a/library/src/meta/state.rs b/library/src/meta/state.rs index 781d4294..dc67e2c4 100644 --- a/library/src/meta/state.rs +++ b/library/src/meta/state.rs @@ -256,6 +256,7 @@ pub struct State { impl State { /// Call a method on a state. + #[tracing::instrument(skip(vm))] pub fn call_method( self, vm: &mut Vm, @@ -280,6 +281,7 @@ impl State { } /// Get the value of the state at the given location. + #[tracing::instrument(skip(self, vt))] pub fn at(self, vt: &mut Vt, location: Location) -> SourceResult<Value> { let sequence = self.sequence(vt)?; let offset = vt @@ -290,6 +292,7 @@ impl State { } /// Get the value of the state at the final location. + #[tracing::instrument(skip(self, vt))] pub fn final_(self, vt: &mut Vt, _: Location) -> SourceResult<Value> { let sequence = self.sequence(vt)?; Ok(sequence.last().unwrap().clone()) @@ -395,6 +398,7 @@ struct DisplayElem { } impl Show for DisplayElem { + #[tracing::instrument(name = "DisplayElem::show", skip(self, vt))] fn show(&self, vt: &mut Vt, _: StyleChain) -> SourceResult<Content> { if !vt.introspector.init() { return Ok(Content::empty()); @@ -425,6 +429,7 @@ struct UpdateElem { } impl Show for UpdateElem { + #[tracing::instrument(name = "UpdateElem::show")] fn show(&self, _: &mut Vt, _: StyleChain) -> SourceResult<Content> { Ok(Content::empty()) } diff --git a/library/src/text/deco.rs b/library/src/text/deco.rs index 7b90b22f..49bd3971 100644 --- a/library/src/text/deco.rs +++ b/library/src/text/deco.rs @@ -66,6 +66,7 @@ pub struct UnderlineElem { } impl Show for UnderlineElem { + #[tracing::instrument(name = "UnderlineElem::show", skip_all)] fn show(&self, _: &mut Vt, styles: StyleChain) -> SourceResult<Content> { Ok(self.body().styled(TextElem::set_deco(Decoration { line: DecoLine::Underline, @@ -145,6 +146,7 @@ pub struct OverlineElem { } impl Show for OverlineElem { + #[tracing::instrument(name = "OverlineElem::show", skip_all)] fn show(&self, _: &mut Vt, styles: StyleChain) -> SourceResult<Content> { Ok(self.body().styled(TextElem::set_deco(Decoration { line: DecoLine::Overline, @@ -209,6 +211,7 @@ pub struct StrikeElem { } impl Show for StrikeElem { + #[tracing::instrument(name = "StrikeElem::show", skip_all)] fn show(&self, _: &mut Vt, styles: StyleChain) -> SourceResult<Content> { Ok(self.body().styled(TextElem::set_deco(Decoration { line: DecoLine::Strikethrough, diff --git a/library/src/text/misc.rs b/library/src/text/misc.rs index a707d130..fa3a99fa 100644 --- a/library/src/text/misc.rs +++ b/library/src/text/misc.rs @@ -105,6 +105,7 @@ pub struct StrongElem { } impl Show for StrongElem { + #[tracing::instrument(name = "StrongElem::show", skip_all)] fn show(&self, _: &mut Vt, styles: StyleChain) -> SourceResult<Content> { Ok(self.body().styled(TextElem::set_delta(Delta(self.delta(styles))))) } @@ -165,6 +166,7 @@ pub struct EmphElem { } impl Show for EmphElem { + #[tracing::instrument(name = "EmphElem::show", skip(self))] fn show(&self, _: &mut Vt, _: StyleChain) -> SourceResult<Content> { Ok(self.body().styled(TextElem::set_emph(Toggle))) } diff --git a/library/src/text/raw.rs b/library/src/text/raw.rs index 6d90bc5b..6cd1fc12 100644 --- a/library/src/text/raw.rs +++ b/library/src/text/raw.rs @@ -129,6 +129,7 @@ impl Synthesize for RawElem { } impl Show for RawElem { + #[tracing::instrument(name = "RawElem::show", skip_all)] fn show(&self, _: &mut Vt, styles: StyleChain) -> SourceResult<Content> { let text = self.text(); let lang = self.lang(styles).as_ref().map(|s| s.to_lowercase()); diff --git a/library/src/text/shift.rs b/library/src/text/shift.rs index 26978b87..4eac5897 100644 --- a/library/src/text/shift.rs +++ b/library/src/text/shift.rs @@ -45,6 +45,7 @@ pub struct SubElem { } impl Show for SubElem { + #[tracing::instrument(name = "SubElem::show", skip_all)] fn show(&self, vt: &mut Vt, styles: StyleChain) -> SourceResult<Content> { let body = self.body(); let mut transformed = None; @@ -107,6 +108,7 @@ pub struct SuperElem { } impl Show for SuperElem { + #[tracing::instrument(name = "SuperElem::show", skip_all)] fn show(&self, vt: &mut Vt, styles: StyleChain) -> SourceResult<Content> { let body = self.body(); let mut transformed = None; diff --git a/library/src/visualize/image.rs b/library/src/visualize/image.rs index 86f87931..3d51743a 100644 --- a/library/src/visualize/image.rs +++ b/library/src/visualize/image.rs @@ -52,6 +52,7 @@ pub struct ImageElem { } impl Layout for ImageElem { + #[tracing::instrument(name = "ImageElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, diff --git a/library/src/visualize/line.rs b/library/src/visualize/line.rs index 362f1a89..0555ddec 100644 --- a/library/src/visualize/line.rs +++ b/library/src/visualize/line.rs @@ -73,6 +73,7 @@ pub struct LineElem { } impl Layout for LineElem { + #[tracing::instrument(name = "LineElem::layout", skip_all)] fn layout( &self, _: &mut Vt, diff --git a/library/src/visualize/path.rs b/library/src/visualize/path.rs index db062093..2ef2bc1a 100644 --- a/library/src/visualize/path.rs +++ b/library/src/visualize/path.rs @@ -60,6 +60,7 @@ pub struct PathElem { } impl Layout for PathElem { + #[tracing::instrument(name = "PathElem::layout", skip_all)] fn layout( &self, _: &mut Vt, diff --git a/library/src/visualize/polygon.rs b/library/src/visualize/polygon.rs index 559ebec3..ee2a6b51 100644 --- a/library/src/visualize/polygon.rs +++ b/library/src/visualize/polygon.rs @@ -49,6 +49,7 @@ pub struct PolygonElem { } impl Layout for PolygonElem { + #[tracing::instrument(name = "PolygonElem::layout", skip_all)] fn layout( &self, _: &mut Vt, diff --git a/library/src/visualize/shape.rs b/library/src/visualize/shape.rs index 48c4d7a3..e9697676 100644 --- a/library/src/visualize/shape.rs +++ b/library/src/visualize/shape.rs @@ -154,6 +154,7 @@ pub struct RectElem { } impl Layout for RectElem { + #[tracing::instrument(name = "RectElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -264,6 +265,7 @@ pub struct SquareElem { } impl Layout for SquareElem { + #[tracing::instrument(name = "SquareElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -346,6 +348,7 @@ pub struct EllipseElem { } impl Layout for EllipseElem { + #[tracing::instrument(name = "EllipseElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -453,6 +456,7 @@ pub struct CircleElem { } impl Layout for CircleElem { + #[tracing::instrument(name = "CircleElem::layout", skip_all)] fn layout( &self, vt: &mut Vt, @@ -477,6 +481,7 @@ impl Layout for CircleElem { } /// Layout a shape. +#[tracing::instrument(name = "shape::layout", skip_all)] #[allow(clippy::too_many_arguments)] fn layout( vt: &mut Vt, diff --git a/src/eval/func.rs b/src/eval/func.rs index 29b85f7a..489527ef 100644 --- a/src/eval/func.rs +++ b/src/eval/func.rs @@ -75,6 +75,12 @@ impl Func { /// Call the function with the given arguments. pub fn call_vm(&self, vm: &mut Vm, mut args: Args) -> SourceResult<Value> { + let _span = tracing::info_span!( + "call", + name = self.name().unwrap_or("<anon>"), + file = 0, + ); + match &self.repr { Repr::Native(native) => { let value = (native.func)(vm, &mut args)?; @@ -111,6 +117,7 @@ impl Func { } /// Call the function with a Vt. + #[tracing::instrument(skip_all)] pub fn call_vt( &self, vt: &mut Vt, @@ -281,6 +288,7 @@ pub enum Param { impl Closure { /// Call the function in the context with the arguments. #[comemo::memoize] + #[tracing::instrument(skip_all)] #[allow(clippy::too_many_arguments)] fn call( this: &Func, @@ -399,6 +407,7 @@ 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/src/eval/mod.rs b/src/eval/mod.rs index 0a963faf..05a43404 100644 --- a/src/eval/mod.rs +++ b/src/eval/mod.rs @@ -64,6 +64,7 @@ const MAX_CALL_DEPTH: usize = 64; /// Evaluate a source file and return the resulting module. #[comemo::memoize] +#[tracing::instrument(skip(world, route, tracer, source))] pub fn eval( world: Tracked<dyn World>, route: Tracked<Route>, @@ -203,6 +204,7 @@ 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 Into<Value>) { let value = value.into(); if self.traced == Some(var.span()) { @@ -213,6 +215,7 @@ impl<'a> Vm<'a> { /// Resolve a user-entered path to be relative to the compilation /// environment's root. + #[tracing::instrument(skip_all)] pub fn locate(&self, path: &str) -> StrResult<PathBuf> { if !self.location.is_detached() { if let Some(path) = path.strip_prefix('/') { @@ -402,6 +405,7 @@ fn eval_markup( impl Eval for ast::Expr { type Output = Value; + #[tracing::instrument(name = "Expr::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let span = self.span(); let forbidden = |name| { @@ -482,6 +486,7 @@ impl ast::Expr { impl Eval for ast::Text { type Output = Content; + #[tracing::instrument(name = "Text::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { Ok((vm.items.text)(self.get().clone())) } @@ -490,6 +495,7 @@ impl Eval for ast::Text { impl Eval for ast::Space { type Output = Content; + #[tracing::instrument(name = "Space::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { Ok((vm.items.space)()) } @@ -498,6 +504,7 @@ impl Eval for ast::Space { impl Eval for ast::Linebreak { type Output = Content; + #[tracing::instrument(name = "Linebreak::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { Ok((vm.items.linebreak)()) } @@ -506,6 +513,7 @@ impl Eval for ast::Linebreak { impl Eval for ast::Parbreak { type Output = Content; + #[tracing::instrument(name = "Parbreak::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { Ok((vm.items.parbreak)()) } @@ -514,6 +522,7 @@ 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<Self::Output> { Ok(Value::Symbol(Symbol::new(self.get()))) } @@ -522,6 +531,7 @@ 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<Self::Output> { Ok(Value::Symbol(Symbol::new(self.get()))) } @@ -530,6 +540,7 @@ impl Eval for ast::Shorthand { impl Eval for ast::SmartQuote { type Output = Content; + #[tracing::instrument(name = "SmartQuote::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { Ok((vm.items.smart_quote)(self.double())) } @@ -538,6 +549,7 @@ 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<Self::Output> { Ok((vm.items.strong)(self.body().eval(vm)?)) } @@ -546,6 +558,7 @@ 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<Self::Output> { Ok((vm.items.emph)(self.body().eval(vm)?)) } @@ -554,6 +567,7 @@ impl Eval for ast::Emph { impl Eval for ast::Raw { type Output = Content; + #[tracing::instrument(name = "Raw::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let text = self.text(); let lang = self.lang().map(Into::into); @@ -565,6 +579,7 @@ impl Eval for ast::Raw { impl Eval for ast::Link { type Output = Content; + #[tracing::instrument(name = "Link::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { Ok((vm.items.link)(self.get().clone())) } @@ -573,6 +588,7 @@ 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<Self::Output> { Ok(Value::Label(Label(self.get().into()))) } @@ -581,6 +597,7 @@ 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<Self::Output> { let label = Label(self.target().into()); let supplement = self.supplement().map(|block| block.eval(vm)).transpose()?; @@ -591,6 +608,7 @@ 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<Self::Output> { let level = self.level(); let body = self.body().eval(vm)?; @@ -601,6 +619,7 @@ 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<Self::Output> { Ok((vm.items.list_item)(self.body().eval(vm)?)) } @@ -609,6 +628,7 @@ 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<Self::Output> { let number = self.number(); let body = self.body().eval(vm)?; @@ -619,6 +639,7 @@ 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<Self::Output> { let term = self.term().eval(vm)?; let description = self.description().eval(vm)?; @@ -629,6 +650,7 @@ 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<Self::Output> { let body = self.body().eval(vm)?; let block = self.block(); @@ -639,6 +661,7 @@ impl Eval for ast::Equation { impl Eval for ast::Math { type Output = Content; + #[tracing::instrument(name = "Math::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { Ok(Content::sequence( self.exprs() @@ -651,6 +674,7 @@ 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<Self::Output> { vm.scopes.get_in_math(self).cloned().at(self.span()) } @@ -659,6 +683,7 @@ impl Eval for ast::MathIdent { impl Eval for ast::MathAlignPoint { type Output = Content; + #[tracing::instrument(name = "MathAlignPoint::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { Ok((vm.items.math_align_point)()) } @@ -667,6 +692,7 @@ 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<Self::Output> { let open = self.open().eval_display(vm)?; let body = self.body().eval(vm)?; @@ -678,6 +704,7 @@ 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<Self::Output> { let base = self.base().eval_display(vm)?; let bottom = self.bottom().map(|expr| expr.eval_display(vm)).transpose()?; @@ -689,6 +716,7 @@ impl Eval for ast::MathAttach { impl Eval for ast::MathFrac { type Output = Content; + #[tracing::instrument(name = "MathFrac::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let num = self.num().eval_display(vm)?; let denom = self.denom().eval_display(vm)?; @@ -699,6 +727,7 @@ impl Eval for ast::MathFrac { impl Eval for ast::Ident { type Output = Value; + #[tracing::instrument(name = "Ident::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { vm.scopes.get(self).cloned().at(self.span()) } @@ -707,6 +736,7 @@ 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<Self::Output> { Ok(Value::None) } @@ -715,6 +745,7 @@ 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<Self::Output> { Ok(Value::Auto) } @@ -723,6 +754,7 @@ 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<Self::Output> { Ok(Value::Bool(self.get())) } @@ -731,6 +763,7 @@ 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<Self::Output> { Ok(Value::Int(self.get())) } @@ -739,6 +772,7 @@ 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<Self::Output> { Ok(Value::Float(self.get())) } @@ -747,6 +781,7 @@ 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<Self::Output> { Ok(Value::numeric(self.get())) } @@ -755,6 +790,7 @@ 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<Self::Output> { Ok(Value::Str(self.get().into())) } @@ -763,6 +799,7 @@ impl Eval for ast::Str { impl Eval for ast::CodeBlock { type Output = Value; + #[tracing::instrument(name = "CodeBlock::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { vm.scopes.enter(); let output = self.body().eval(vm)?; @@ -828,6 +865,7 @@ fn eval_code( impl Eval for ast::ContentBlock { type Output = Content; + #[tracing::instrument(name = "ContentBlock::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { vm.scopes.enter(); let content = self.body().eval(vm)?; @@ -839,6 +877,7 @@ 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::Output> { self.expr().eval(vm) } @@ -847,6 +886,7 @@ impl Eval for ast::Parenthesized { impl Eval for ast::Array { type Output = Array; + #[tracing::instrument(skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let items = self.items(); @@ -869,6 +909,7 @@ impl Eval for ast::Array { impl Eval for ast::Dict { type Output = Dict; + #[tracing::instrument(skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let mut map = indexmap::IndexMap::new(); @@ -899,6 +940,7 @@ impl Eval for ast::Dict { impl Eval for ast::Unary { type Output = Value; + #[tracing::instrument(name = "Unary::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let value = self.expr().eval(vm)?; let result = match self.op() { @@ -913,6 +955,7 @@ 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<Self::Output> { match self.op() { ast::BinOp::Add => self.apply(vm, ops::add), @@ -987,6 +1030,7 @@ impl ast::Binary { impl Eval for ast::FieldAccess { type Output = Value; + #[tracing::instrument(name = "FieldAccess::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let value = self.target().eval(vm)?; let field = self.field(); @@ -997,6 +1041,7 @@ impl Eval for ast::FieldAccess { impl Eval for ast::FuncCall { type Output = Value; + #[tracing::instrument(name = "FuncCall::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let span = self.span(); if vm.depth >= MAX_CALL_DEPTH { @@ -1074,7 +1119,10 @@ impl Eval for ast::FuncCall { let callee = callee.cast::<Func>().at(callee_span)?; let point = || Tracepoint::Call(callee.name().map(Into::into)); - callee.call_vm(vm, args).trace(vm.world(), point, span) + + stacker::maybe_grow(32 * 1024, 2 * 1024 * 1024, || { + callee.call_vm(vm, args).trace(vm.world(), point, span) + }) } } @@ -1138,6 +1186,7 @@ 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<Self::Output> { // The closure's name is defined by its let binding if there's one. let name = self.name(); @@ -1179,6 +1228,7 @@ impl Eval for ast::Closure { impl ast::Pattern { // Destruct the given value into the pattern. + #[tracing::instrument(skip_all)] pub fn define(&self, vm: &mut Vm, value: Value) -> SourceResult<Value> { match self { ast::Pattern::Ident(ident) => { @@ -1274,6 +1324,7 @@ impl ast::Pattern { impl Eval for ast::LetBinding { type Output = Value; + #[tracing::instrument(name = "LetBinding::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let value = match self.init() { Some(expr) => expr.eval(vm)?, @@ -1339,6 +1390,7 @@ impl Eval for ast::ShowRule { impl Eval for ast::Conditional { type Output = Value; + #[tracing::instrument(name = "Conditional::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let condition = self.condition(); if condition.eval(vm)?.cast::<bool>().at(condition.span())? { @@ -1354,6 +1406,7 @@ impl Eval for ast::Conditional { impl Eval for ast::WhileLoop { type Output = Value; + #[tracing::instrument(name = "WhileLoop::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let flow = vm.flow.take(); let mut output = Value::None; @@ -1421,6 +1474,7 @@ fn can_diverge(expr: &SyntaxNode) -> bool { impl Eval for ast::ForLoop { type Output = Value; + #[tracing::instrument(name = "ForLoop::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let flow = vm.flow.take(); let mut output = Value::None; @@ -1487,6 +1541,7 @@ impl Eval for ast::ForLoop { impl Eval for ast::ModuleImport { type Output = Value; + #[tracing::instrument(name = "ModuleImport::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { let span = self.source().span(); let source = self.source().eval(vm)?; @@ -1523,6 +1578,7 @@ 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<Self::Output> { let span = self.source().span(); let source = self.source().eval(vm)?; @@ -1559,6 +1615,7 @@ fn import(vm: &mut Vm, source: Value, span: Span) -> SourceResult<Module> { impl Eval for ast::LoopBreak { type Output = Value; + #[tracing::instrument(name = "LoopBreak::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult<Self::Output> { if vm.flow.is_none() { vm.flow = Some(Flow::Break(self.span())); @@ -1570,6 +1627,7 @@ 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<Self::Output> { if vm.flow.is_none() { vm.flow = Some(Flow::Continue(self.span())); @@ -1581,6 +1639,7 @@ 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<Self::Output> { let value = self.body().map(|body| body.eval(vm)).transpose()?; if vm.flow.is_none() { diff --git a/src/eval/value.rs b/src/eval/value.rs index e0f03d27..0548c01f 100644 --- a/src/eval/value.rs +++ b/src/eval/value.rs @@ -310,6 +310,7 @@ where T::TYPE_NAME } + #[tracing::instrument(skip_all)] fn hash128(&self) -> u128 { // Also hash the TypeId since values with different types but // equal data should be different. diff --git a/src/export/pdf/font.rs b/src/export/pdf/font.rs index ada5e05d..de79976a 100644 --- a/src/export/pdf/font.rs +++ b/src/export/pdf/font.rs @@ -9,6 +9,7 @@ use super::{deflate, EmExt, PdfContext, RefExt}; use crate::util::SliceExt; /// Embed all used fonts into the PDF. +#[tracing::instrument(skip_all)] pub fn write_fonts(ctx: &mut PdfContext) { for font in ctx.font_map.items() { let type0_ref = ctx.alloc.bump(); diff --git a/src/export/pdf/image.rs b/src/export/pdf/image.rs index e6eaa9c9..04d4dcc3 100644 --- a/src/export/pdf/image.rs +++ b/src/export/pdf/image.rs @@ -7,6 +7,7 @@ use super::{deflate, PdfContext, RefExt}; use crate::image::{DecodedImage, RasterFormat}; /// Embed all used images into the PDF. +#[tracing::instrument(skip_all)] pub fn write_images(ctx: &mut PdfContext) { for image in ctx.image_map.items() { let image_ref = ctx.alloc.bump(); @@ -67,6 +68,7 @@ pub 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_image( format: RasterFormat, dynamic: &DynamicImage, @@ -111,6 +113,7 @@ fn encode_image( } /// Encode an image's alpha channel if present. +#[tracing::instrument(skip_all)] fn encode_alpha(dynamic: &DynamicImage) -> (Vec<u8>, Filter) { let pixels: Vec<_> = dynamic.pixels().map(|(_, _, Rgba([_, _, _, a]))| a).collect(); (deflate(&pixels), Filter::FlateDecode) diff --git a/src/export/pdf/mod.rs b/src/export/pdf/mod.rs index 8fc76471..ffbf67a3 100644 --- a/src/export/pdf/mod.rs +++ b/src/export/pdf/mod.rs @@ -23,6 +23,7 @@ use crate::model::Introspector; /// Export a document into a PDF file. /// /// Returns the raw bytes making up the PDF file. +#[tracing::instrument(skip_all)] pub fn pdf(document: &Document) -> Vec<u8> { let mut ctx = PdfContext::new(document); page::construct_pages(&mut ctx, &document.pages); @@ -79,6 +80,7 @@ impl<'a> PdfContext<'a> { } /// Write the document catalog. +#[tracing::instrument(skip_all)] fn write_catalog(ctx: &mut PdfContext) { let lang = ctx .languages @@ -140,6 +142,7 @@ fn write_catalog(ctx: &mut PdfContext) { } /// Compress data with the DEFLATE algorithm. +#[tracing::instrument(skip_all)] fn deflate(data: &[u8]) -> Vec<u8> { const COMPRESSION_LEVEL: u8 = 6; miniz_oxide::deflate::compress_to_vec_zlib(data, COMPRESSION_LEVEL) diff --git a/src/export/pdf/outline.rs b/src/export/pdf/outline.rs index 03ca3b27..f8f12d71 100644 --- a/src/export/pdf/outline.rs +++ b/src/export/pdf/outline.rs @@ -8,6 +8,7 @@ use crate::model::Content; use crate::util::NonZeroExt; /// Construct the outline for the document. +#[tracing::instrument(skip_all)] pub fn write_outline(ctx: &mut PdfContext) -> Option<Ref> { let mut tree: Vec<HeadingNode> = vec![]; for heading in ctx.introspector.query(&item!(heading_func).select()) { @@ -81,6 +82,7 @@ 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/src/export/pdf/page.rs b/src/export/pdf/page.rs index 94650a3f..e15f3750 100644 --- a/src/export/pdf/page.rs +++ b/src/export/pdf/page.rs @@ -15,6 +15,7 @@ use crate::geom::{ use crate::image::Image; /// Construct page objects. +#[tracing::instrument(skip_all)] pub fn construct_pages(ctx: &mut PdfContext, frames: &[Frame]) { for frame in frames { construct_page(ctx, frame); @@ -22,6 +23,7 @@ pub fn construct_pages(ctx: &mut PdfContext, frames: &[Frame]) { } /// Construct a page object. +#[tracing::instrument(skip_all)] pub fn construct_page(ctx: &mut PdfContext, frame: &Frame) { let page_ref = ctx.alloc.bump(); ctx.page_refs.push(page_ref); @@ -64,6 +66,7 @@ pub fn construct_page(ctx: &mut PdfContext, frame: &Frame) { } /// Write the page tree. +#[tracing::instrument(skip_all)] pub fn write_page_tree(ctx: &mut PdfContext) { for page in std::mem::take(&mut ctx.pages).into_iter() { write_page(ctx, page); @@ -100,6 +103,7 @@ pub fn write_page_tree(ctx: &mut PdfContext) { } /// Write a page tree node. +#[tracing::instrument(skip_all)] fn write_page(ctx: &mut PdfContext, page: Page) { let content_id = ctx.alloc.bump(); @@ -64,6 +64,7 @@ use crate::syntax::{Source, SourceId}; use crate::util::Buffer; /// Compile a source file into a fully layouted document. +#[tracing::instrument(skip(world))] pub fn compile(world: &(dyn World + 'static)) -> SourceResult<Document> { // Evaluate the source file into a module. let route = Route::default(); @@ -71,6 +72,8 @@ pub fn compile(world: &(dyn World + 'static)) -> SourceResult<Document> { let module = eval::eval(world.track(), route.track(), tracer.track_mut(), world.main())?; + tracing::info!("Evaluation successful"); + // Typeset the module's contents. model::typeset(world.track(), tracer.track_mut(), &module.content()) } diff --git a/src/model/content.rs b/src/model/content.rs index 619793ec..c2c70f9d 100644 --- a/src/model/content.rs +++ b/src/model/content.rs @@ -39,16 +39,19 @@ enum Attr { impl Content { /// Create an empty element. + #[tracing::instrument()] pub fn new(func: ElemFunc) -> Self { Self { func, attrs: EcoVec::new() } } /// Create empty content. + #[tracing::instrument()] pub fn empty() -> Self { Self::new(SequenceElem::func()) } /// Create a new sequence element from multiples elements. + #[tracing::instrument(skip_all)] pub fn sequence(iter: impl IntoIterator<Item = Self>) -> Self { let mut iter = iter.into_iter(); let Some(first) = iter.next() else { return Self::empty() }; @@ -91,6 +94,7 @@ impl Content { } /// Access the child and styles. + #[tracing::instrument(skip_all)] pub fn to_styled(&self) -> Option<(&Content, &Styles)> { if !self.is::<StyledElem>() { return None; @@ -116,6 +120,7 @@ impl Content { /// Cast to a trait object if the contained element has the given /// capability. + #[tracing::instrument(skip_all)] pub fn with<C>(&self) -> Option<&C> where C: ?Sized + 'static, @@ -127,6 +132,7 @@ impl Content { /// Cast to a mutable trait object if the contained element has the given /// capability. + #[tracing::instrument(skip_all)] pub fn with_mut<C>(&mut self) -> Option<&mut C> where C: ?Sized + 'static, @@ -174,6 +180,7 @@ impl Content { } /// Access a field on the content. + #[tracing::instrument(skip_all)] pub fn field(&self, name: &str) -> Option<Value> { if let (Some(iter), "children") = (self.to_sequence(), name) { Some(Value::Array(iter.cloned().map(Value::Content).collect())) @@ -360,6 +367,7 @@ 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<&Content> { let mut results = Vec::new(); self.traverse(&mut |element| { diff --git a/src/model/introspect.rs b/src/model/introspect.rs index 031f2d5e..5a286ec9 100644 --- a/src/model/introspect.rs +++ b/src/model/introspect.rs @@ -94,6 +94,7 @@ pub struct Introspector { impl Introspector { /// Create a new introspector. + #[tracing::instrument(skip(frames))] pub fn new(frames: &[Frame]) -> Self { let mut introspector = Self { pages: frames.len(), @@ -113,6 +114,7 @@ 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 { @@ -154,6 +156,7 @@ impl Introspector { } /// Query for all matching elements. + #[tracing::instrument(skip_all)] pub fn query<'a>(&'a self, selector: &'a Selector) -> Vec<Content> { match selector { Selector::Location(location) => self @@ -168,6 +171,7 @@ impl Introspector { } /// Query for the first matching element. + #[tracing::instrument(skip_all)] pub fn query_first<'a>(&'a self, selector: &'a Selector) -> Option<Content> { match selector { Selector::Location(location) => { @@ -178,6 +182,7 @@ impl Introspector { } /// Query for a unique element with the label. + #[tracing::instrument(skip(self))] pub fn query_label(&self, label: &Label) -> StrResult<Content> { let mut found = None; for elem in self.all().filter(|elem| elem.label() == Some(label)) { @@ -200,12 +205,14 @@ impl Introspector { } /// Gets the page numbering for the given location, if any. + #[tracing::instrument(skip(self))] pub fn page_numbering(&self, location: Location) -> Value { let page = self.page(location); self.page_numberings.get(page.get() - 1).cloned().unwrap_or_default() } /// Find the position for the given location. + #[tracing::instrument(skip(self))] pub fn position(&self, location: Location) -> Position { self.elems .get(&location) diff --git a/src/model/mod.rs b/src/model/mod.rs index 7458dc3c..4ec7311a 100644 --- a/src/model/mod.rs +++ b/src/model/mod.rs @@ -23,11 +23,13 @@ use crate::World; /// Typeset content into a fully layouted document. #[comemo::memoize] +#[tracing::instrument(skip(world, tracer, content))] pub fn typeset( world: Tracked<dyn World>, mut tracer: TrackedMut<Tracer>, content: &Content, ) -> SourceResult<Document> { + tracing::info!("Starting layout"); let library = world.library(); let styles = StyleChain::new(&library.styles); @@ -38,6 +40,8 @@ pub 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 constraint = Constraint::new(); let mut provider = StabilityProvider::new(); let mut vt = Vt { diff --git a/src/model/styles.rs b/src/model/styles.rs index 8b7a829f..9ef74276 100644 --- a/src/model/styles.rs +++ b/src/model/styles.rs @@ -360,7 +360,7 @@ impl Selector { Self::Before { selector, end: location, inclusive } => { if let Some(content) = introspector.query_first(location) { let loc = content.location().unwrap(); - Box::new(selector.match_iter_inner(introspector, parent).filter( + Box::new(selector.match_iter_inner(introspector, parent).take_while( move |elem| { introspector.is_before( elem.location().unwrap(), @@ -376,12 +376,12 @@ impl Selector { Self::After { selector, start: location, inclusive } => { if let Some(content) = introspector.query_first(location) { let loc = content.location().unwrap(); - Box::new(selector.match_iter_inner(introspector, parent).filter( + Box::new(selector.match_iter_inner(introspector, parent).skip_while( move |elem| { - introspector.is_after( + introspector.is_before( elem.location().unwrap(), loc, - *inclusive, + !*inclusive, ) }, )) @@ -586,6 +586,7 @@ impl<'a> StyleChain<'a> { /// The resulting style chain contains styles from `local` as well as /// `self`. The ones from `local` take precedence over the ones from /// `self`. For folded properties `local` contributes the inner value. + #[tracing::instrument(skip_all)] pub fn chain<'b>(&'b self, local: &'b Styles) -> StyleChain<'b> { if local.is_empty() { *self @@ -595,6 +596,7 @@ impl<'a> StyleChain<'a> { } /// Cast the first value for the given property in the chain. + #[tracing::instrument(skip_all)] pub fn get<T: Cast>( self, func: ElemFunc, @@ -608,6 +610,7 @@ impl<'a> StyleChain<'a> { } /// Cast the first value for the given property in the chain. + #[tracing::instrument(skip_all)] pub fn get_resolve<T: Cast + Resolve>( self, func: ElemFunc, @@ -619,6 +622,7 @@ impl<'a> StyleChain<'a> { } /// Cast the first value for the given property in the chain. + #[tracing::instrument(skip_all)] pub fn get_fold<T: Cast + Fold>( self, func: ElemFunc, @@ -640,6 +644,7 @@ impl<'a> StyleChain<'a> { } /// Cast the first value for the given property in the chain. + #[tracing::instrument(skip_all)] pub fn get_resolve_fold<T>( self, func: ElemFunc, @@ -674,6 +679,7 @@ impl<'a> StyleChain<'a> { } /// Iterate over all values for the given property in the chain. + #[tracing::instrument(skip_all)] pub fn properties<T: Cast + 'a>( self, func: ElemFunc, diff --git a/src/syntax/node.rs b/src/syntax/node.rs index 3c9bc049..d2adc13a 100644 --- a/src/syntax/node.rs +++ b/src/syntax/node.rs @@ -190,6 +190,7 @@ impl SyntaxNode { } /// Assign spans to each node. + #[tracing::instrument(skip_all)] pub(super) fn numberize( &mut self, id: SourceId, diff --git a/src/syntax/source.rs b/src/syntax/source.rs index a51da301..2a474b17 100644 --- a/src/syntax/source.rs +++ b/src/syntax/source.rs @@ -28,6 +28,7 @@ pub struct Source { impl Source { /// Create a new source file. + #[tracing::instrument(skip_all)] pub fn new(id: SourceId, path: &Path, text: String) -> Self { let mut root = parse(&text); root.numberize(id, Span::FULL).unwrap(); diff --git a/src/util/mod.rs b/src/util/mod.rs index b8bf90d2..592ba1fa 100644 --- a/src/util/mod.rs +++ b/src/util/mod.rs @@ -34,6 +34,7 @@ where } /// Calculate a 128-bit siphash of a value. +#[tracing::instrument(skip_all)] pub fn hash128<T: Hash + ?Sized>(value: &T) -> u128 { let mut state = SipHasher13::new(); value.hash(&mut state); @@ -128,6 +129,7 @@ pub trait PathExt { } impl PathExt for Path { + #[tracing::instrument(skip_all)] fn normalize(&self) -> PathBuf { let mut out = PathBuf::new(); for component in self.components() { |