Draft: redo tracing UI and add span close events

Author: rcoh

dial9-tokio-telemetry/Cargo.toml

@@ -129,6 +129,10 @@ harness = false
 name = "threadlocal_encode"
 harness = false
 
+[[example]]
+name = "tracing_sleep"
+required-features = ["tracing-layer"]
+
 [[bench]]
 name = "tracing_layer_bench"
 harness = false

dial9-tokio-telemetry/src/tracing_layer.rs

@@ -57,6 +57,7 @@
 //! for production use with appropriate span filtering.
 
 use crate::telemetry::{TelemetryHandle, clock_monotonic_ns, current_worker_id};
+use dial9_trace_format::TraceEvent;
 use dial9_trace_format::encoder::Schema;
 use dial9_trace_format::schema::FieldDef;
 use dial9_trace_format::types::{FieldType, FieldValue};
@@ -67,6 +68,13 @@ use tracing::callsite::Identifier;
 use tracing::span;
 use tracing_subscriber::{Layer, layer::Context, registry::LookupSpan};
 
+#[derive(TraceEvent)]
+struct SpanCloseEvent {
+    #[traceevent(timestamp)]
+    timestamp_ns: u64,
+    span_id: u64,
+}
+
 // ── Per-callsite schema cache ───────────────────────────────────────────────
 
 /// Cached schemas for a single callsite (one for enter, one for exit).
@@ -367,4 +375,15 @@ where
             enc.write_event(&schemas.exit, &values);
         });
     }
+
+    fn on_close(&self, id: span::Id, _ctx: Context<'_, S>) {
+        let Some(handle) = TelemetryHandle::try_current() else {
+            return;
+        };
+
+        handle.record_encodable_event(&SpanCloseEvent {
+            timestamp_ns: clock_monotonic_ns(),
+            span_id: id.into_u64(),
+        });
+    }
 }

dial9-tokio-telemetry/tests/tracing_layer.rs

@@ -14,6 +14,7 @@ use tracing_subscriber::prelude::*;
 struct SpanEvents {
     enter_count: u32,
     exit_count: u32,
+    close_count: u32,
     enter_names: Vec<String>,
     /// All (field_key, field_value) pairs seen on enter events.
     enter_fields: Vec<(String, String)>,
@@ -34,6 +35,7 @@ fn decode_span_events(path: &std::path::Path) -> SpanEvents {
     let mut result = SpanEvents {
         enter_count: 0,
         exit_count: 0,
+        close_count: 0,
         enter_names: Vec::new(),
         enter_fields: Vec::new(),
         exit_fields: Vec::new(),
@@ -88,6 +90,8 @@ fn decode_span_events(path: &std::path::Path) -> SpanEvents {
                             .push((field_def.name.clone(), v.to_owned()));
                     }
                 }
+            } else if ev.name == "SpanCloseEvent" {
+                result.close_count += 1;
             }
         })
         .unwrap();
@@ -185,6 +189,12 @@ fn span_events_appear_in_trace() {
         "enter/exit count mismatch"
     );
 
