New performance timings (#3096)

Co-authored-by: Laurenz <laurmaedje@gmail.com>

9 files changed, 118 insertions, 177 deletions

diff --git a/crates/typst-cli/src/args.rs b/crates/typst-cli/src/args.rs
index 8f0261f1..ec5e8ed1 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<PathBuf>,
@@ -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<Option<PathBuf>>,
+    /// 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<Option<PathBuf>>,
 }
 
 /// 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 5916f18b..ea612630 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 7793840c..4ea9f446 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<Font> {
         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 bab1a07b..15a758af 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<CliArguments> = 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 dadcd978..f2257bdf 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 00000000..df7665b7
--- /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<PathBuf>,
+    /// 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<T>(
+        &mut self,
+        world: &mut SystemWorld,
+        f: impl FnOnce(&mut SystemWorld) -> T,
+    ) -> StrResult<T> {
+        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 331c6327..00000000
--- 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<Option<impl Drop>> {
-    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<FlushGuard<BufWriter<File>>>,
-    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 aea3ca48..ee3a8f5b 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 095458df..fee6b7db 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<T: Clone> SlotCell<T> {
         }
 
         // 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 {