feat(telemetry): USDT probes for tracing spans end

examples/Cargo.toml

@@ -22,3 +22,7 @@ tokio = { workspace = true, features = ["full"]}
 [[example]]
 name = "http_server"
 path = "http_server/main.rs"
+
+[[example]]
+name = "span_with_probe"
+path = "span_with_probe/main.rs"

examples/README.md

@@ -21,5 +21,34 @@ cargo run --example http_server -- --config http_server/example_conf.yaml
 ```
 
 
+## `span_with_probe`
+
+
+Demo workload for per-span USDT probes. Runs two instrumented spans in a
+loop; attach with bpftrace to get a duration histogram:
+
+```
+cargo run --example span_with_probe
+sudo bpftrace examples/span_with_probe/span_durations.bt -p <pid>
+```
+
+Sample output:
+
+```
+Attaching to span end probes, durations in milliseconds...
+Hit Ctrl-C to end and print histograms.
+^C
+
+@long_task_ms:
+[32, 64)              15 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
+[64, 128)             12 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           |
+
+@short_task_ms:
+[4, 8)                 2 |@@@@@                                               |
+[8, 16)                8 |@@@@@@@@@@@@@@@@@@@@@@@                             |
+[16, 32)              18 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
+```
+
+
 
 

examples/span_with_probe/main.rs

@@ -0,0 +1,60 @@
+//! Demo workload for the `span_with_probe!` macro.
+//!
+//! Two instrumented spans with distinct delay ranges run in a loop. Attach
+//! with bpftrace to get duration histograms for both spans (from the repo
+//! root, so the probe path resolves):
+//!
+//! ```text
+//! bpftrace examples/span_with_probe/span_durations.bt -p <pid>
+//! ```
+//!
+//! No telemetry context is installed: every span is unsampled and tracing is
+//! effectively disabled. This is intentional — the USDT probe must fire
+//! regardless of span sampling.
+
+use foundations::telemetry::tracing::span_with_probe;
+use std::io::Write as _;
+use std::time::Duration;
+
+/// Span with a 5-25ms delay range.
+async fn short_task(iter: u64) {
+    let work_fut = async move {
+        // Simulate variable work so durations show up as a histogram.
+        tokio::time::sleep(Duration::from_millis(5 + iter % 20)).await;
+    };
+
+    span_with_probe!("example::short_task")
+        .into_context()
+        .apply(work_fut)
+        .await;
+}
+
+/// Span with a distinct delay range (50-70ms) so the two can be told apart
+/// in a duration histogram.
+async fn long_task(iter: u64) {
+    let work_fut = async move {
+        tokio::time::sleep(Duration::from_millis(50 + iter % 20)).await;
+    };
+
+    span_with_probe!("example::long_task")
+        .into_context()
+        .apply(work_fut)
+        .await;
+}
+
+#[tokio::main(flavor = "current_thread")]
+async fn main() {
+    println!("pid {}", std::process::id());
+
+    let mut iter = 0;
+    loop {
+        short_task(iter).await;
+        long_task(iter).await;
+
+        print!("\riteration {iter}");
+        std::io::stdout().flush().unwrap();
+
+        iter += 1;
+        tokio::time::sleep(Duration::from_millis(100)).await;
+    }
+}

examples/span_with_probe/span_durations.bt

@@ -0,0 +1,23 @@
+/*
+ * Duration histograms for the span_with_probe example's spans.
+ *
+ * Run from the repository root (the probe path is relative to the cwd):
+ *
+ *   cargo run --example span_with_probe
+ *   sudo bpftrace examples/span_with_probe/span_durations.bt -p <pid>
+ *
+ * Probes receive the span duration in nanoseconds as arg0; recorded here in
+ * milliseconds.
+ */
+BEGIN {
+    printf("Attaching to span end probes, durations in milliseconds...\n");
+    printf("Hit Ctrl-C to end and print histograms.\n");
+}
+
+usdt:target/debug/examples/span_with_probe:foundations:span_end_example__short_task {
+    @short_task_ms = hist((uint64)arg0 / 1000000);
+}
+
+usdt:target/debug/examples/span_with_probe:foundations:span_end_example__long_task {
+    @long_task_ms = hist((uint64)arg0 / 1000000);
+}

foundations-macros/src/lib.rs

@@ -3,6 +3,7 @@ mod info_metric;
 mod metrics;
 mod settings;
 mod span_fn;
+mod span_with_probe;
 mod with_test_telemetry;
 
 use proc_macro::TokenStream;
@@ -27,6 +28,44 @@ pub fn span_fn(args: TokenStream, item: TokenStream) -> TokenStream {
     span_fn::expand(args, item)
 }
 
+/// Like `foundations::telemetry::tracing::span`, plus a per-span USDT probe at
+/// span end.
+///
+/// Probes are only emitted on linux/x86_64; on any other platform the macro
+/// degrades to a plain `foundations::telemetry::tracing::span` call.
+///
+/// The probe shows up to tracers as
+/// `<binary>:<usdt_provider>:span_end_<sanitized span name>`, where
+/// sanitization replaces `::` with `__` and any other non-alphanumeric
+/// character with `_`.
+///
+/// Expands a dedicated probe semaphore: a `static` in the `.probes` ELF section
+/// that the tracer (like bpftrace) increments on attach. When the semaphore is
+/// non-zero, the span start timestamp is recorded in the span state (regardless
+/// of span sampling), and the per-span `probe_end` function's address is stored
+/// alongside it. When the last clone of the span drops, `probe_end` is called
+/// with the span duration in nanoseconds, executing the NOP whose address the
+/// `stapsdt` ELF note publishes as the `span_end_<sanitized>` probe location.
+///
+/// # Example
+///
+/// ```rust,ignore
+/// use foundations::telemetry::tracing::span_with_probe;
+///
+/// span_with_probe!("tls::keyless::client::exchange_on_stream", usdt_provider = "bastion")
+///      .into_context()
+///      .apply(do_exchange())
+///      .await
+/// ```
+///
+/// Options:
+/// - `crate_path = "..."` (defaults to `::foundations`)
+/// - `usdt_provider = "..."` (defaults to `"foundations"`)
+#[proc_macro]
+pub fn span_with_probe(input: TokenStream) -> TokenStream {
+    span_with_probe::expand(input)
+}
+
 #[proc_macro_attribute]
 pub fn with_test_telemetry(args: TokenStream, item: TokenStream) -> TokenStream {
     with_test_telemetry::expand(args, item)