From eef2673ff3072ec2a1d65eaae4a4239af1da39b7 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?David=20Ml=C3=A1dek?= <david.mladek.cz@gmail.com>
Date: Wed, 17 Apr 2024 14:08:26 +0200
Subject: [PATCH 1/2] fix: set span end time when it exits

Setting end time when a span is closed makes it impossible for child
spans to live longer than their parents if we want to keep the
relationship in `tracing` itself.
---
 src/layer.rs | 14 ++++++++------
 1 file changed, 8 insertions(+), 6 deletions(-)

diff --git a/src/layer.rs b/src/layer.rs
index 83bed1d..43d2193 100644
--- a/src/layer.rs
+++ b/src/layer.rs
@@ -970,13 +970,17 @@ where
     }
 
     fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) {
+        let span = ctx.span(id).expect("Span not found, this is a bug");
+        let mut extensions = span.extensions_mut();
+
+        if let Some(otel_data) = extensions.get_mut::<OtelData>() {
+            otel_data.builder.end_time = Some(crate::time::now());
+        }
+
         if !self.tracked_inactivity {
             return;
         }
 
-        let span = ctx.span(id).expect("Span not found, this is a bug");
-        let mut extensions = span.extensions_mut();
-
         if let Some(timings) = extensions.get_mut::<Timings>() {
             let now = Instant::now();
             timings.busy += (now - timings.last).as_nanos() as i64;
@@ -1165,9 +1169,7 @@ where
             }
 
             // Assign end time, build and start span, drop span to export
-            builder
-                .with_end_time(crate::time::now())
-                .start_with_context(&self.tracer, &parent_cx);
+            builder.start_with_context(&self.tracer, &parent_cx);
         }
     }
 

From 54b86f71d85b0fa12de3342cb5a0498d7933f861 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?David=20Ml=C3=A1dek?= <david.mladek.cz@gmail.com>
Date: Mon, 29 Apr 2024 23:20:59 +0200
Subject: [PATCH 2/2] add trace benchmark with many enters and exits

---
 benches/trace.rs | 71 ++++++++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 69 insertions(+), 2 deletions(-)

diff --git a/benches/trace.rs b/benches/trace.rs
index 83c1e56..827bcc5 100644
--- a/benches/trace.rs
+++ b/benches/trace.rs
@@ -10,6 +10,65 @@ use std::time::SystemTime;
 use tracing::{trace, trace_span};
 use tracing_subscriber::prelude::*;
 
+fn many_enters(c: &mut Criterion) {
+    let mut group = c.benchmark_group("otel_many_enters");
+
+    group.bench_function("spec_baseline", |b| {
+        let provider = TracerProvider::default();
+        let tracer = provider.tracer("bench");
+        b.iter(|| {
+            fn dummy(tracer: &Tracer, cx: &Context) {
+                let mut span = tracer.start_with_context("child", cx);
+                for _ in 0..1000 {
+                    span.add_event("name", Vec::new());
+                }
+            }
+
+            tracer.in_span("parent", |cx| dummy(&tracer, &cx));
+        });
+    });
+
+    {
+        let _subscriber = tracing_subscriber::registry()
+            .with(RegistryAccessLayer)
+            .set_default();
+        group.bench_function("no_data_baseline", |b| b.iter(enters_harness));
+    }
+
+    {
+        let _subscriber = tracing_subscriber::registry()
+            .with(OtelDataLayer)
+            .set_default();
+        group.bench_function("data_only_baseline", |b| b.iter(enters_harness));
+    }
+
+    {
+        let provider = TracerProvider::default();
+        let tracer = provider.tracer("bench");
+        let otel_layer = tracing_opentelemetry::layer()
+            .with_tracer(tracer)
+            .with_tracked_inactivity(false);
+        let _subscriber = tracing_subscriber::registry()
+            .with(otel_layer)
+            .set_default();
+
+        group.bench_function("full_without_timings", |b| b.iter(enters_harness));
+    }
+
+    {
+        let provider = TracerProvider::default();
+        let tracer = provider.tracer("bench");
+        let otel_layer = tracing_opentelemetry::layer()
+            .with_tracer(tracer)
+            .with_tracked_inactivity(true);
+        let _subscriber = tracing_subscriber::registry()
+            .with(otel_layer)
+            .set_default();
+
+        group.bench_function("full_with_timings", |b| b.iter(enters_harness));
+    }
+}
+
 fn many_children(c: &mut Criterion) {
     let mut group = c.benchmark_group("otel_many_children");
 
@@ -231,6 +290,14 @@ fn tracing_harness() {
     dummy();
 }
 
+fn enters_harness() {
+    let span = trace_span!("span");
+    for _ in 0..1000 {
+        let guard = span.enter();
+        _ = criterion::black_box(guard)
+    }
+}
+
 fn events_harness() {
     fn dummy() {
         let _child = trace_span!("child").entered();
@@ -249,12 +316,12 @@ fn events_harness() {
 criterion_group! {
     name = benches;
     config = Criterion::default().with_profiler(PProfProfiler::new(100, Output::Flamegraph(None)));
-    targets = many_children, many_events
+    targets = many_enters, many_children, many_events
 }
 #[cfg(target_os = "windows")]
 criterion_group! {
     name = benches;
     config = Criterion::default();
-    targets = many_children, many_events
+    targets = many_enters, many_children, many_events
 }
 criterion_main!(benches);