+    // Close events: one per unique span instance
+    assert!(
+        events.close_count > 0,
+        "expected at least 1 SpanCloseEvent, got 0"
+    );
+
     // Span names
     assert!(
         events.enter_names.contains(&"handle_request".to_string()),

dial9-viewer/skills/analyze.js

@@ -198,14 +198,12 @@ function accumulateTrace(acc, trace) {
 
   // Span durations (native HDR histogram for bounded memory, exact percentiles)
   if (trace.customEvents && trace.customEvents.length > 0) {
-    const { spansByWorker } = buildSpanData(trace.customEvents);
-    for (const spans of Object.values(spansByWorker)) {
-      for (const s of spans) {
-        const dur = Math.max(1, Math.round(s.end - s.start));
-        let h = acc.spanStats.get(s.spanName);
-        if (!h) { h = createHistogram(); acc.spanStats.set(s.spanName, h); }
-        h.record(dur);
-      }
+    const { allSpans } = buildSpanData(trace.customEvents);
+    for (const s of allSpans) {
+      const dur = Math.max(1, Math.round(s.end - s.start));
+      let h = acc.spanStats.get(s.spanName);
+      if (!h) { h = createHistogram(); acc.spanStats.set(s.spanName, h); }
+      h.record(dur);
     }
   }
 }
@@ -767,8 +765,8 @@ function analyzeWorkerMain(cachePath) {
   partial.schedDelayWorst.sort((a, b) => b.delay - a.delay);
   partial.schedDelayWorst.length = Math.min(partial.schedDelayWorst.length, 100);
   if (trace.customEvents && trace.customEvents.length > 0) {
-    const { spansByWorker } = buildSpanData(trace.customEvents);
-    for (const ss of Object.values(spansByWorker)) for (const s of ss)
+    const { allSpans } = buildSpanData(trace.customEvents);
+    for (const s of allSpans)
       (partial.spanDurations[s.spanName] || (partial.spanDurations[s.spanName] = [])).push(Math.max(1, Math.round(s.end - s.start)));
   }
   process.stdout.write(JSON.stringify(partial) + '\n');

dial9-viewer/ui/demo-trace.bin

@@ -373,20 +373,18 @@ async function main() {
       { name: "SpanExitEvent",  timestamp: 1200, fields: { worker_id: 0, span_id: 2, span_name: "redis_get", fields: { key: "foo" } } },
       { name: "SpanExitEvent",  timestamp: 1300, fields: { worker_id: 0, span_id: 1, span_name: "handle_request", fields: { user_id: "42" } } },
     ];
-    const { spansByWorker, spanMeta } = buildSpanData(customEvents);
-    const w0 = spansByWorker[0] || [];
-    if (w0.length !== 2) fail(`Expected 2 span intervals on worker 0, got ${w0.length}`);
-    if (w0[0].spanName !== "handle_request" && w0[1].spanName !== "handle_request")
-      fail("Missing handle_request span");
-    if (w0[0].spanName !== "redis_get" && w0[1].spanName !== "redis_get")
-      fail("Missing redis_get span");
-    // Verify sorted by start time
-    if (w0[0].start > w0[1].start) fail("Spans not sorted by start time");
-    // Verify enter/exit pairing
-    const redis = w0.find(s => s.spanName === "redis_get");
+    const { allSpans, spanMeta } = buildSpanData(customEvents);
+    if (allSpans.length !== 2) fail(`Expected 2 spans, got ${allSpans.length}`);
+    const redis = allSpans.find(s => s.spanName === "redis_get");
+    const handle = allSpans.find(s => s.spanName === "handle_request");
+    if (!redis || !handle) fail("Missing expected spans");
     if (redis.start !== 1100 || redis.end !== 1200) fail("redis_get timing wrong");
+    if (redis.segments.length !== 1) fail(`Expected 1 segment, got ${redis.segments.length}`);
+    if (redis.segments[0].workerId !== 0) fail("segment workerId wrong");
     if (!spanMeta.has(1) || !spanMeta.has(2)) fail("spanMeta missing entries");
-    pass(`${w0.length} span intervals paired correctly`);
+    // Verify sorted by start time
+    if (allSpans[0].start > allSpans[1].start) fail("Spans not sorted by start time");
+    pass(`${allSpans.length} spans paired correctly`);
   }
 
   function testBuildSpanDataParent() {
@@ -396,17 +394,17 @@ async function main() {
       { name: "SpanExitEvent",  timestamp: 1200, fields: { worker_id: 0, span_id: 20, span_name: "child", fields: {} } },
       { name: "SpanExitEvent",  timestamp: 1300, fields: { worker_id: 0, span_id: 10, span_name: "root", fields: {} } },
     ];
-    const { spansByWorker } = buildSpanData(customEvents);
-    const child = spansByWorker[0].find(s => s.spanName === "child");
+    const { allSpans } = buildSpanData(customEvents);
+    const child = allSpans.find(s => s.spanName === "child");
     if (child.parentSpanId !== 10) fail(`Expected parentSpanId=10, got ${child.parentSpanId}`);
-    const root = spansByWorker[0].find(s => s.spanName === "root");
+    const root = allSpans.find(s => s.spanName === "root");
     if (root.parentSpanId !== null) fail(`Expected root parentSpanId=null, got ${root.parentSpanId}`);
     pass("Parent span IDs preserved correctly");
   }
 
   function testBuildSpanDataEmpty() {
-    const { spansByWorker, spanMeta } = buildSpanData([]);
-    if (Object.keys(spansByWorker).length !== 0) fail("Expected empty spansByWorker");
+    const { allSpans, spanMeta } = buildSpanData([]);
+    if (allSpans.length !== 0) fail("Expected empty allSpans");
     if (spanMeta.size !== 0) fail("Expected empty spanMeta");
     pass("Empty input produces empty output");
   }
@@ -421,11 +419,10 @@ async function main() {
       { name: "SpanExitEvent",  timestamp: 1400, fields: { worker_id: 0, span_id: 2, span_name: "mid", fields: {} } },
       { name: "SpanExitEvent",  timestamp: 1500, fields: { worker_id: 0, span_id: 1, span_name: "root", fields: {} } },
     ];
-    const { spansByWorker, maxDepth } = buildSpanData(customEvents);
-    const spans = spansByWorker[0];
-    const root = spans.find(s => s.spanName === "root");
-    const mid = spans.find(s => s.spanName === "mid");
-    const leaf = spans.find(s => s.spanName === "leaf");
+    const { allSpans, maxDepth } = buildSpanData(customEvents);
+    const root = allSpans.find(s => s.spanName === "root");
+    const mid = allSpans.find(s => s.spanName === "mid");
+    const leaf = allSpans.find(s => s.spanName === "leaf");
     if (root.depth !== 0) fail(`root depth=${root.depth}, expected 0`);
     if (mid.depth !== 1) fail(`mid depth=${mid.depth}, expected 1`);
     if (leaf.depth !== 2) fail(`leaf depth=${leaf.depth}, expected 2`);
@@ -441,31 +438,31 @@ async function main() {
       { name: "SpanExitEvent",  timestamp: 1200, fields: { worker_id: 0, span_id: 2, span_name: "b", fields: {} } },
       { name: "SpanExitEvent",  timestamp: 1300, fields: { worker_id: 0, span_id: 1, span_name: "a", fields: {} } },
     ];
-    const { spansByWorker } = buildSpanData(customEvents);
-    if (!spansByWorker[0] || spansByWorker[0].length !== 2) fail("Expected 2 spans");
+    const { allSpans } = buildSpanData(customEvents);
+    if (allSpans.length !== 2) fail("Expected 2 spans");
     // Just verify it didn't crash; depths may be arbitrary due to cycle
     pass("Cyclic parent chain does not stack overflow");
   }
 
   function testBuildSpanDataRecycledId() {
-    // Span ID 1 used first as "alpha", then recycled as "beta"
+    // Span ID 1 used first as "alpha", closed, then recycled as "beta"
     const customEvents = [
       { name: "SpanEnterEvent", timestamp: 1000, fields: { worker_id: 0, span_id: 1, parent_span_id: null, span_name: "alpha", fields: {} } },
       { name: "SpanExitEvent",  timestamp: 1100, fields: { worker_id: 0, span_id: 1, span_name: "alpha", fields: {} } },
+      { name: "SpanCloseEvent", timestamp: 1150, fields: { span_id: 1 } },
       // Same span_id reused with different name
       { name: "SpanEnterEvent", timestamp: 2000, fields: { worker_id: 0, span_id: 1, parent_span_id: null, span_name: "beta", fields: {} } },
       { name: "SpanExitEvent",  timestamp: 2100, fields: { worker_id: 0, span_id: 1, span_name: "beta", fields: {} } },
+      { name: "SpanCloseEvent", timestamp: 2150, fields: { span_id: 1 } },
       // Child of the recycled span
       { name: "SpanEnterEvent", timestamp: 3000, fields: { worker_id: 0, span_id: 2, parent_span_id: 1, span_name: "child", fields: {} } },
       { name: "SpanExitEvent",  timestamp: 3100, fields: { worker_id: 0, span_id: 2, span_name: "child", fields: {} } },
     ];
-    const { spansByWorker } = buildSpanData(customEvents);
-    const spans = spansByWorker[0];
-    if (spans.length !== 3) fail(`Expected 3 spans, got ${spans.length}`);
-    const alpha = spans.find(s => s.spanName === "alpha");
-    const beta = spans.find(s => s.spanName === "beta");
+    const { allSpans } = buildSpanData(customEvents);
+    if (allSpans.length !== 3) fail(`Expected 3 spans, got ${allSpans.length}`);
+    const alpha = allSpans.find(s => s.spanName === "alpha");
+    const beta = allSpans.find(s => s.spanName === "beta");
     if (!alpha || !beta) fail("Missing alpha or beta span");
-    // Both should exist as separate intervals despite same span_id
     if (alpha.start !== 1000 || beta.start !== 2000) fail("Span intervals not distinct");
     pass("Recycled span IDs produce separate intervals");
   }
@@ -477,14 +474,13 @@ async function main() {
       { name: "SpanEnter:myapp::handle:src/main.rs:10", timestamp: 1000, fields: { worker_id: 0, span_id: 1, parent_span_id: null, span_name: "handle", request_id: "abc-123" } },
       { name: "SpanExit:myapp::handle:src/main.rs:10",  timestamp: 1100, fields: { worker_id: 0, span_id: 1, span_name: "handle", request_id: "abc-123" } },
     ];
-    const { spansByWorker } = buildSpanData(customEvents);
-    const spans = spansByWorker[0];
-    if (!spans || spans.length !== 1) fail(`Expected 1 span, got ${spans?.length}`);
-    if (spans[0].spanName !== "handle") fail(`Expected span name 'handle', got '${spans[0].spanName}'`);
-    if (spans[0].fields.request_id !== "abc-123") fail(`Expected request_id='abc-123', got '${spans[0].fields.request_id}'`);
+    const { allSpans } = buildSpanData(customEvents);
+    if (!allSpans || allSpans.length !== 1) fail(`Expected 1 span, got ${allSpans?.length}`);
+    if (allSpans[0].spanName !== "handle") fail(`Expected span name 'handle', got '${allSpans[0].spanName}'`);
+    if (allSpans[0].fields.request_id !== "abc-123") fail(`Expected request_id='abc-123', got '${allSpans[0].fields.request_id}'`);
     // Base fields should NOT appear in the user fields
-    if (spans[0].fields.worker_id) fail("worker_id should not be in user fields");
-    if (spans[0].fields.span_name) fail("span_name should not be in user fields");
+    if (allSpans[0].fields.worker_id) fail("worker_id should not be in user fields");
+    if (allSpans[0].fields.span_name) fail("span_name should not be in user fields");
     pass("Per-callsite schema with typed fields parsed correctly");
   }
 
