add tracing to the treehouse as an instrumenting profiler

to create a trace of the treehouse's startup, use `--trace file.json`

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"

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<PathBuf>,
+
     #[clap(subcommand)]
     pub command: Command,
 }

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::{

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<Sources>, 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<String>,
 }
 
+#[instrument(skip(state))]
 async fn get_static_file(path: &str, query: &VfsQuery, state: &Server) -> Option<Response> {
     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<Arc<Server>>) -> 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<Arc<Server>>) -> Response {
     if let Some(named_id) = named_id {
         let branch_id = state

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<Syntax, _> = 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);
                     }

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<Self> {
-        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<Item = &'a VPath>) -> 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<DirEntry> {
         // 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<Vec<u8>> {
-        debug!("content({path})");
-
         let path = if path.is_root() {
             VPath::new_const("index")
         } else {

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 {

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,

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<TokenId>,
 }
 
+#[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 {

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();
 

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(),

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<DynDir> {
     Ok(root.to_dyn())
 }
 
-async fn fallible_main() -> anyhow::Result<()> {
-    let args = ProgramArgs::parse();
-
+async fn fallible_main(
+    args: ProgramArgs,
+    flush_guard: Option<tracing_chrome::FlushGuard>,
+) -> 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<dyn std::error::Error>> {
-    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:?}"),
     }

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,

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<Diagnostic<FileId>>,

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<T> ContentCache<T>
 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<Vec<u8>> {
         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());

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<String> {
         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])

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 {

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<ImageSize> {
         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 {

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<DirEntry> {
         let mut dir = self.base.dir(path);
         dir.append(&mut self.overlay.dir(path));

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<DirEntry> {
         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<Vec<u8>> {
         std::fs::read(self.root.join(physical_path(path)))
             .inspect_err(|err| error!("{self:?} cannot read file at vpath {path:?}: {err:?}",))