Include widget ids in tracing spans (#729)

New tracy image:


![image](https://github.com/user-attachments/assets/94e54c89-8159-4dd4-a521-4a7122f64375)

New log tracing file:
<details><summary>An overview of the new logs</summary>
<p>

```
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}: masonry::passes::update: RootWidget received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}: masonry::passes::update: Flex received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#8}: masonry::passes::update: Flex received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#8}:SizedBox{id=#7}: masonry::passes::update: SizedBox received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#8}:SizedBox{id=#7}:Flex{id=#6}: masonry::passes::update: Flex received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#8}:SizedBox{id=#7}:Flex{id=#6}:Flex{id=#3}: masonry::passes::update: Flex received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#8}:SizedBox{id=#7}:Flex{id=#6}:Flex{id=#3}:Prose{id=#1}: masonry::passes::update: Prose received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#8}:SizedBox{id=#7}:Flex{id=#6}:Flex{id=#3}:Label{id=#2}: masonry::passes::update: Label received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#8}:SizedBox{id=#7}:Flex{id=#6}:Flex{id=#5}: masonry::passes::update: Flex received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#8}:SizedBox{id=#7}:Flex{id=#6}:Flex{id=#5}:VariableLabel{id=#4}: masonry::passes::update: VariableLabel received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#17}: masonry::passes::update: Flex received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#17}:Button{id=#10}: masonry::passes::update: Button received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#17}:Button{id=#10}:Label{id=#9}: masonry::passes::update: Label received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#17}:Button{id=#12}: masonry::passes::update: Button received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#17}:Button{id=#12}:Label{id=#11}: masonry::passes::update: Label received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#17}:Button{id=#14}: masonry::passes::update: Button received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#17}:Button{id=#14}:Label{id=#13}: masonry::passes::update: Label received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#17}:Button{id=#16}: masonry::passes::update: Button received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Flex{id=#17}:Button{id=#16}:Label{id=#15}: masonry::passes::update: Label received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Portal{id=#163}: masonry::passes::update: Portal received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Portal{id=#163}:Flex{id=#160}: masonry::passes::update: Flex received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Portal{id=#163}:Flex{id=#160}:SizedBox{id=#24}: masonry::passes::update: SizedBox received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Portal{id=#163}:Flex{id=#160}:SizedBox{id=#24}:Flex{id=#23}: masonry::passes::update: Flex received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Portal{id=#163}:Flex{id=#160}:SizedBox{id=#24}:Flex{id=#23}:Flex{id=#20}: masonry::passes::update: Flex received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Portal{id=#163}:Flex{id=#160}:SizedBox{id=#24}:Flex{id=#23}:Flex{id=#20}:Prose{id=#18}: masonry::passes::update: Prose received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Portal{id=#163}:Flex{id=#160}:SizedBox{id=#24}:Flex{id=#23}:Flex{id=#20}:Label{id=#19}: masonry::passes::update: Label received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Portal{id=#163}:Flex{id=#160}:SizedBox{id=#24}:Flex{id=#23}:Flex{id=#22}: masonry::passes::update: Flex received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Portal{id=#163}:Flex{id=#160}:SizedBox{id=#24}:Flex{id=#23}:Flex{id=#22}:VariableLabel{id=#21}: masonry::passes::update: VariableLabel received Update::WidgetAdded
14:37:40.365Z TRACE update_new_widgets:RootWidget{id=#165}:Flex{id=#164}:Portal{id=#163}:Flex{id=#160}:SizedBox{id=#31}: masonry::passes::update: SizedBox received Update::WidgetAdded
```

</p>
</details> 

This was originally an experiment into caching spans, but I determined
that was non-viable due to the pass names.

Author: DJMcNab

masonry/examples/calc_masonry.rs

@@ -17,8 +17,8 @@ use masonry::dpi::LogicalSize;
 use masonry::widget::{Align, CrossAxisAlignment, Flex, Label, RootWidget, SizedBox};
 use masonry::{
     AccessCtx, AccessEvent, Action, AppDriver, BoxConstraints, Color, DriverCtx, EventCtx,
-    LayoutCtx, PaintCtx, Point, PointerEvent, RegisterCtx, Size, TextEvent, Update, UpdateCtx,
-    Widget, WidgetId, WidgetPod,
+    LayoutCtx, PaintCtx, Point, PointerEvent, QueryCtx, RegisterCtx, Size, TextEvent, Update,
+    UpdateCtx, Widget, WidgetId, WidgetPod,
 };
 use smallvec::{smallvec, SmallVec};
 use tracing::{trace, trace_span, Span};
@@ -244,8 +244,8 @@ impl Widget for CalcButton {
         smallvec![self.inner.id()]
     }
 
-    fn make_trace_span(&self) -> Span {
-        trace_span!("CalcButton")
+    fn make_trace_span(&self, ctx: &QueryCtx<'_>) -> Span {
+        trace_span!("CalcButton", id = ctx.widget_id().trace())
     }
 }
 

masonry/examples/custom_widget.rs

@@ -15,7 +15,8 @@ use masonry::kurbo::{BezPath, Stroke};
 use masonry::widget::{ObjectFit, RootWidget};
 use masonry::{
     AccessCtx, AccessEvent, Action, Affine, AppDriver, BoxConstraints, Color, DriverCtx, EventCtx,
-    LayoutCtx, PaintCtx, Point, PointerEvent, Rect, RegisterCtx, Size, TextEvent, Widget, WidgetId,
+    LayoutCtx, PaintCtx, Point, PointerEvent, QueryCtx, Rect, RegisterCtx, Size, TextEvent, Widget,
+    WidgetId,
 };
 use parley::layout::Alignment;
 use parley::style::{FontFamily, FontStack, StyleProperty};
@@ -139,8 +140,8 @@ impl Widget for CustomWidget {
         SmallVec::new()
     }
 
-    fn make_trace_span(&self) -> Span {
-        trace_span!("CustomWidget")
+    fn make_trace_span(&self, ctx: &QueryCtx<'_>) -> Span {
+        trace_span!("CustomWidget", id = ctx.widget_id().trace())
     }
 }
 

masonry/src/passes/accessibility.rs

@@ -10,6 +10,8 @@ use crate::render_root::{RenderRoot, RenderRootState};
 use crate::tree_arena::ArenaMut;
 use crate::{AccessCtx, Widget, WidgetState};
 
+use super::enter_span_if;
+
 // --- MARK: BUILD TREE ---
 fn build_accessibility_tree(
     global_state: &mut RenderRootState,
@@ -19,10 +21,12 @@ fn build_accessibility_tree(
     rebuild_all: bool,
     scale_factor: f64,
 ) {
-    let _span = global_state
-        .trace
-        .access
-        .then(|| widget.item.make_trace_span().entered());
+    let _span = enter_span_if(
+        global_state.trace.access,
+        global_state,
+        widget.reborrow(),
+        state.reborrow(),
+    );
     let id = state.item.id;
 
     if !rebuild_all && !state.item.needs_accessibility {

masonry/src/passes/anim.rs

@@ -3,7 +3,7 @@
 
 use tracing::info_span;
 
-use crate::passes::recurse_on_children;
+use crate::passes::{enter_span_if, recurse_on_children};
 use crate::render_root::{RenderRoot, RenderRootState};
 use crate::tree_arena::ArenaMut;
 use crate::{UpdateCtx, Widget, WidgetState};
@@ -15,11 +15,12 @@ fn update_anim_for_widget(
     mut state: ArenaMut<'_, WidgetState>,
     elapsed_ns: u64,
 ) {
-    let _span = global_state
-        .trace
-        .anim
-        .then(|| widget.item.make_trace_span().entered());
-
+    let _span = enter_span_if(
+        global_state.trace.anim,
+        global_state,
+        widget.reborrow(),
+        state.reborrow(),
+    );
     if !state.item.needs_anim {
         return;
     }

masonry/src/passes/compose.rs

@@ -4,7 +4,7 @@
 use tracing::info_span;
 use vello::kurbo::Vec2;
 
-use crate::passes::recurse_on_children;
+use crate::passes::{enter_span_if, recurse_on_children};
 use crate::render_root::{RenderRoot, RenderRootSignal, RenderRootState};
 use crate::tree_arena::ArenaMut;
 use crate::{ComposeCtx, Widget, WidgetState};
@@ -17,10 +17,12 @@ fn compose_widget(
     parent_moved: bool,
     parent_translation: Vec2,
 ) {
-    let _span = global_state
-        .trace
-        .compose
-        .then(|| widget.item.make_trace_span().entered());
+    let _span = enter_span_if(
+        global_state.trace.compose,
+        global_state,
+        widget.reborrow(),
+        state.reborrow(),
+    );
 
     let moved = parent_moved || state.item.translation_changed;
     let translation = parent_translation + state.item.translation + state.item.origin.to_vec2();

masonry/src/passes/event.rs

@@ -6,7 +6,7 @@ use tracing::{debug, info_span, trace};
 use winit::event::ElementState;
 use winit::keyboard::{KeyCode, PhysicalKey};
 
-use crate::passes::merge_state_up;
+use crate::passes::{enter_span, merge_state_up};
 use crate::render_root::RenderRoot;
 use crate::{AccessEvent, EventCtx, Handled, PointerEvent, TextEvent, Widget, WidgetId};
 
@@ -46,21 +46,24 @@ fn run_event_pass<E>(
     let mut is_handled = false;
     while let Some(widget_id) = target_widget_id {
         let parent_id = root.widget_arena.parent_of(widget_id);
-        let (widget_mut, state_mut) = root.widget_arena.get_pair_mut(widget_id);
-
-        let mut ctx = EventCtx {
-            global_state: &mut root.global_state,
-            widget_state: state_mut.item,
-            widget_state_children: state_mut.children,
-            widget_children: widget_mut.children,
-            target: original_target.unwrap(),
-            allow_pointer_capture,
-            is_handled: false,
-        };
-        let widget = widget_mut.item;
+        let (mut widget_mut, mut state_mut) = root.widget_arena.get_pair_mut(widget_id);
 
         if !is_handled {
-            let _span = widget.make_trace_span().entered();
+            let _span = enter_span(
+                &root.global_state,
+                widget_mut.reborrow(),
+                state_mut.reborrow(),
+            );
+            let mut ctx = EventCtx {
+                global_state: &mut root.global_state,
+                widget_state: state_mut.item,
+                widget_state_children: state_mut.children,
+                widget_children: widget_mut.children,
+                target: original_target.unwrap(),
+                allow_pointer_capture,
+                is_handled: false,
+            };
+            let widget = widget_mut.item;
             if trace {
                 trace!(
                     "Widget '{}' {} visited",

masonry/src/passes/layout.rs

@@ -10,7 +10,7 @@ use smallvec::SmallVec;
 use tracing::{info_span, trace};
 use vello::kurbo::{Point, Rect, Size};
 
-use crate::passes::recurse_on_children;
+use crate::passes::{enter_span_if, recurse_on_children};
 use crate::render_root::{RenderRoot, RenderRootSignal, WindowSizePolicy};
 use crate::widget::WidgetState;
 use crate::{BoxConstraints, LayoutCtx, Widget, WidgetPod};
@@ -28,7 +28,12 @@ pub(crate) fn run_layout_on<W: Widget>(
     let mut state = parent_ctx.widget_state_children.get_child_mut(id).unwrap();
 
     let trace = parent_ctx.global_state.trace.layout;
-    let _span = trace.then(|| widget.item.make_trace_span().entered());
+    let _span = enter_span_if(
+        trace,
+        parent_ctx.global_state,
+        widget.reborrow(),
+        state.reborrow(),
+    );
 
     let mut children_ids = SmallVec::new();
     if cfg!(debug_assertions) {

masonry/src/passes/mod.rs

@@ -1,9 +1,12 @@
 // Copyright 2024 the Xilem Authors
 // SPDX-License-Identifier: Apache-2.0
 
-use crate::tree_arena::{ArenaMut, ArenaMutChildren};
+use tracing::span::EnteredSpan;
+
+use crate::render_root::RenderRootState;
+use crate::tree_arena::{ArenaMut, ArenaMutChildren, ArenaRef};
 use crate::widget::WidgetArena;
-use crate::{Widget, WidgetId, WidgetState};
+use crate::{QueryCtx, Widget, WidgetId, WidgetState};
 
 pub(crate) mod accessibility;
 pub(crate) mod anim;
@@ -14,6 +17,35 @@ pub(crate) mod mutate;
 pub(crate) mod paint;
 pub(crate) mod update;
 
+#[must_use = "Span will be immediately closed if dropped"]
+pub(crate) fn enter_span_if(
+    enabled: bool,
+    global_state: &RenderRootState,
+    widget: ArenaRef<'_, Box<dyn Widget>>,
+    state: ArenaRef<'_, WidgetState>,
+) -> Option<EnteredSpan> {
+    if enabled {
+        Some(enter_span(global_state, widget, state))
+    } else {
+        None
+    }
+}
+
+#[must_use = "Span will be immediately closed if dropped"]
+pub(crate) fn enter_span(
+    global_state: &RenderRootState,
+    widget: ArenaRef<'_, Box<dyn Widget>>,
+    state: ArenaRef<'_, WidgetState>,
+) -> EnteredSpan {
+    let ctx = QueryCtx {
+        global_state,
+        widget_state: state.item,
+        widget_state_children: state.children,
+        widget_children: widget.children,
+    };
+    widget.item.make_trace_span(&ctx).entered()
+}
+
 pub(crate) fn recurse_on_children(
     id: WidgetId,
     mut widget: ArenaMut<'_, Box<dyn Widget>>,
@@ -68,6 +100,12 @@ pub(crate) fn merge_state_up(arena: &mut WidgetArena, widget_id: WidgetId) {
 /// `MASONRY_TRACE_PASSES` environment variable.
 ///
 /// Note that passes which are bounded by depth (rather than absolute size) are never filtered out here.
+///
+/// Ideally, we'd cache the spans, which would make a lot (but not all) of this unnecessary.
+/// However, each pass uses a different parent span (with the individual pass's name), so it's
+/// (at best) non-trivial to make that work.
+///
+/// We could *maybe* use a global parent span called "Pass", with a name field, but that's extremely ugly.
 pub(crate) struct PassTracing {
     pub(crate) update_tree: bool,
     pub(crate) anim: bool,

masonry/src/passes/paint.rs

@@ -8,7 +8,7 @@ use vello::kurbo::{Affine, Stroke};
 use vello::peniko::Mix;
 use vello::Scene;
 
-use crate::passes::recurse_on_children;
+use crate::passes::{enter_span_if, recurse_on_children};
 use crate::render_root::{RenderRoot, RenderRootState};
 use crate::theme::get_debug_color;
 use crate::tree_arena::ArenaMut;
@@ -24,7 +24,8 @@ fn paint_widget(
     debug_paint: bool,
 ) {
     let trace = global_state.trace.paint;
-    let _span = trace.then(|| widget.item.make_trace_span().entered());
+    let _span = enter_span_if(trace, global_state, widget.reborrow(), state.reborrow());
+
     let id = state.item.id;
 
     // TODO - Handle invalidation regions

masonry/src/passes/update.rs

@@ -7,7 +7,7 @@ use cursor_icon::CursorIcon;
 use tracing::{info_span, trace};
 
 use crate::passes::event::run_on_pointer_event_pass;
-use crate::passes::{merge_state_up, recurse_on_children};
+use crate::passes::{enter_span, enter_span_if, merge_state_up, recurse_on_children};
 use crate::render_root::{RenderRoot, RenderRootSignal, RenderRootState};
 use crate::tree_arena::ArenaMut;
 use crate::{
@@ -82,7 +82,7 @@ fn update_widget_tree(
     mut state: ArenaMut<'_, WidgetState>,
 ) {
     let trace = global_state.trace.update_tree;
-    let _span = trace.then(|| widget.item.make_trace_span().entered());
+    let _span = enter_span_if(trace, global_state, widget.reborrow(), state.reborrow());
     let id = state.item.id;
 
     if !state.item.children_changed {
@@ -196,7 +196,7 @@ fn update_disabled_for_widget(
     mut state: ArenaMut<'_, WidgetState>,
     parent_disabled: bool,
 ) {
-    let _span = widget.item.make_trace_span().entered();
+    let _span = enter_span(global_state, widget.reborrow(), state.reborrow());
     let id = state.item.id;
 
     let disabled = state.item.is_explicitly_disabled || parent_disabled;
@@ -260,7 +260,7 @@ fn update_stashed_for_widget(
     mut state: ArenaMut<'_, WidgetState>,
     parent_stashed: bool,
 ) {
-    let _span = widget.item.make_trace_span().entered();
+    let _span = enter_span(global_state, widget.reborrow(), state.reborrow());
     let id = state.item.id;
 
     let stashed = state.item.is_explicitly_stashed || parent_stashed;
@@ -327,10 +327,10 @@ pub(crate) fn run_update_stashed_pass(root: &mut RenderRoot) {
 fn update_focus_chain_for_widget(
     global_state: &mut RenderRootState,
     mut widget: ArenaMut<'_, Box<dyn Widget>>,
-    state: ArenaMut<'_, WidgetState>,
+    mut state: ArenaMut<'_, WidgetState>,
     parent_focus_chain: &mut Vec<WidgetId>,
 ) {
-    let _span = widget.item.make_trace_span().entered();
+    let _span = enter_span(global_state, widget.reborrow(), state.reborrow());
     let id = state.item.id;
 
     if !state.item.update_focus_chain {