@@ -495,15 +491,39 @@ async function main() {
       // This enter has no matching exit (trace ended mid-span)
       { name: "SpanEnter:app::b:f:2", timestamp: 1200, fields: { worker_id: 0, span_id: 2, parent_span_id: null, span_name: "b" } },
     ];
-    const { spansByWorker, unmatchedSpans } = buildSpanData(customEvents);
-    const matched = spansByWorker[0] || [];
-    if (matched.length !== 1) fail(`Expected 1 matched span, got ${matched.length}`);
+    const { allSpans, unmatchedSpans } = buildSpanData(customEvents);
+    if (allSpans.length !== 1) fail(`Expected 1 matched span, got ${allSpans.length}`);
     if (!unmatchedSpans || unmatchedSpans.length !== 1) fail(`Expected 1 unmatched span, got ${unmatchedSpans?.length}`);
     if (unmatchedSpans[0].spanName !== "b") fail(`Expected unmatched span 'b', got '${unmatchedSpans[0].spanName}'`);
     if (unmatchedSpans[0].spanId !== 2) fail(`Expected unmatched spanId 2, got ${unmatchedSpans[0].spanId}`);
     pass("Unmatched spans (enter without exit) detected correctly");
   }
 
+  function testBuildSpanDataMultiplePolls() {
+    // A span entered/exited multiple times (async future polled 3 times with sleep gap)
+    const customEvents = [
+      { name: "SpanEnter:app::f:f:1", timestamp: 1000, fields: { worker_id: 0, span_id: 1, parent_span_id: null, span_name: "my_fn" } },
+      { name: "SpanExit:app::f:f:1",  timestamp: 1500, fields: { worker_id: 0, span_id: 1, span_name: "my_fn" } },
+      { name: "SpanEnter:app::f:f:1", timestamp: 100000, fields: { worker_id: 1, span_id: 1, parent_span_id: null, span_name: "my_fn" } },
+      { name: "SpanExit:app::f:f:1",  timestamp: 100200, fields: { worker_id: 1, span_id: 1, span_name: "my_fn" } },
+      { name: "SpanEnter:app::f:f:1", timestamp: 100300, fields: { worker_id: 0, span_id: 1, parent_span_id: null, span_name: "my_fn" } },
+      { name: "SpanExit:app::f:f:1",  timestamp: 100400, fields: { worker_id: 0, span_id: 1, span_name: "my_fn" } },
+      { name: "SpanCloseEvent",        timestamp: 100500, fields: { span_id: 1 } },
+    ];
+    const { allSpans } = buildSpanData(customEvents);
+    if (allSpans.length !== 1) fail(`Expected 1 span, got ${allSpans.length}`);
+    const s = allSpans[0];
+    if (s.segments.length !== 3) fail(`Expected 3 segments, got ${s.segments.length}`);
+    if (s.start !== 1000) fail(`Expected start=1000, got ${s.start}`);
+    if (s.end !== 100400) fail(`Expected end=100400, got ${s.end}`);
+    // activeNs = 500 + 200 + 100 = 800
+    if (s.activeNs !== 800) fail(`Expected activeNs=800, got ${s.activeNs}`);
+    // Workers: polled on both 0 and 1
+    const workers = [...new Set(s.segments.map(seg => seg.workerId))].sort();
+    if (workers.length !== 2 || workers[0] !== 0 || workers[1] !== 1) fail(`Expected workers [0,1], got ${workers}`);
+    pass("Multiple polls grouped into single span with segments");
+  }
+
   // ── Regression: open PollStart at trace end must not create phantom poll (#194) ──
 
   function testOpenPollStartDiscarded() {
@@ -576,6 +596,7 @@ async function main() {
   testBuildSpanDataRecycledId();
   testBuildSpanDataPerCallsiteSchema();
   testBuildSpanDataUnmatched();
+  testBuildSpanDataMultiplePolls();
 
   console.log("\n✓ All analysis checks passed!");
 }