From c4d9b0c3d8d2cf895137d2047e597fd3e24e0104 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?S=C3=A9bastien=20d=27Herbais=20de=20Thun?= Date: Sat, 30 Dec 2023 13:36:15 +0100 Subject: New performance timings (#3096) Co-authored-by: Laurenz --- crates/typst-cli/src/args.rs | 15 ++--- crates/typst-cli/src/compile.rs | 13 ++-- crates/typst-cli/src/fonts.rs | 2 + crates/typst-cli/src/main.rs | 16 ++--- crates/typst-cli/src/query.rs | 2 - crates/typst-cli/src/timings.rs | 89 +++++++++++++++++++++++++ crates/typst-cli/src/tracing.rs | 139 ---------------------------------------- crates/typst-cli/src/watch.rs | 12 ++-- crates/typst-cli/src/world.rs | 7 +- 9 files changed, 118 insertions(+), 177 deletions(-) create mode 100644 crates/typst-cli/src/timings.rs delete mode 100644 crates/typst-cli/src/tracing.rs (limited to 'crates/typst-cli/src') 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, @@ -72,9 +67,13 @@ pub struct CompileCommand { #[arg(long = "ppi", default_value_t = 144.0)] pub ppi: f32, - /// Produces a flamegraph of the compilation process - #[arg(long = "flamegraph", value_name = "OUTPUT_SVG")] - pub flamegraph: Option>, + /// Produces performance timings of the compilation process (experimental) + /// + /// The resulting JSON file can be loaded into a tracing tool such as + /// https://ui.perfetto.dev. It does not contain any sensitive information + /// apart from file names and line numbers. + #[arg(long = "timings", value_name = "OUTPUT_JSON")] + pub timings: Option>, } /// Processes an input file to extract provided metadata diff --git a/crates/typst-cli/src/compile.rs b/crates/typst-cli/src/compile.rs index 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 { 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 = 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, + /// The current watch iteration. + index: usize, +} + +impl Timer { + /// Initializes the timing system and returns a timer that can be used to + /// record timings for a specific function invocation. + pub fn new(args: &CliArguments) -> Timer { + let record = match &args.command { + Command::Compile(command) => command.timings.clone(), + Command::Watch(command) => command.timings.clone(), + _ => None, + }; + + // Enable event collection. + if record.is_some() { + typst_timing::enable(); + } + + let path = + record.map(|path| path.unwrap_or_else(|| PathBuf::from("record-{n}.json"))); + + Timer { path, index: 0 } + } + + /// Records all timings in `f` and writes them to disk. + pub fn record( + &mut self, + world: &mut SystemWorld, + f: impl FnOnce(&mut SystemWorld) -> T, + ) -> StrResult { + let Some(path) = &self.path else { + return Ok(f(world)); + }; + + typst_timing::clear(); + + let string = path.to_str().unwrap_or_default(); + let numbered = string.contains("{n}"); + if !numbered && self.index > 0 { + bail!("cannot export multiple recordings without `{{n}}` in path"); + } + + let storage; + let path = if numbered { + storage = string.replace("{n}", &self.index.to_string()); + Path::new(&storage) + } else { + path.as_path() + }; + + let output = f(world); + self.index += 1; + + let file = + File::create(path).map_err(|e| format!("failed to create file: {e}"))?; + let writer = BufWriter::with_capacity(1 << 20, file); + + typst_timing::export_json(writer, |span| { + resolve_span(world, span).unwrap_or_else(|| ("unknown".to_string(), 0)) + })?; + + Ok(output) + } +} + +/// Turns a span into a (file, line) pair. +fn resolve_span(world: &SystemWorld, span: Span) -> Option<(String, u32)> { + let id = span.id()?; + let source = world.source(id).ok()?; + let range = source.range(span)?; + let line = source.byte_to_line(range.start)?; + Some((format!("{id:?}"), line as u32 + 1)) +} diff --git a/crates/typst-cli/src/tracing.rs b/crates/typst-cli/src/tracing.rs deleted file mode 100644 index 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> { - let flamegraph = match &args.command { - Command::Compile(command) => command.flamegraph.as_ref(), - Command::Watch(command) if command.flamegraph.is_some() => { - return Err(io::Error::new( - io::ErrorKind::InvalidInput, - "cannot use --flamegraph with watch command", - )); - } - _ => None, - }; - - // Short circuit if we don't need to initialize flamegraph or debugging. - if flamegraph.is_none() && args.verbosity == 0 { - tracing_subscriber::fmt() - .without_time() - .with_max_level(level_filter(args)) - .init(); - - return Ok(None); - } - - // Build the FMT layer printing to the console. - let fmt_layer = fmt::Layer::default().without_time().with_filter(level_filter(args)); - - // Error layer for building backtraces - let error_layer = ErrorLayer::default(); - - // Build the registry. - let registry = tracing_subscriber::registry().with(fmt_layer).with(error_layer); - - let Some(path) = flamegraph else { - registry.init(); - return Ok(None); - }; - - // Create a temporary file to store the flamegraph data. - let temp_file = tempfile::tempfile()?; - let writer = BufWriter::new(temp_file.try_clone()?); - - // Build the flamegraph layer. - let flame_layer = FlameLayer::new(writer) - .with_empty_samples(false) - .with_threads_collapsed(true) - .with_module_path(false) - .with_file_and_line(true); - let flush_guard = flame_layer.flush_on_drop(); - - // Build the subscriber. - registry.with(flame_layer).init(); - - tracing::warn!( - "Flamegraph is enabled, this can create a large temporary \ - file and slow down the compilation process." - ); - - Ok(Some(TracingGuard { - flush_guard: Some(flush_guard), - temp_file, - output_svg: path.clone().unwrap_or_else(|| "flamegraph.svg".into()), - })) -} - -/// Returns the log level filter for the given verbosity level. -fn level_filter(args: &CliArguments) -> LevelFilter { - match args.verbosity { - 0 => LevelFilter::OFF, - 1 => LevelFilter::WARN, - 2 => LevelFilter::INFO, - 3 => LevelFilter::DEBUG, - _ => LevelFilter::TRACE, - } -} - -/// Will flush the flamegraph to disk when dropped. -struct TracingGuard { - flush_guard: Option>>, - temp_file: File, - output_svg: PathBuf, -} - -impl TracingGuard { - fn finish(&mut self) -> io::Result<()> { - if self.flush_guard.is_none() { - return Ok(()); - } - - tracing::info!("Flushing tracing flamegraph..."); - - // At this point, we're done tracing, so we can drop the guard. - // This will flush the tracing output to disk. - // We can then read the file and generate the flamegraph. - drop(self.flush_guard.take()); - - // Reset the file pointer to the beginning. - self.temp_file.seek(SeekFrom::Start(0))?; - - // Create the readers and writers. - let reader = BufReader::new(&mut self.temp_file); - let output = BufWriter::new(File::create(&self.output_svg)?); - - // Create the options: default in flame chart mode - let mut options = Options::default(); - options.flame_chart = true; - - inferno::flamegraph::from_reader(&mut options, reader, output) - .map_err(|e| io::Error::new(io::ErrorKind::Other, e))?; - - Ok(()) - } -} - -impl Drop for TracingGuard { - fn drop(&mut self) { - if !std::thread::panicking() { - if let Err(err) = self.finish() { - // Since we are finished, we cannot rely on tracing to log the - // error. - eprintln!("failed to flush tracing flamegraph ({err})"); - } - } - } -} diff --git a/crates/typst-cli/src/watch.rs b/crates/typst-cli/src/watch.rs index 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 SlotCell { } // Read and hash the file. - let result = path().and_then(|p| read(&p)); - let fingerprint = typst::util::hash128(&result); + let result = timed!("loading file", path().and_then(|p| read(&p))); + let fingerprint = timed!("hashing file", typst::util::hash128(&result)); // If the file contents didn't change, yield the old processed data. if mem::replace(&mut self.fingerprint, fingerprint) == fingerprint { -- cgit v1.2.3