From 561ff979d574f496415c0499345d41da2e1f6e1e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?S=C3=A9bastien=20d=27Herbais=20de=20Thun?= Date: Sun, 23 Apr 2023 14:33:56 +0200 Subject: Add instrumentation (Part 1) (#761) --- src/eval/func.rs | 9 +++++++ src/eval/mod.rs | 61 ++++++++++++++++++++++++++++++++++++++++++++++- src/eval/value.rs | 1 + src/export/pdf/font.rs | 1 + src/export/pdf/image.rs | 3 +++ src/export/pdf/mod.rs | 3 +++ src/export/pdf/outline.rs | 2 ++ src/export/pdf/page.rs | 4 ++++ src/lib.rs | 3 +++ src/model/content.rs | 8 +++++++ src/model/introspect.rs | 7 ++++++ src/model/mod.rs | 4 ++++ src/model/styles.rs | 14 +++++++---- src/syntax/node.rs | 1 + src/syntax/source.rs | 1 + src/util/mod.rs | 2 ++ 16 files changed, 119 insertions(+), 5 deletions(-) (limited to 'src') 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 { + let _span = tracing::info_span!( + "call", + name = self.name().unwrap_or(""), + 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, route: Tracked, @@ -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) { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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 { 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.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 { 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 { 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 { 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 { 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 { 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 { let span = self.span(); if vm.depth >= MAX_CALL_DEPTH { @@ -1074,7 +1119,10 @@ impl Eval for ast::FuncCall { let callee = callee.cast::().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 { // 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 { 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 { 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 { let condition = self.condition(); if condition.eval(vm)?.cast::().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 { 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 { 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 { 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 { 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 { impl Eval for ast::LoopBreak { type Output = Value; + #[tracing::instrument(name = "LoopBreak::eval", skip_all)] fn eval(&self, vm: &mut Vm) -> SourceResult { 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 { 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 { 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, 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 { 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 { 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 { let mut tree: Vec = 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 { // Evaluate the source file into a module. let route = Route::default(); @@ -71,6 +72,8 @@ pub fn compile(world: &(dyn World + 'static)) -> SourceResult { 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) -> 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::() { 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(&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(&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 { 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 { 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 { 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 { 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, mut tracer: TrackedMut, content: &Content, ) -> SourceResult { + 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( 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( 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( 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( 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( 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(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() { -- cgit v1.2.3