Add instrumentation (Part 1) (#761)

16 files changed, 119 insertions, 5 deletions

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();
 
diff --git a/src/lib.rs b/src/lib.rs
index 53887a49..4a5f0c15 100644
--- a/src/lib.rs
+++ b/src/lib.rs
@@ -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() {