From 07419ca702f2729b1bea5b36f5cc00d8809e03a7 Mon Sep 17 00:00:00 2001 From: liquidev Date: Tue, 26 Nov 2024 20:55:49 +0100 Subject: [PATCH] add tracing to the treehouse as an instrumenting profiler to create a trace of the treehouse's startup, use `--trace file.json` --- Cargo.lock | 229 ++++++++++++------ Cargo.toml | 2 +- crates/treehouse/Cargo.toml | 9 +- crates/treehouse/src/cli.rs | 6 + crates/treehouse/src/cli/fix.rs | 2 +- crates/treehouse/src/cli/serve.rs | 7 +- crates/treehouse/src/config.rs | 8 +- crates/treehouse/src/generate.rs | 73 +++--- crates/treehouse/src/history.rs | 2 +- crates/treehouse/src/html/breadcrumbs.rs | 3 + .../treehouse/src/html/highlight/compiled.rs | 3 +- crates/treehouse/src/html/navmap.rs | 3 + crates/treehouse/src/import_map.rs | 2 + crates/treehouse/src/main.rs | 39 ++- crates/treehouse/src/parse.rs | 2 + crates/treehouse/src/tree.rs | 5 + crates/treehouse/src/vfs/content_cache.rs | 7 +- .../src/vfs/content_version_cache.rs | 4 + crates/treehouse/src/vfs/edit.rs | 2 +- crates/treehouse/src/vfs/image_size_cache.rs | 8 +- crates/treehouse/src/vfs/overlay.rs | 3 + crates/treehouse/src/vfs/physical.rs | 4 +- 22 files changed, 287 insertions(+), 136 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 1a499bb..9ba32b1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1,6 +1,6 @@ # This file is automatically @generated by Cargo. # It is not intended for manual editing. -version = 3 +version = 4 [[package]] name = "addr2line" @@ -438,15 +438,6 @@ version = "0.3.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7c74b8349d32d297c9134b8c88677813a227df8f779daa29bfc29c183fe3dca6" -[[package]] -name = "copy_dir" -version = "0.1.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "543d1dd138ef086e2ff05e3a48cf9da045da2033d16f8538fd76b86cd49b2ca3" -dependencies = [ - "walkdir", -] - [[package]] name = "core-foundation-sys" version = "0.8.7" @@ -553,19 +544,6 @@ version = "1.13.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "60b1af1c220855b6ceac025d3f6ecdd2b7c4894bfe9cd9bda4fbb4bc7c0d4cf0" -[[package]] -name = "env_logger" -version = "0.10.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4cd405aab171cb85d6735e5c8d9db038c17d3ca007a4d2c25f337935c3d90580" -dependencies = [ - "humantime", - "is-terminal", - "log", - "regex", - "termcolor", -] - [[package]] name = "equivalent" version = "1.0.1" @@ -754,12 +732,6 @@ version = "0.3.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d231dfb89cfffdbc30e7fc41579ed6066ad03abda9e567ccafae602b97ec5024" -[[package]] -name = "hermit-abi" -version = "0.4.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "fbf6a919d6cf397374f7dfeeea91d974c7c0a7221d0d0f4f20d859d329e53fcc" - [[package]] name = "http" version = "1.1.0" @@ -806,12 +778,6 @@ version = "1.0.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "df3b46402a9d5adb4c86a0cf463f42e19994e3ee891101b1841f30a545cb49a9" -[[package]] -name = "humantime" -version = "2.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" - [[package]] name = "hyper" version = "1.5.1" @@ -1070,17 +1036,6 @@ dependencies = [ "syn", ] -[[package]] -name = "is-terminal" -version = "0.4.13" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "261f68e344040fbd0edea105bef17c66edf46f984ddb1115b775ce31be948f4b" -dependencies = [ - "hermit-abi 0.4.0", - "libc", - "windows-sys 0.52.0", -] - [[package]] name = "is_terminal_polyfill" version = "1.70.1" @@ -1132,6 +1087,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "lazy_static" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe" + [[package]] name = "lebe" version = "0.5.2" @@ -1209,6 +1170,15 @@ dependencies = [ "imgref", ] +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata 0.1.10", +] + [[package]] name = "matchit" version = "0.7.3" @@ -1259,7 +1229,7 @@ version = "1.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "80e04d1dcff3aae0704555fe5fee3bcfaf3d1fdf8a7e521d5b9d2b42acb52cec" dependencies = [ - "hermit-abi 0.3.9", + "hermit-abi", "libc", "wasi", "windows-sys 0.52.0", @@ -1287,6 +1257,16 @@ version = "0.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0676bb32a98c1a483ce53e500a81ad9c3d5b3f7c920c28c24e9cb0980d0b5bc8" +[[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.6" @@ -1352,6 +1332,12 @@ version = "1.20.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1261fe7e33c73b354eab43b1273a57c8f967d0391e80353e51f764ac02cf6775" +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parking_lot" version = "0.12.3" @@ -1641,8 +1627,17 @@ checksum = "b544ef1b4eac5dc2db33ea63606ae9ffcfac26c1416a2806ae0bf5f56b201191" dependencies = [ "aho-corasick", "memchr", - "regex-automata", - "regex-syntax", + "regex-automata 0.4.9", + "regex-syntax 0.8.5", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", ] [[package]] @@ -1653,9 +1648,15 @@ checksum = "809e8dc61f6de73b46c85f4c96486310fe304c434cfa43669d7b40f711150908" dependencies = [ "aho-corasick", "memchr", - "regex-syntax", + "regex-syntax 0.8.5", ] +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + [[package]] name = "regex-syntax" version = "0.8.5" @@ -1686,15 +1687,6 @@ version = "1.0.18" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f3cb5ba0dc43242ce17de99c180e96db90b235b8a9fdc9543c96d2209116bd9f" -[[package]] -name = "same-file" -version = "1.0.6" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "93fc1dc3aaa9bfed95e02e6eadabb4baf7e3078b0bd1b4d7b6b0b68378900502" -dependencies = [ - "winapi-util", -] - [[package]] name = "scopeguard" version = "1.2.0" @@ -1775,6 +1767,15 @@ dependencies = [ "digest", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.3.0" @@ -1915,6 +1916,16 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8b9ef9bad013ada3808854ceac7b46812a6465ba368859a37e2100283d2d719c" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "tiff" version = "0.9.1" @@ -2048,9 +2059,32 @@ checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef" dependencies = [ "log", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.27" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-chrome" +version = "0.7.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bf0a738ed5d6450a9fb96e86a23ad808de2b727fd1394585da5cdd6788ffe724" +dependencies = [ + "serde_json", + "tracing-core", + "tracing-subscriber", +] + [[package]] name = "tracing-core" version = "0.1.32" @@ -2058,6 +2092,36 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", ] [[package]] @@ -2071,16 +2135,12 @@ dependencies = [ "chrono", "clap", "codespan-reporting", - "copy_dir", "dashmap", - "env_logger", "git2", "handlebars", - "http-body", "image", "indexmap", "jotdown", - "log", "rand", "rayon", "regex", @@ -2088,10 +2148,11 @@ dependencies = [ "serde_json", "tokio", "toml_edit 0.19.15", + "tracing", + "tracing-chrome", + "tracing-subscriber", "treehouse-format", "ulid", - "url", - "walkdir", ] [[package]] @@ -2176,6 +2237,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "vcpkg" version = "0.2.15" @@ -2194,16 +2261,6 @@ version = "0.9.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0b928f33d975fc6ad9f86c8f283853ad26bdd5b10b7f1542aa2fa15e2289105a" -[[package]] -name = "walkdir" -version = "2.5.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "29790946404f91d9c5d06f9874efddea1dc06c5efe94541a7d6863108e3a5e4b" -dependencies = [ - "same-file", - "winapi-util", -] - [[package]] name = "wasi" version = "0.11.0+wasi-snapshot-preview1" @@ -2281,6 +2338,22 @@ version = "0.1.8" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "53a85b86a771b1c87058196170769dd264f66c0782acf1ae6cc51bfd64b39082" +[[package]] +name = "winapi" +version = "0.3.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5c839a674fcd7a98952e593242ea400abe93992746761e38641405d28b00f419" +dependencies = [ + "winapi-i686-pc-windows-gnu", + "winapi-x86_64-pc-windows-gnu", +] + +[[package]] +name = "winapi-i686-pc-windows-gnu" +version = "0.4.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" + [[package]] name = "winapi-util" version = "0.1.9" @@ -2290,6 +2363,12 @@ dependencies = [ "windows-sys 0.59.0", ] +[[package]] +name = "winapi-x86_64-pc-windows-gnu" +version = "0.4.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "712e227841d057c1ee1cd2fb22fa7e5a5461ae8e48fa2ca79ec42cfc1931183f" + [[package]] name = "windows-core" version = "0.52.0" diff --git a/Cargo.toml b/Cargo.toml index 9996aa8..1a27c1c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -3,6 +3,6 @@ members = ["crates/*"] resolver = "2" [workspace.dependencies] -log = "0.4.20" +tracing = "0.1.40" treehouse-format = { path = "crates/treehouse-format" } diff --git a/crates/treehouse/Cargo.toml b/crates/treehouse/Cargo.toml index c74bbb0..8b53f86 100644 --- a/crates/treehouse/Cargo.toml +++ b/crates/treehouse/Cargo.toml @@ -14,16 +14,12 @@ blake3 = "1.5.3" chrono = "0.4.35" clap = { version = "4.3.22", features = ["derive"] } codespan-reporting = "0.11.1" -copy_dir = "0.1.3" dashmap = "6.1.0" -env_logger = "0.10.0" git2 = { version = "0.19.0", default-features = false, features = ["vendored-libgit2"] } handlebars = "4.3.7" -http-body = "1.0.0" image = "0.25.5" indexmap = { version = "2.2.6", features = ["serde"] } jotdown = { version = "0.4.1", default-features = false } -log = { workspace = true } rand = "0.8.5" rayon = "1.10.0" regex = "1.10.3" @@ -31,6 +27,7 @@ serde = { version = "1.0.183", features = ["derive"] } serde_json = "1.0.105" tokio = { version = "1.32.0", features = ["full"] } toml_edit = { version = "0.19.14", features = ["serde"] } -walkdir = "2.3.3" +tracing.workspace = true +tracing-chrome = "0.7.2" +tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } ulid = "1.0.0" -url = "2.5.0" diff --git a/crates/treehouse/src/cli.rs b/crates/treehouse/src/cli.rs index 8ff2948..5266950 100644 --- a/crates/treehouse/src/cli.rs +++ b/crates/treehouse/src/cli.rs @@ -2,12 +2,18 @@ pub mod fix; pub mod serve; pub mod wc; +use std::path::PathBuf; + use clap::{Args, Parser, Subcommand}; use crate::vfs::VPathBuf; #[derive(Parser)] pub struct ProgramArgs { + /// Emit a Chrome trace to the given file. + #[clap(long)] + pub trace: Option, + #[clap(subcommand)] pub command: Command, } diff --git a/crates/treehouse/src/cli/fix.rs b/crates/treehouse/src/cli/fix.rs index 4da2ed8..2da6251 100644 --- a/crates/treehouse/src/cli/fix.rs +++ b/crates/treehouse/src/cli/fix.rs @@ -2,7 +2,7 @@ use std::ops::{ControlFlow, Range}; use anyhow::{anyhow, Context}; use codespan_reporting::diagnostic::Diagnostic; -use log::{error, info}; +use tracing::{error, info}; use treehouse_format::ast::Branch; use crate::{ diff --git a/crates/treehouse/src/cli/serve.rs b/crates/treehouse/src/cli/serve.rs index 6ac8355..94fe822 100644 --- a/crates/treehouse/src/cli/serve.rs +++ b/crates/treehouse/src/cli/serve.rs @@ -14,9 +14,9 @@ use axum::{ routing::get, Router, }; -use log::info; use serde::Deserialize; use tokio::net::TcpListener; +use tracing::{info, instrument}; use crate::generate::Sources; use crate::vfs::asynch::AsyncDir; @@ -36,6 +36,7 @@ struct Server { target: AsyncDir, } +#[instrument(skip(sources, target))] pub async fn serve(sources: Arc, target: AsyncDir, port: u16) -> anyhow::Result<()> { let app = Router::new() .route("/", get(index)) // needed explicitly because * does not match empty paths @@ -62,12 +63,13 @@ fn get_content_type(extension: &str) -> Option<&'static str> { } } -#[derive(Deserialize)] +#[derive(Debug, Deserialize)] struct VfsQuery { #[serde(rename = "v")] content_version: Option, } +#[instrument(skip(state))] async fn get_static_file(path: &str, query: &VfsQuery, state: &Server) -> Option { let vpath = VPath::try_new(path).ok()?; let content = state.target.content(vpath).await?; @@ -123,6 +125,7 @@ async fn four_oh_four(State(state): State>) -> Response { system_page(&state.target, system::FOUR_OH_FOUR, StatusCode::NOT_FOUND).await } +#[instrument(skip(state))] async fn branch(RawQuery(named_id): RawQuery, State(state): State>) -> Response { if let Some(named_id) = named_id { let branch_id = state diff --git a/crates/treehouse/src/config.rs b/crates/treehouse/src/config.rs index 945f497..77add2d 100644 --- a/crates/treehouse/src/config.rs +++ b/crates/treehouse/src/config.rs @@ -1,8 +1,8 @@ use std::{collections::HashMap, ops::ControlFlow}; use anyhow::{anyhow, Context}; -use log::{debug, error}; use serde::{Deserialize, Serialize}; +use tracing::{debug, error, info_span, instrument}; use crate::{ html::highlight::{ @@ -99,6 +99,7 @@ pub enum Markup { } impl Config { + #[instrument(name = "Config::autopopulate_emoji", skip(self))] pub fn autopopulate_emoji(&mut self, dir: &dyn Dir) -> anyhow::Result<()> { vfs::walk_dir_rec(dir, VPath::ROOT, &mut |path| { if path.extension().is_some_and(is_image_file) { @@ -115,6 +116,7 @@ impl Config { Ok(()) } + #[instrument(name = "Config::autopopulate_pics", skip(self))] pub fn autopopulate_pics(&mut self, dir: &dyn Dir) -> anyhow::Result<()> { vfs::walk_dir_rec(dir, VPath::ROOT, &mut |path| { if path.extension().is_some_and(is_image_file) { @@ -156,13 +158,13 @@ impl Config { } /// Loads all syntax definition files. + #[instrument(name = "Config::load_syntaxes", skip(self))] pub fn load_syntaxes(&mut self, dir: &dyn Dir) -> anyhow::Result<()> { vfs::walk_dir_rec(dir, VPath::ROOT, &mut |path| { if path.extension() == Some("json") { let name = path .file_stem() .expect("syntax file name should have a stem due to the .json extension"); - debug!("loading syntax {name:?}"); let result: Result = dir .content(path) @@ -171,10 +173,12 @@ impl Config { String::from_utf8(b).context("syntax .json contains invalid UTF-8") }) .and_then(|s| { + let _span = info_span!("Config::load_syntaxes::parse").entered(); serde_json::from_str(&s).context("could not deserialize syntax file") }); match result { Ok(syntax) => { + let _span = info_span!("Config::load_syntaxes::compile", ?name).entered(); let compiled = compile_syntax(&syntax); self.syntaxes.insert(name.to_owned(), compiled); } diff --git a/crates/treehouse/src/generate.rs b/crates/treehouse/src/generate.rs index 3e9d596..87cef80 100644 --- a/crates/treehouse/src/generate.rs +++ b/crates/treehouse/src/generate.rs @@ -8,8 +8,8 @@ use codespan_reporting::diagnostic::Diagnostic; use dir_helper::DirHelper; use handlebars::{handlebars_helper, Handlebars}; use include_static_helper::IncludeStaticHelper; -use log::{debug, error, info}; use serde::Serialize; +use tracing::{debug, error, info, info_span, instrument}; use crate::{ config::Config, @@ -81,10 +81,12 @@ fn create_handlebars(site: &str, static_: DynDir) -> Handlebars<'static> { handlebars } +#[instrument(skip(handlebars))] fn load_templates(handlebars: &mut Handlebars, dir: &dyn Dir) { vfs::walk_dir_rec(dir, VPath::ROOT, &mut |path| { if path.extension() == Some("hbs") { if let Some(content) = dir.content(path).and_then(|b| String::from_utf8(b).ok()) { + let _span = info_span!("register_template", ?path).entered(); if let Err(err) = handlebars.register_template_string(path.as_str(), content) { error!("in template: {err}"); } @@ -94,6 +96,7 @@ fn load_templates(handlebars: &mut Handlebars, dir: &dyn Dir) { }); } +#[instrument(skip(treehouse, config, source, target_path, tree_path))] fn parse_tree( treehouse: &mut Treehouse, config: &Config, @@ -125,6 +128,7 @@ fn parse_tree( } } +#[instrument(skip(config, dirs))] fn parse_trees( config: &Config, dirs: &Dirs, @@ -143,8 +147,6 @@ fn parse_trees( let tree_path = path.with_extension(""); let target_path = path.with_extension("html"); - debug!("tree file: {path}"); - match parse_tree( &mut treehouse, config, @@ -174,6 +176,7 @@ fn parse_trees( Ok((treehouse, parsed_trees)) } +#[instrument(skip(sources, handlebars))] fn generate_simple_template( sources: &Sources, handlebars: &Handlebars, @@ -202,6 +205,7 @@ fn generate_simple_template_or_error( } } +#[instrument(skip(sources, dirs, handlebars, parsed_tree), fields(root_key = parsed_tree.root_key))] fn generate_tree( sources: &Sources, dirs: &Dirs, @@ -214,20 +218,25 @@ fn generate_tree( &parsed_tree.root_key, ); - let mut tree = String::new(); let roots = sources .treehouse .roots .get(&parsed_tree.root_key) .expect("tree should have been added to the treehouse"); - branches_to_html( - &mut tree, - &sources.treehouse, - &sources.config, - dirs, - parsed_tree.file_id, - &roots.branches, - ); + + let tree = { + let _span = info_span!("generate_tree::branches_to_html").entered(); + let mut tree = String::new(); + branches_to_html( + &mut tree, + &sources.treehouse, + &sources.config, + dirs, + parsed_tree.file_id, + &roots.branches, + ); + tree + }; let base_template_data = BaseTemplateData { config: &sources.config, @@ -270,6 +279,7 @@ fn generate_tree( "template {template_name} does not exist" ); + let _span = info_span!("handlebars::render").entered(); handlebars .render(&template_name, &template_data) .context("template rendering failed") @@ -297,27 +307,25 @@ pub struct Sources { impl Sources { pub fn load(dirs: &Dirs) -> anyhow::Result { - info!("loading config"); - let mut config: Config = toml_edit::de::from_str( - &dirs - .root - .content(VPath::new("treehouse.toml")) - .map(String::from_utf8) - .ok_or_else(|| anyhow!("config file does not exist"))??, - ) - .context("failed to deserialize config")?; - config.site = std::env::var("TREEHOUSE_SITE").unwrap_or(config.site); - config.autopopulate_emoji(&*dirs.emoji)?; - config.autopopulate_pics(&*dirs.pic)?; - config.load_syntaxes(&*dirs.syntax)?; + let config = { + let _span = info_span!("load_config").entered(); + let mut config: Config = toml_edit::de::from_str( + &dirs + .root + .content(VPath::new("treehouse.toml")) + .map(String::from_utf8) + .ok_or_else(|| anyhow!("config file does not exist"))??, + ) + .context("failed to deserialize config")?; + config.site = std::env::var("TREEHOUSE_SITE").unwrap_or(config.site); + config.autopopulate_emoji(&*dirs.emoji)?; + config.autopopulate_pics(&*dirs.pic)?; + config.load_syntaxes(&*dirs.syntax)?; + config + }; - info!("parsing tree files"); let (treehouse, parsed_trees) = parse_trees(&config, dirs)?; - - info!("constructing navigation map"); let navigation_map = NavigationMap::build(&treehouse, "index"); - - info!("constructing import map"); let import_map = ImportMap::generate( &config.site, &Cd::new(dirs.static_.clone(), VPathBuf::new("js")), @@ -342,6 +350,7 @@ struct DirIndex { } impl DirIndex { + #[instrument(name = "DirIndex::new", skip(paths))] pub fn new<'a>(paths: impl Iterator) -> Self { let mut root = DirIndex::default(); @@ -387,6 +396,7 @@ impl TreehouseDir { } impl Dir for TreehouseDir { + #[instrument("TreehouseDir::dir", skip(self))] fn dir(&self, path: &VPath) -> Vec { // NOTE: This does not include simple templates, because that's not really needed right now. @@ -410,9 +420,8 @@ impl Dir for TreehouseDir { .collect() } + #[instrument("TreehouseDir::content", skip(self))] fn content(&self, path: &VPath) -> Option> { - debug!("content({path})"); - let path = if path.is_root() { VPath::new_const("index") } else { diff --git a/crates/treehouse/src/history.rs b/crates/treehouse/src/history.rs index 4a76c97..493abfa 100644 --- a/crates/treehouse/src/history.rs +++ b/crates/treehouse/src/history.rs @@ -1,7 +1,7 @@ use std::collections::HashMap; use indexmap::IndexMap; -use log::debug; +use tracing::debug; #[derive(Debug, Default, Clone)] pub struct History { diff --git a/crates/treehouse/src/html/breadcrumbs.rs b/crates/treehouse/src/html/breadcrumbs.rs index 8438aee..b78a375 100644 --- a/crates/treehouse/src/html/breadcrumbs.rs +++ b/crates/treehouse/src/html/breadcrumbs.rs @@ -1,9 +1,12 @@ use std::{borrow::Cow, fmt::Write}; +use tracing::instrument; + use crate::config::Config; use super::{navmap::NavigationMap, EscapeAttribute}; +#[instrument(skip(config, navigation_map))] pub fn breadcrumbs_to_html( config: &Config, navigation_map: &NavigationMap, diff --git a/crates/treehouse/src/html/highlight/compiled.rs b/crates/treehouse/src/html/highlight/compiled.rs index 5552ab2..6ad669a 100644 --- a/crates/treehouse/src/html/highlight/compiled.rs +++ b/crates/treehouse/src/html/highlight/compiled.rs @@ -1,7 +1,7 @@ use std::collections::HashMap; -use log::error; use regex::{Regex, RegexBuilder}; +use tracing::{error, instrument}; use super::{RegexFlag, Syntax, TokenTypes}; @@ -43,6 +43,7 @@ pub struct CompiledKeyword { pub only_replaces: Option, } +#[instrument(skip(syntax))] pub fn compile_syntax(syntax: &Syntax) -> CompiledSyntax { let mut token_names = vec!["default".into()]; let mut get_token_id = |name: &str| -> TokenId { diff --git a/crates/treehouse/src/html/navmap.rs b/crates/treehouse/src/html/navmap.rs index 4595d95..d331b38 100644 --- a/crates/treehouse/src/html/navmap.rs +++ b/crates/treehouse/src/html/navmap.rs @@ -1,5 +1,7 @@ use std::collections::HashMap; +use tracing::instrument; + use crate::{ state::Treehouse, tree::{attributes::Content, SemaBranchId}, @@ -33,6 +35,7 @@ pub struct NavigationMap { } impl NavigationMap { + #[instrument(name = "NavigationMap::build", skip(treehouse))] pub fn build(treehouse: &Treehouse, root_tree_path: &str) -> Self { let mut builder = NavigationMapBuilder::default(); diff --git a/crates/treehouse/src/import_map.rs b/crates/treehouse/src/import_map.rs index 3fa24df..ea48b97 100644 --- a/crates/treehouse/src/import_map.rs +++ b/crates/treehouse/src/import_map.rs @@ -2,6 +2,7 @@ use std::ops::ControlFlow; use indexmap::IndexMap; use serde::{Deserialize, Serialize}; +use tracing::instrument; use crate::vfs::{self, Dir, VPathBuf}; @@ -17,6 +18,7 @@ pub struct ImportRoot { } impl ImportMap { + #[instrument(name = "ImportMap::generate", skip(import_roots))] pub fn generate(site: &str, root: &dyn Dir, import_roots: &[ImportRoot]) -> Self { let mut import_map = ImportMap { imports: IndexMap::new(), diff --git a/crates/treehouse/src/main.rs b/crates/treehouse/src/main.rs index 0fa55c4..5bc08a0 100644 --- a/crates/treehouse/src/main.rs +++ b/crates/treehouse/src/main.rs @@ -1,10 +1,13 @@ -use std::fs; +use std::fs::{self, File}; use std::path::PathBuf; use std::sync::Arc; use anyhow::Context; use clap::Parser; -use log::error; +use tracing::{error, info_span}; +use tracing_subscriber::fmt::format::FmtSpan; +use tracing_subscriber::layer::SubscriberExt as _; +use tracing_subscriber::util::SubscriberInitExt as _; use treehouse::cli::serve::serve; use treehouse::dirs::Dirs; use treehouse::generate::{self, Sources}; @@ -50,9 +53,10 @@ fn vfs_sources() -> anyhow::Result { Ok(root.to_dyn()) } -async fn fallible_main() -> anyhow::Result<()> { - let args = ProgramArgs::parse(); - +async fn fallible_main( + args: ProgramArgs, + flush_guard: Option, +) -> anyhow::Result<()> { let src = vfs_sources()?; let dirs = Arc::new(Dirs { root: src.clone(), @@ -69,8 +73,12 @@ async fn fallible_main() -> anyhow::Result<()> { generate: _, serve: serve_args, } => { + let _span = info_span!("load").entered(); let sources = Arc::new(Sources::load(&dirs).context("failed to load sources")?); let target = generate::target(dirs, sources.clone()); + drop(_span); + drop(flush_guard); + serve(sources, AsyncDir::new(target), serve_args.port).await?; } @@ -93,11 +101,26 @@ async fn fallible_main() -> anyhow::Result<()> { #[tokio::main] async fn main() -> Result<(), Box> { - env_logger::Builder::new() - .filter_module("treehouse", log::LevelFilter::Debug) + let args = ProgramArgs::parse(); + + let (chrome_layer, flush_guard) = args + .trace + .as_ref() + .map(|path| { + tracing_chrome::ChromeLayerBuilder::new() + .file(path) + .include_args(true) + .build() + }) + .unzip(); + + tracing_subscriber::registry() + .with(tracing_subscriber::EnvFilter::new("treehouse=trace")) + .with(tracing_subscriber::fmt::layer().with_writer(std::io::stderr)) + .with(chrome_layer) .init(); - match fallible_main().await { + match fallible_main(args, flush_guard).await { Ok(_) => (), Err(error) => error!("fatal: {error:?}"), } diff --git a/crates/treehouse/src/parse.rs b/crates/treehouse/src/parse.rs index 2680a08..8193d81 100644 --- a/crates/treehouse/src/parse.rs +++ b/crates/treehouse/src/parse.rs @@ -1,12 +1,14 @@ use std::{ops::Range, str::FromStr}; use codespan_reporting::diagnostic::{Diagnostic, Label, LabelStyle, Severity}; +use tracing::instrument; use treehouse_format::ast::Roots; use crate::state::{toml_error_to_diagnostic, FileId, TomlError, Treehouse}; pub struct ErrorsEmitted; +#[instrument(skip(treehouse))] pub fn parse_tree_with_diagnostics( treehouse: &mut Treehouse, file_id: FileId, diff --git a/crates/treehouse/src/tree.rs b/crates/treehouse/src/tree.rs index e56381a..ca72f57 100644 --- a/crates/treehouse/src/tree.rs +++ b/crates/treehouse/src/tree.rs @@ -4,6 +4,7 @@ pub mod mini_template; use std::ops::Range; use codespan_reporting::diagnostic::{Diagnostic, Label, LabelStyle, Severity}; +use tracing::instrument; use treehouse_format::{ ast::{Branch, Roots}, pull::BranchKind, @@ -44,6 +45,10 @@ pub struct SemaRoots { } impl SemaRoots { + #[instrument( + name = "SemaRoots::from_roots", + skip(treehouse, diagnostics, config, roots) + )] pub fn from_roots( treehouse: &mut Treehouse, diagnostics: &mut Vec>, diff --git a/crates/treehouse/src/vfs/content_cache.rs b/crates/treehouse/src/vfs/content_cache.rs index 0007878..03fd41e 100644 --- a/crates/treehouse/src/vfs/content_cache.rs +++ b/crates/treehouse/src/vfs/content_cache.rs @@ -4,8 +4,8 @@ use std::{ }; use dashmap::DashMap; -use log::debug; use rayon::iter::{IntoParallelRefIterator, ParallelIterator}; +use tracing::{info_span, instrument}; use super::{walk_dir_rec, Dir, DirEntry, EditPath, ImageSize, VPath, VPathBuf}; @@ -27,8 +27,8 @@ impl ContentCache where T: Dir + Send + Sync, { + #[instrument(name = "ContentCache::warm_up", skip(self))] pub fn warm_up(&self) { - debug!("warm_up({self:?})"); let mut paths = vec![]; walk_dir_rec(&self.inner, VPath::ROOT, &mut |path| { paths.push(path.to_owned()); @@ -47,8 +47,11 @@ where self.inner.dir(path) } + #[instrument(name = "ContentCache::content", skip(self))] fn content(&self, path: &VPath) -> Option> { self.cache.get(path).map(|x| x.clone()).or_else(|| { + let _span = info_span!("cache_miss").entered(); + let content = self.inner.content(path); if let Some(content) = &content { self.cache.insert(path.to_owned(), content.clone()); diff --git a/crates/treehouse/src/vfs/content_version_cache.rs b/crates/treehouse/src/vfs/content_version_cache.rs index 7ec1a5e..0dfaae5 100644 --- a/crates/treehouse/src/vfs/content_version_cache.rs +++ b/crates/treehouse/src/vfs/content_version_cache.rs @@ -1,6 +1,7 @@ use std::fmt::{self, Debug}; use dashmap::DashMap; +use tracing::{info_span, instrument}; use super::{Dir, DirEntry, EditPath, ImageSize, VPath, VPathBuf}; @@ -30,8 +31,11 @@ where self.inner.content(path) } + #[instrument(name = "Blake3ContentVersionCache::content_version", skip(self))] fn content_version(&self, path: &VPath) -> Option { self.cache.get(path).map(|x| x.clone()).or_else(|| { + let _span = info_span!("cache_miss").entered(); + let version = self.inner.content(path).map(|content| { let hash = blake3::hash(&content).to_hex(); format!("b3-{}", &hash[0..8]) diff --git a/crates/treehouse/src/vfs/edit.rs b/crates/treehouse/src/vfs/edit.rs index 8d784d5..efe6b52 100644 --- a/crates/treehouse/src/vfs/edit.rs +++ b/crates/treehouse/src/vfs/edit.rs @@ -1,7 +1,7 @@ use std::{error::Error, fmt, future::Future, path::PathBuf}; -use log::{debug, error, info}; use tokio::task::JoinSet; +use tracing::{debug, error, info}; #[derive(Clone, PartialEq, Eq, PartialOrd, Ord)] pub struct EditPath { diff --git a/crates/treehouse/src/vfs/image_size_cache.rs b/crates/treehouse/src/vfs/image_size_cache.rs index 5a7b008..19466f7 100644 --- a/crates/treehouse/src/vfs/image_size_cache.rs +++ b/crates/treehouse/src/vfs/image_size_cache.rs @@ -2,7 +2,7 @@ use std::{fmt, io::Cursor}; use anyhow::Context; use dashmap::DashMap; -use log::{debug, warn}; +use tracing::{debug, info_span, instrument, warn}; use crate::config; @@ -33,7 +33,6 @@ where .with_guessed_format() .context("cannot guess image format")?; let (width, height) = reader.into_dimensions()?; - debug!("image_size({path}) = ({width}, {height})"); return Ok(Some(ImageSize { width, height })); } } @@ -58,11 +57,14 @@ where self.inner.content_version(path) } + #[instrument("ImageSizeCache::image_size", skip(self))] fn image_size(&self, path: &VPath) -> Option { self.cache.get(path).map(|x| *x).or_else(|| { + let _span = info_span!("cache_miss").entered(); + let image_size = self .compute_image_size(path) - .inspect_err(|err| warn!("compute_image_size({path}) failed: {err:?}")) + .inspect_err(|err| warn!(%path, ?err, "compute_image_size failure")) .ok() .flatten(); if let Some(image_size) = image_size { diff --git a/crates/treehouse/src/vfs/overlay.rs b/crates/treehouse/src/vfs/overlay.rs index b65fc4e..33d6b55 100644 --- a/crates/treehouse/src/vfs/overlay.rs +++ b/crates/treehouse/src/vfs/overlay.rs @@ -1,5 +1,7 @@ use std::fmt; +use tracing::instrument; + use super::{Dir, DirEntry, DynDir, EditPath, ImageSize, VPath, VPathBuf}; pub struct Overlay { @@ -14,6 +16,7 @@ impl Overlay { } impl Dir for Overlay { + #[instrument("Overlay::dir", skip(self))] fn dir(&self, path: &VPath) -> Vec { let mut dir = self.base.dir(path); dir.append(&mut self.overlay.dir(path)); diff --git a/crates/treehouse/src/vfs/physical.rs b/crates/treehouse/src/vfs/physical.rs index 9b60468..d4af780 100644 --- a/crates/treehouse/src/vfs/physical.rs +++ b/crates/treehouse/src/vfs/physical.rs @@ -1,6 +1,6 @@ use std::path::{Path, PathBuf}; -use log::error; +use tracing::{error, instrument}; use super::{Dir, DirEntry, EditPath, VPath, VPathBuf}; @@ -16,6 +16,7 @@ impl PhysicalDir { } impl Dir for PhysicalDir { + #[instrument("PhysicalDir::dir", skip(self))] fn dir(&self, vpath: &VPath) -> Vec { let physical = self.root.join(physical_path(vpath)); if !physical.is_dir() { @@ -63,6 +64,7 @@ impl Dir for PhysicalDir { None } + #[instrument("PhysicalDir::content", skip(self))] fn content(&self, path: &VPath) -> Option> { std::fs::read(self.root.join(physical_path(path))) .inspect_err(|err| error!("{self:?} cannot read file at vpath {path:?}: {err:?}",))