diff --git a/examples/tracing-http-propagator/src/server.rs b/examples/tracing-http-propagator/src/server.rs index 8060c99841..c1be13a043 100644 --- a/examples/tracing-http-propagator/src/server.rs +++ b/examples/tracing-http-propagator/src/server.rs @@ -15,12 +15,17 @@ use opentelemetry_sdk::{ error::OTelSdkResult, logs::{LogProcessor, SdkLogRecord, SdkLoggerProvider}, propagation::{BaggagePropagator, TraceContextPropagator}, - trace::{SdkTracerProvider, SpanProcessor}, + trace::{FinishedSpan, ReadableSpan, SdkTracerProvider, SpanProcessor}, }; use opentelemetry_semantic_conventions::trace; use opentelemetry_stdout::{LogExporter, SpanExporter}; use std::time::Duration; -use std::{convert::Infallible, net::SocketAddr, sync::OnceLock}; +use std::{ + collections::HashMap, + convert::Infallible, + net::SocketAddr, + sync::{Mutex, OnceLock}, +}; use tokio::net::TcpListener; use tracing::info; use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt}; @@ -84,6 +89,7 @@ async fn router( let span = tracer .span_builder("router") .with_kind(SpanKind::Server) + .with_attributes([KeyValue::new("http.route", req.uri().path().to_string())]) .start_with_context(tracer, &parent_cx); info!(name = "router", message = "Dispatching request"); @@ -105,6 +111,66 @@ async fn router( response } +#[derive(Debug, Default)] +/// A custom span processor that counts concurrent requests for each route (indentified by the http.route +/// attribute) and adds that information to the span attributes. +struct RouteConcurrencyCounterSpanProcessor(Mutex>); + +impl SpanProcessor for RouteConcurrencyCounterSpanProcessor { + fn force_flush(&self) -> OTelSdkResult { + Ok(()) + } + + fn shutdown_with_timeout(&self, _timeout: Duration) -> crate::OTelSdkResult { + Ok(()) + } + + fn on_start(&self, span: &mut opentelemetry_sdk::trace::Span, _cx: &Context) { + if !matches!(span.span_kind(), SpanKind::Server) { + return; + } + let Some(route) = span + .attributes() + .iter() + .find(|kv| kv.key.as_str() == "http.route") + else { + return; + }; + let Ok(mut counts) = self.0.lock() else { + return; + }; + let count = counts.entry(route.key.clone()).or_default(); + *count += 1; + span.set_attribute(KeyValue::new( + "http.route.concurrent_requests", + *count as i64, + )); + } + + fn on_end(&self, span: &mut FinishedSpan) { + if !matches!(span.span_kind(), SpanKind::Server) { + return; + } + let Some(route) = span + .attributes() + .iter() + .find(|kv| kv.key.as_str() == "http.route") + else { + return; + }; + let Ok(mut counts) = self.0.lock() else { + return; + }; + let Some(count) = counts.get_mut(&route.key) else { + return; + }; + *count -= 1; + if *count == 0 { + counts.remove(&route.key); + } + } +} + /// A custom log processor that enriches LogRecords with baggage attributes. /// Baggage information is not added automatically without this processor. #[derive(Debug)] @@ -146,7 +212,7 @@ impl SpanProcessor for EnrichWithBaggageSpanProcessor { } } - fn on_end(&self, _span: opentelemetry_sdk::trace::SpanData) {} + fn on_end(&self, _span: &mut opentelemetry_sdk::trace::FinishedSpan) {} } fn init_tracer() -> SdkTracerProvider { @@ -162,6 +228,7 @@ fn init_tracer() -> SdkTracerProvider { // Setup tracerprovider with stdout exporter // that prints the spans to stdout. let provider = SdkTracerProvider::builder() + .with_span_processor(RouteConcurrencyCounterSpanProcessor::default()) .with_span_processor(EnrichWithBaggageSpanProcessor) .with_simple_exporter(SpanExporter::default()) .build(); diff --git a/opentelemetry-sdk/CHANGELOG.md b/opentelemetry-sdk/CHANGELOG.md index 4f91ae7f75..6415773c9b 100644 --- a/opentelemetry-sdk/CHANGELOG.md +++ b/opentelemetry-sdk/CHANGELOG.md @@ -2,6 +2,20 @@ ## vNext +- **Breaking** `SpanProcessor::on_end` now takes `&mut FinishedSpan` instead of `SpanData`. + Processors that only need to read span data can use the `ReadableSpan` trait without cloning. + Processors that need ownership call `FinishedSpan::consume()` — the last processor receives + ownership via move (zero-copy), earlier processors receive a clone. Both `Span` (live) and + `FinishedSpan` (ended) implement `ReadableSpan`, enabling processors to inspect span data + in both `on_start` and `on_end` hooks. New `FinishedSpan::is_consumed()` method allows + checking whether span data has been consumed. + Supersedes [#2962](https://github.com/open-telemetry/opentelemetry-rust/pull/2962). + Relates to [#2940](https://github.com/open-telemetry/opentelemetry-rust/issues/2940), + [#2726](https://github.com/open-telemetry/opentelemetry-rust/issues/2726), + [#2939](https://github.com/open-telemetry/opentelemetry-rust/issues/2939). +- Fix `Span::end_with_timestamp` preserving explicit end times even when equal to start time, + instead of silently overwriting with the current time. + ## 0.32.1 Released 2026-May-23 diff --git a/opentelemetry-sdk/Cargo.toml b/opentelemetry-sdk/Cargo.toml index 1a10758afa..bb65611c90 100644 --- a/opentelemetry-sdk/Cargo.toml +++ b/opentelemetry-sdk/Cargo.toml @@ -129,6 +129,11 @@ name = "bound_instruments" harness = false required-features = ["metrics", "experimental_metrics_custom_reader", "experimental_metrics_bound_instruments", "spec_unstable_metrics_views"] +[[bench]] +name = "span_processor_api" +harness = false +required-features = ["testing"] + [lib] bench = false diff --git a/opentelemetry-sdk/benches/batch_span_processor.rs b/opentelemetry-sdk/benches/batch_span_processor.rs index 6e90b9a62b..9f0f2ca07b 100644 --- a/opentelemetry-sdk/benches/batch_span_processor.rs +++ b/opentelemetry-sdk/benches/batch_span_processor.rs @@ -4,10 +4,10 @@ use opentelemetry::trace::{ SpanContext, SpanId, SpanKind, Status, TraceFlags, TraceId, TraceState, }; use opentelemetry_sdk::testing::trace::NoopSpanExporter; -use opentelemetry_sdk::trace::SpanData; use opentelemetry_sdk::trace::{ BatchConfigBuilder, BatchSpanProcessor, SpanEvents, SpanLinks, SpanProcessor, }; +use opentelemetry_sdk::trace::{FinishedSpan, SpanData}; use std::sync::Arc; use tokio::runtime::Runtime; @@ -63,7 +63,8 @@ fn criterion_benchmark(c: &mut Criterion) { let spans = get_span_data(); handles.push(tokio::spawn(async move { for span in spans { - span_processor.on_end(span); + let mut span = FinishedSpan::new(span); + span_processor.on_end(&mut span); tokio::task::yield_now().await; } })); diff --git a/opentelemetry-sdk/benches/span_processor_api.rs b/opentelemetry-sdk/benches/span_processor_api.rs new file mode 100644 index 0000000000..882e46e54b --- /dev/null +++ b/opentelemetry-sdk/benches/span_processor_api.rs @@ -0,0 +1,88 @@ +use std::time::Duration; + +use criterion::{black_box, criterion_group, criterion_main, Criterion}; +use opentelemetry::{ + trace::{Span, Tracer, TracerProvider}, + Context, KeyValue, +}; +use opentelemetry_sdk::trace as sdktrace; + +#[cfg(not(target_os = "windows"))] +use pprof::criterion::{Output, PProfProfiler}; + +/* +Adding results in comments for a quick reference. + Chip: Apple M4 Max + Total Number of Cores: 16 (12 performance and 4 efficiency) + +SpanProcessorApi/0_processors + time: [190.51 ns 190.82 ns 191.13 ns] +SpanProcessorApi/1_processors + time: [191.60 ns 192.53 ns 193.42 ns] +SpanProcessorApi/2_processors + time: [191.24 ns 191.67 ns 192.15 ns] +SpanProcessorApi/4_processors + time: [192.94 ns 193.48 ns 194.12 ns] +*/ + +#[derive(Debug)] +struct NoopSpanProcessor; + +impl sdktrace::SpanProcessor for NoopSpanProcessor { + fn on_start(&self, _span: &mut sdktrace::Span, _parent_cx: &Context) {} + fn on_end(&self, _span: &mut sdktrace::FinishedSpan) {} + fn force_flush(&self) -> opentelemetry_sdk::error::OTelSdkResult { + Ok(()) + } + fn shutdown_with_timeout(&self, _timeout: Duration) -> opentelemetry_sdk::error::OTelSdkResult { + Ok(()) + } +} + +fn create_tracer(span_processors_count: usize) -> sdktrace::SdkTracer { + let mut builder = sdktrace::SdkTracerProvider::builder(); + for _ in 0..span_processors_count { + builder = builder.with_span_processor(NoopSpanProcessor); + } + builder.build().tracer("tracer") +} + +fn create_span(tracer: &sdktrace::Tracer) -> sdktrace::Span { + let mut span = tracer.start("foo"); + span.set_attribute(KeyValue::new("key1", false)); + span.set_attribute(KeyValue::new("key2", "hello")); + span.set_attribute(KeyValue::new("key4", 123.456)); + span.add_event("my_event", vec![KeyValue::new("key1", "value1")]); + span +} + +fn criterion_benchmark(c: &mut Criterion) { + let mut group = c.benchmark_group("SpanProcessorApi"); + for i in [0, 1, 2, 4] { + group.bench_function(format!("{}_processors", i), |b| { + let tracer = create_tracer(i); + b.iter(|| { + black_box(create_span(&tracer)); + }); + }); + } +} + +#[cfg(not(target_os = "windows"))] +criterion_group! { + name = benches; + config = Criterion::default().with_profiler(PProfProfiler::new(100, Output::Flamegraph(None))) + .warm_up_time(std::time::Duration::from_secs(1)) + .measurement_time(std::time::Duration::from_secs(2)); + targets = criterion_benchmark +} + +#[cfg(target_os = "windows")] +criterion_group! { + name = benches; + config = Criterion::default().warm_up_time(std::time::Duration::from_secs(1)) + .measurement_time(std::time::Duration::from_secs(2)); + targets = criterion_benchmark +} + +criterion_main!(benches); diff --git a/opentelemetry-sdk/src/trace/mod.rs b/opentelemetry-sdk/src/trace/mod.rs index 00156ae6f9..473f2fcf27 100644 --- a/opentelemetry-sdk/src/trace/mod.rs +++ b/opentelemetry-sdk/src/trace/mod.rs @@ -37,7 +37,7 @@ pub use id_generator::{IdGenerator, RandomIdGenerator}; pub use links::SpanLinks; pub use provider::{SdkTracerProvider, TracerProviderBuilder}; pub use sampler::{Sampler, SamplingDecision, SamplingResult, ShouldSample}; -pub use span::Span; +pub use span::{FinishedSpan, ReadableSpan, Span}; pub use span_limit::SpanLimits; pub use span_processor::{ BatchConfig, BatchConfigBuilder, BatchSpanProcessor, BatchSpanProcessorBuilder, @@ -150,7 +150,7 @@ mod tests { } } - fn on_end(&self, span: SpanData) { + fn on_end(&self, span: &mut FinishedSpan) { // Fixed: Context::current() no longer panics from Drop // See https://github.com/open-telemetry/opentelemetry-rust/issues/2871 Context::current(); @@ -161,7 +161,7 @@ mod tests { // Verify: on_start stored the baggage as an attribute assert!( - span.attributes + span.attributes() .iter() .any(|kv| kv.key.as_str() == "bag-key"), "Baggage should have been stored as span attribute in on_start" diff --git a/opentelemetry-sdk/src/trace/provider.rs b/opentelemetry-sdk/src/trace/provider.rs index b8dc113ca7..d61716fbdc 100644 --- a/opentelemetry-sdk/src/trace/provider.rs +++ b/opentelemetry-sdk/src/trace/provider.rs @@ -510,8 +510,8 @@ mod tests { SERVICE_NAME, TELEMETRY_SDK_LANGUAGE, TELEMETRY_SDK_NAME, TELEMETRY_SDK_VERSION, }; use crate::trace::provider::TracerProviderInner; - use crate::trace::{Config, Span, SpanProcessor}; - use crate::trace::{SdkTracerProvider, SpanData}; + use crate::trace::SdkTracerProvider; + use crate::trace::{Config, FinishedSpan, Span, SpanProcessor}; use crate::Resource; use opentelemetry::trace::{Tracer, TracerProvider}; use opentelemetry::{Context, Key, KeyValue, Value}; @@ -565,7 +565,7 @@ mod tests { .fetch_add(1, Ordering::SeqCst); } - fn on_end(&self, _span: SpanData) { + fn on_end(&self, _span: &mut FinishedSpan) { // ignore } @@ -858,7 +858,7 @@ mod tests { // No operation needed for this processor } - fn on_end(&self, _span: SpanData) { + fn on_end(&self, _span: &mut FinishedSpan) { // No operation needed for this processor } diff --git a/opentelemetry-sdk/src/trace/span.rs b/opentelemetry-sdk/src/trace/span.rs index 09cc7474c2..a4457a0ad9 100644 --- a/opentelemetry-sdk/src/trace/span.rs +++ b/opentelemetry-sdk/src/trace/span.rs @@ -37,6 +37,8 @@ pub(crate) struct SpanData { pub(crate) start_time: SystemTime, /// Span end time pub(crate) end_time: SystemTime, + /// Whether end_time was explicitly set via `end_with_timestamp` + pub(crate) end_time_set: bool, /// Span attributes pub(crate) attributes: Vec, /// The number of attributes that were above the configured limit, and thus @@ -194,49 +196,48 @@ impl opentelemetry::trace::Span for Span { /// Finishes the span with given timestamp. fn end_with_timestamp(&mut self, timestamp: SystemTime) { - self.ensure_ended_and_exported(Some(timestamp)); + if let Some(ref mut data) = self.data { + data.end_time = timestamp; + data.end_time_set = true; + } + self.end_and_export(); } } impl Span { - fn ensure_ended_and_exported(&mut self, timestamp: Option) { - // skip if data has already been exported + /// Exports the span to all registered processors. + /// + /// Takes ownership of span data, sets end time if not already set, + /// and passes the finished span to each processor. + fn end_and_export(&mut self) { + // Take data first so Drop won't re-enter if provider is shut down let mut data = match self.data.take() { Some(data) => data, None => return, }; let provider = self.tracer.provider(); - // skip if provider has been shut down if provider.is_shutdown() { return; } - // ensure end time is set via explicit end or implicitly on drop - if let Some(timestamp) = timestamp { - data.end_time = timestamp; - } else if data.end_time == data.start_time { + // Set end time to now if not explicitly set via end_with_timestamp + if !data.end_time_set { data.end_time = opentelemetry::time::now(); } - match provider.span_processors() { - [] => {} - [processor] => { - processor.on_end(build_export_data( - data, - self.span_context.clone(), - &self.tracer, - )); - } - processors => { - for processor in processors { - processor.on_end(build_export_data( - data.clone(), - self.span_context.clone(), - &self.tracer, - )); - } - } + // Move span_context out of the span. After data.take() above, the span + // is effectively dead (all further operations no-op), so replacing the + // context with an empty one avoids cloning the TraceState. + let span_context = std::mem::replace(&mut self.span_context, SpanContext::empty_context()); + + let mut finished_span = + FinishedSpan::new(build_export_data(data, span_context, &self.tracer)); + + let span_processors = provider.span_processors(); + for (i, processor) in span_processors.iter().enumerate() { + finished_span.reset(i == span_processors.len() - 1); + processor.on_end(&mut finished_span); } } } @@ -244,10 +245,345 @@ impl Span { impl Drop for Span { /// Report span on inner drop fn drop(&mut self) { - self.ensure_ended_and_exported(None); + self.end_and_export(); + } +} + +impl ReadableSpan for Span { + fn context(&self) -> &SpanContext { + &self.span_context + } + + fn parent_span_id(&self) -> SpanId { + self.data + .as_ref() + .map(|data| data.parent_span_id) + .unwrap_or(SpanId::INVALID) + } + + fn span_kind(&self) -> &SpanKind { + self.data + .as_ref() + .map(|data| &data.span_kind) + .unwrap_or(&SpanKind::Internal) + } + + fn name(&self) -> Option<&str> { + Some(&self.data.as_ref()?.name) + } + + fn start_time(&self) -> Option { + self.data.as_ref().map(|data| data.start_time) + } + + fn end_time(&self) -> Option { + self.data.as_ref().map(|data| data.end_time) + } + + fn attributes(&self) -> &[KeyValue] { + self.data + .as_ref() + .map(|data| data.attributes.as_slice()) + .unwrap_or(&[]) + } + + fn dropped_attributes_count(&self) -> u32 { + self.data + .as_ref() + .map(|data| data.dropped_attributes_count) + .unwrap_or(0) + } + + fn events(&self) -> &[Event] { + self.data + .as_ref() + .map(|data| data.events.events.as_slice()) + .unwrap_or(&[]) + } + + fn dropped_events_count(&self) -> u32 { + self.data + .as_ref() + .map(|data| data.events.dropped_count) + .unwrap_or(0) + } + + fn links(&self) -> &[Link] { + self.data + .as_ref() + .map(|data| data.links.links.as_slice()) + .unwrap_or(&[]) + } + + fn dropped_links_count(&self) -> u32 { + self.data + .as_ref() + .map(|data| data.links.dropped_count) + .unwrap_or(0) + } + + fn status(&self) -> &Status { + self.data + .as_ref() + .map(|data| &data.status) + .unwrap_or(&Status::Unset) + } + + fn instrumentation_scope(&self) -> &opentelemetry::InstrumentationScope { + self.tracer.instrumentation_scope() + } +} + +/// Represents a finished span passed to a span processor. +/// +/// The data associated with the span is not writable, but it can be read +/// through the [`ReadableSpan`] trait. +/// +/// Taking ownership of the span data is done by calling [`consume`](FinishedSpan::consume). +/// If `consume` is never called, the `on_end` method will not perform any copy of +/// the span data. +/// +/// After `consume` is called, [`ReadableSpan`] methods return default values +/// (empty attributes, `SpanKind::Internal`, etc.) since the underlying data +/// has been taken. Use [`is_consumed`](FinishedSpan::is_consumed) to check. +/// +/// ``` +/// use opentelemetry_sdk::trace::{FinishedSpan, ReadableSpan}; +/// fn on_end(span: &mut FinishedSpan) { +/// // Read the span data without consuming it +/// if span.name() != Some("my_span") { +/// return; +/// } +/// // Consume the span data, potentially cloning it +/// let span = span.consume(); +/// # let _ = span; +/// } +/// ``` +pub struct FinishedSpan { + span: Option, + is_last_processor: bool, + is_consumed: bool, +} + +impl FinishedSpan { + /// Creates a new `FinishedSpan` with the given span data. + pub fn new(span_data: crate::trace::SpanData) -> Self { + FinishedSpan { + span: Some(span_data), + is_last_processor: true, + is_consumed: false, + } + } + + fn reset(&mut self, last_processor: bool) { + self.is_last_processor = last_processor; + self.is_consumed = false; + } + + /// Returns whether the span data has been consumed. + pub fn is_consumed(&self) -> bool { + self.is_consumed + } + + /// Takes ownership of the span data in the `FinishedSpan`. + /// + /// The last processor in the chain receives the data via move (zero-copy); + /// earlier processors receive a clone. + /// + /// Returns `None` if the span data has already been consumed. + /// After consuming, [`ReadableSpan`] methods will return default values. + pub fn consume(&mut self) -> Option { + if self.is_consumed { + opentelemetry::otel_error!(name: "FinishedSpan.ConsumeTwice", message = "consume called twice on FinishedSpan in the same span processor"); + return None; + } + self.is_consumed = true; + if self.is_last_processor { + self.span.take() + } else { + self.span.clone() + } + } +} + +impl ReadableSpan for FinishedSpan { + fn context(&self) -> &SpanContext { + match self.span { + Some(ref data) => &data.span_context, + None => &SpanContext::NONE, + } + } + + fn parent_span_id(&self) -> SpanId { + match self.span { + Some(ref data) => data.parent_span_id, + None => SpanId::INVALID, + } + } + + fn span_kind(&self) -> &SpanKind { + match self.span { + Some(ref data) => &data.span_kind, + None => &SpanKind::Internal, + } + } + + fn name(&self) -> Option<&str> { + self.span.as_ref().map(|s| s.name.as_ref()) + } + + fn start_time(&self) -> Option { + self.span.as_ref().map(|s| s.start_time) + } + + fn end_time(&self) -> Option { + self.span.as_ref().map(|s| s.end_time) + } + + fn attributes(&self) -> &[KeyValue] { + match self.span { + Some(ref data) => data.attributes.as_slice(), + None => &[], + } + } + + fn dropped_attributes_count(&self) -> u32 { + match self.span { + Some(ref data) => data.dropped_attributes_count, + None => 0, + } + } + + fn events(&self) -> &[Event] { + match self.span { + Some(ref data) => data.events.events.as_slice(), + None => &[], + } + } + + fn dropped_events_count(&self) -> u32 { + match self.span { + Some(ref data) => data.events.dropped_count, + None => 0, + } + } + + fn links(&self) -> &[Link] { + match self.span { + Some(ref data) => data.links.links.as_slice(), + None => &[], + } + } + + fn dropped_links_count(&self) -> u32 { + match self.span { + Some(ref data) => data.links.dropped_count, + None => 0, + } + } + + fn status(&self) -> &Status { + match self.span { + Some(ref data) => &data.status, + None => &Status::Unset, + } + } + + fn instrumentation_scope(&self) -> &opentelemetry::InstrumentationScope { + // TODO Replace with LazyLock once it is stable + static DEFAULT_SCOPE: std::sync::OnceLock = + std::sync::OnceLock::new(); + match self.span { + Some(ref data) => &data.instrumentation_scope, + None => DEFAULT_SCOPE.get_or_init(opentelemetry::InstrumentationScope::default), + } } } +impl std::fmt::Debug for FinishedSpan { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + let mut fmt = f.debug_struct("FinishedSpan"); + if let Some(ref s) = self.span { + if !self.is_consumed { + fmt.field("span", s); + } else { + fmt.field("consumed", &true); + } + } else { + fmt.field("consumed", &true); + } + fmt.finish() + } +} + +/// A trait for reading span data. +/// +/// Implemented by [`Span`] (for use in `on_start`) and [`FinishedSpan`] (for +/// use in `on_end`). After a [`Span`] has ended, its data has been moved into +/// a [`FinishedSpan`] and `ReadableSpan` methods on the `Span` will return +/// default values. +pub trait ReadableSpan { + /// Returns the `SpanContext` of the span. + fn context(&self) -> &SpanContext; + + /// Returns the `SpanId` of the parent span. + fn parent_span_id(&self) -> SpanId; + + /// Returns the `SpanKind` of the span. + /// + /// Returns `SpanKind::Internal` if the span is not recording. + fn span_kind(&self) -> &SpanKind; + + /// Returns the name of the span. + /// + /// Returns `None` if the span is not recording. + fn name(&self) -> Option<&str>; + + /// Returns the start time of the span. + /// + /// Returns `None` if the span is not recording. + fn start_time(&self) -> Option; + + /// Returns the end time of the span. + /// + /// Returns `None` if + /// * the span is not recording. + /// * the span has not been ended. + fn end_time(&self) -> Option; + + /// Returns the attributes of the span. + /// + /// Returns an empty slice if the span is not recording. + fn attributes(&self) -> &[KeyValue]; + + /// Returns the number of dropped attributes. + fn dropped_attributes_count(&self) -> u32; + + /// Returns the events associated to the span. + /// + /// Returns an empty slice if the span is not recording. + fn events(&self) -> &[Event]; + + /// Returns the number of dropped events. + fn dropped_events_count(&self) -> u32; + + /// Returns the span links associated to the span. + /// + /// Returns an empty slice if the span is not recording. + fn links(&self) -> &[Link]; + + /// Returns the number of dropped links. + fn dropped_links_count(&self) -> u32; + + /// Returns the status of the span. + /// + /// Returns `Status::Unset` if the span is not recording. + fn status(&self) -> &Status; + + /// Returns the instrumentation scope of the span. + fn instrumentation_scope(&self) -> &opentelemetry::InstrumentationScope; +} + fn build_export_data( data: SpanData, span_context: SpanContext, @@ -278,9 +614,10 @@ mod tests { DEFAULT_MAX_ATTRIBUTES_PER_EVENT, DEFAULT_MAX_ATTRIBUTES_PER_LINK, DEFAULT_MAX_ATTRIBUTES_PER_SPAN, DEFAULT_MAX_EVENT_PER_SPAN, DEFAULT_MAX_LINKS_PER_SPAN, }; - use crate::trace::{SpanEvents, SpanLinks}; - use opentelemetry::trace::{self, SpanBuilder, TraceFlags, TraceId, Tracer}; - use opentelemetry::{trace::Span as _, trace::TracerProvider}; + use crate::trace::{SdkTracer, SpanEvents, SpanLinks, SpanProcessor}; + use opentelemetry::trace::{ + Span as _, SpanBuilder, SpanKind, TraceFlags, TraceId, Tracer, TracerProvider, + }; use std::time::Duration; use std::vec; @@ -290,10 +627,11 @@ mod tests { let data = SpanData { parent_span_id: SpanId::from(0), parent_span_is_remote: false, - span_kind: trace::SpanKind::Internal, + span_kind: SpanKind::Internal, name: "opentelemetry".into(), start_time: opentelemetry::time::now(), end_time: opentelemetry::time::now(), + end_time_set: false, attributes: Vec::new(), dropped_attributes_count: 0, events: SpanEvents::default(), @@ -709,6 +1047,57 @@ mod tests { assert_eq!(event_vec.len(), DEFAULT_MAX_EVENT_PER_SPAN as usize); } + fn make_test_span(tracer: &SdkTracer) -> Span { + let mut span = tracer.start("test_span"); + span.set_attribute(KeyValue::new("k", "v")); + span.add_event("test_event", vec![]); + span + } + + #[test] + fn test_readable_span_recording() { + let provider = crate::trace::SdkTracerProvider::builder() + .with_simple_exporter(NoopSpanExporter::new()) + .build(); + let tracer = provider.tracer("test"); + + let span = make_test_span(&tracer); + + assert!(span.context().span_id() != SpanId::INVALID); + assert_eq!(span.name(), Some("test_span")); + assert!(span.start_time().is_some()); + assert!(span.end_time().is_some()); + assert_eq!(span.attributes(), &[KeyValue::new("k", "v")]); + assert_eq!(span.dropped_attributes_count(), 0); + assert_eq!(span.events().len(), 1); + assert_eq!(span.events()[0].name, "test_event"); + assert_eq!(span.dropped_events_count(), 0); + } + + #[test] + fn test_readable_span_non_recording() { + use crate::trace::Sampler; + + let provider = crate::trace::SdkTracerProvider::builder() + .with_sampler(Sampler::AlwaysOff) + .with_simple_exporter(NoopSpanExporter::new()) + .build(); + let tracer = provider.tracer("test"); + + let span = make_test_span(&tracer); + + assert!(span.context().span_id() != SpanId::INVALID); + assert_eq!(span.name(), None); + assert_eq!(span.span_kind(), &SpanKind::Internal); + assert!(span.start_time().is_none()); + assert!(span.end_time().is_none()); + assert_eq!(span.attributes(), &[]); + assert_eq!(span.dropped_attributes_count(), 0); + assert_eq!(span.events().len(), 0); + assert_eq!(span.dropped_events_count(), 0); + assert_eq!(span.links().len(), 0); + } + #[test] fn multiple_processors_receive_span_data() { use crate::trace::InMemorySpanExporterBuilder; @@ -765,4 +1154,145 @@ mod tests { // return none if the provider has already been dropped assert!(dropped_span.exported_data().is_none()); } + + #[test] + fn test_finished_span_consume() { + #[derive(Debug)] + struct TestSpanProcessor; + impl SpanProcessor for TestSpanProcessor { + fn on_end(&self, span: &mut FinishedSpan) { + assert!(span.context().span_id() != SpanId::INVALID); + assert_eq!(span.name(), Some("test_span")); + assert!(span.start_time().is_some()); + assert!(span.end_time().is_some()); + assert_eq!(span.attributes(), &[KeyValue::new("k", "v")]); + assert_eq!(span.dropped_attributes_count(), 0); + assert_eq!(span.events().len(), 1); + assert_eq!(span.events()[0].name, "test_event"); + assert_eq!(span.dropped_events_count(), 0); + + let _ = span.consume(); + } + + fn on_start(&self, _span: &mut Span, _cx: &opentelemetry::Context) {} + + fn force_flush(&self) -> crate::error::OTelSdkResult { + Ok(()) + } + + fn shutdown_with_timeout(&self, _timeout: Duration) -> crate::error::OTelSdkResult { + Ok(()) + } + } + + let provider = crate::trace::SdkTracerProvider::builder() + .with_span_processor(TestSpanProcessor) + .with_span_processor(TestSpanProcessor) + .build(); + drop(make_test_span(&provider.tracer("test"))); + let res = provider.shutdown(); + assert!(res.is_ok()); + } + + #[test] + fn test_finished_span_consume_twice() { + #[derive(Debug)] + struct TestSpanProcessor; + impl SpanProcessor for TestSpanProcessor { + fn on_end(&self, span: &mut FinishedSpan) { + let _ = span.consume(); + assert!(span.consume().is_none()); + } + + fn on_start(&self, _span: &mut Span, _cx: &opentelemetry::Context) {} + + fn force_flush(&self) -> crate::error::OTelSdkResult { + Ok(()) + } + + fn shutdown_with_timeout(&self, _timeout: Duration) -> crate::error::OTelSdkResult { + Ok(()) + } + } + + let provider = crate::trace::SdkTracerProvider::builder() + .with_span_processor(TestSpanProcessor) + .build(); + drop(make_test_span(&provider.tracer("test"))); + + let res = provider.shutdown(); + assert!(res.is_ok()); + } + + #[test] + fn test_readable_span_after_consume_returns_defaults() { + use crate::trace::SpanData as ExportSpanData; + + let span_data = ExportSpanData { + span_context: SpanContext::new( + TraceId::from(1), + SpanId::from(1), + TraceFlags::SAMPLED, + false, + Default::default(), + ), + parent_span_id: SpanId::INVALID, + parent_span_is_remote: false, + span_kind: SpanKind::Client, + name: "test".into(), + start_time: opentelemetry::time::now(), + end_time: opentelemetry::time::now(), + attributes: vec![KeyValue::new("k", "v")], + dropped_attributes_count: 0, + events: SpanEvents::default(), + links: SpanLinks::default(), + status: Status::Ok, + instrumentation_scope: Default::default(), + }; + + let mut finished = FinishedSpan::new(span_data); + + // Before consume, ReadableSpan returns real data + assert_eq!(finished.name(), Some("test")); + assert!(!finished.is_consumed()); + + // Consume takes the data + let consumed = finished.consume(); + assert!(consumed.is_some()); + assert!(finished.is_consumed()); + + // After consume, ReadableSpan returns defaults + assert_eq!(finished.name(), None); + assert_eq!(finished.span_kind(), &SpanKind::Internal); + assert_eq!(finished.attributes(), &[]); + assert_eq!(finished.events().len(), 0); + assert_eq!(finished.links().len(), 0); + assert_eq!(finished.status(), &Status::Unset); + } + + #[test] + fn test_end_with_timestamp_equal_to_start_time() { + use crate::trace::InMemorySpanExporter; + + let exporter = InMemorySpanExporter::default(); + let provider = crate::trace::SdkTracerProvider::builder() + .with_simple_exporter(exporter.clone()) + .build(); + let tracer = provider.tracer("test"); + + let mut span = tracer.start("test_span"); + let start_time = span.data.as_ref().unwrap().start_time; + + // Explicitly set end_time = start_time (zero-duration span). + // Before the end_time_set fix, this would be silently overwritten + // with now() because end_time == start_time triggered the sentinel. + span.end_with_timestamp(start_time); + + let spans = exporter.get_finished_spans().unwrap(); + assert_eq!(spans.len(), 1); + assert_eq!( + spans[0].end_time, start_time, + "end_with_timestamp should preserve the explicit timestamp even when equal to start_time" + ); + } } diff --git a/opentelemetry-sdk/src/trace/span_processor.rs b/opentelemetry-sdk/src/trace/span_processor.rs index 49641cc2de..f96e9991f7 100644 --- a/opentelemetry-sdk/src/trace/span_processor.rs +++ b/opentelemetry-sdk/src/trace/span_processor.rs @@ -92,7 +92,14 @@ pub trait SpanProcessor: Send + Sync + std::fmt::Debug { /// /// **Best Practice**: Extract any needed context information in [`on_start`] /// and store it as span attributes. This ensures the information is available - /// in the [`SpanData`] passed to `on_end`. + /// via the [`ReadableSpan`] trait on the [`FinishedSpan`] passed to `on_end`. + /// + /// # Reading vs Consuming + /// + /// Processors can read span data without cloning via the [`ReadableSpan`] trait. + /// If ownership of the [`SpanData`] is needed, call [`FinishedSpan::consume()`]. + /// The last processor receives the data via move (zero-copy); earlier processors + /// receive a clone. /// /// # Example /// @@ -105,19 +112,22 @@ pub trait SpanProcessor: Send + Sync + std::fmt::Debug { /// } /// } /// - /// fn on_end(&self, span: SpanData) { - /// // Access the attribute stored in on_start - /// let my_value = span.attributes.iter() + /// fn on_end(&self, span: &mut FinishedSpan) { + /// // Read attributes via ReadableSpan trait (no clone) + /// let my_value = span.attributes().iter() /// .find(|kv| kv.key.as_str() == "my-key"); + /// + /// // Or consume to take ownership (clones if not last processor) + /// if let Some(span_data) = span.consume() { + /// // use span_data + /// } /// } /// } /// ``` /// /// [`on_start`]: SpanProcessor::on_start /// [`Context::current()`]: opentelemetry::Context::current - /// - /// TODO - This method should take reference to `SpanData` - fn on_end(&self, span: SpanData); + fn on_end(&self, span: &mut FinishedSpan); /// Force the spans lying in the cache to be exported. fn force_flush(&self) -> OTelSdkResult; /// Shuts down the processor. Called when SDK is shut down. This is an @@ -172,10 +182,11 @@ impl SpanProcessor for SimpleSpanProcessor { // Ignored } - fn on_end(&self, span: SpanData) { - if !span.span_context.is_sampled() { + fn on_end(&self, span: &mut FinishedSpan) { + if !span.context().is_sampled() { return; } + let Some(span) = span.consume() else { return }; let result = self .exporter @@ -284,6 +295,9 @@ use std::sync::mpsc::Receiver; use std::sync::mpsc::RecvTimeoutError; use std::sync::mpsc::SyncSender; +use super::span::FinishedSpan; +use super::ReadableSpan; + /// Messages exchanged between the main thread and the background thread. #[allow(clippy::large_enum_variant)] #[derive(Debug)] @@ -582,7 +596,10 @@ impl SpanProcessor for BatchSpanProcessor { } /// Handles span end. - fn on_end(&self, span: SpanData) { + fn on_end(&self, span: &mut FinishedSpan) { + let Some(span) = span.consume() else { + return; + }; let result = self.span_sender.try_send(span); // match for result and handle each separately @@ -1000,8 +1017,8 @@ mod tests { OTEL_BSP_EXPORT_TIMEOUT_DEFAULT, OTEL_BSP_MAX_CONCURRENT_EXPORTS, OTEL_BSP_MAX_CONCURRENT_EXPORTS_DEFAULT, OTEL_BSP_MAX_EXPORT_BATCH_SIZE_DEFAULT, }; - use crate::trace::InMemorySpanExporterBuilder; use crate::trace::{BatchConfig, BatchConfigBuilder, SpanEvents, SpanLinks}; + use crate::trace::{FinishedSpan, InMemorySpanExporterBuilder}; use crate::trace::{SpanData, SpanExporter}; use opentelemetry::trace::{SpanContext, SpanId, SpanKind, Status}; use std::fmt::Debug; @@ -1012,7 +1029,7 @@ mod tests { let exporter = InMemorySpanExporterBuilder::new().build(); let processor = SimpleSpanProcessor::new(exporter.clone()); let span_data = new_test_export_span_data(); - processor.on_end(span_data.clone()); + processor.on_end(&mut FinishedSpan::new(span_data.clone())); assert_eq!(exporter.get_finished_spans().unwrap()[0], span_data); let _result = processor.shutdown(); } @@ -1036,7 +1053,7 @@ mod tests { status: Status::Unset, instrumentation_scope: Default::default(), }; - processor.on_end(unsampled); + processor.on_end(&mut FinishedSpan::new(unsampled)); assert!(exporter.get_finished_spans().unwrap().is_empty()); } @@ -1045,7 +1062,7 @@ mod tests { let exporter = InMemorySpanExporterBuilder::new().build(); let processor = SimpleSpanProcessor::new(exporter.clone()); let span_data = new_test_export_span_data(); - processor.on_end(span_data.clone()); + processor.on_end(&mut FinishedSpan::new(span_data.clone())); assert!(!exporter.get_finished_spans().unwrap().is_empty()); let _result = processor.shutdown(); // Assume shutdown is called by ensuring spans are empty in the exporter @@ -1254,7 +1271,7 @@ mod tests { let processor = BatchSpanProcessor::new(exporter, config); let test_span = create_test_span("test_span"); - processor.on_end(test_span.clone()); + processor.on_end(&mut FinishedSpan::new(test_span.clone())); // Wait for flush interval to ensure the span is processed std::thread::sleep(Duration::from_secs(6)); @@ -1277,7 +1294,7 @@ mod tests { // Create a test span and send it to the processor let test_span = create_test_span("force_flush_span"); - processor.on_end(test_span.clone()); + processor.on_end(&mut FinishedSpan::new(test_span.clone())); // Call force_flush to immediately export the spans let flush_result = processor.force_flush(); @@ -1345,12 +1362,14 @@ mod tests { let record = create_test_span("test_span"); - processor.on_end(record); + processor.on_end(&mut FinishedSpan::new(record)); processor.force_flush().unwrap(); processor.shutdown().unwrap(); // todo: expect to see errors here. How should we assert this? - processor.on_end(create_test_span("after_shutdown_span")); + processor.on_end(&mut FinishedSpan::new(create_test_span( + "after_shutdown_span", + ))); assert_eq!(1, exporter.get_finished_spans().unwrap().len()); assert!(exporter.is_shutdown_called()); @@ -1398,7 +1417,7 @@ mod tests { let total_spans_to_send = 100; for i in 0..total_spans_to_send { let span = create_test_span(&format!("span_{}", i)); - processor.on_end(span); + processor.on_end(&mut FinishedSpan::new(span)); } // Force flush any remaining spans - this waits for export to complete @@ -1467,9 +1486,9 @@ mod tests { let processor = BatchSpanProcessor::new(exporter, config); - processor.on_end(new_test_export_span_data()); - processor.on_end(new_test_export_span_data()); - processor.on_end(new_test_export_span_data()); + processor.on_end(&mut FinishedSpan::new(new_test_export_span_data())); + processor.on_end(&mut FinishedSpan::new(new_test_export_span_data())); + processor.on_end(&mut FinishedSpan::new(new_test_export_span_data())); processor.force_flush().expect("force flush failed"); processor.shutdown().expect("shutdown failed"); @@ -1499,7 +1518,7 @@ mod tests { KeyValue::new("key1", "value1"), KeyValue::new("key2", "value2"), ]; - processor.on_end(span_data.clone()); + processor.on_end(&mut FinishedSpan::new(span_data.clone())); // Force flush to export the span let _ = processor.force_flush(); @@ -1532,7 +1551,7 @@ mod tests { // Create a span and send it to the processor let test_span = create_test_span("resource_test"); - processor.on_end(test_span.clone()); + processor.on_end(&mut FinishedSpan::new(test_span.clone())); // Force flush to ensure the span is exported let _ = processor.force_flush(); @@ -1567,7 +1586,7 @@ mod tests { for _ in 0..4 { let span = new_test_export_span_data(); - processor.on_end(span); + processor.on_end(&mut FinishedSpan::new(span)); } processor.force_flush().unwrap(); @@ -1590,7 +1609,7 @@ mod tests { for _ in 0..4 { let span = new_test_export_span_data(); - processor.on_end(span); + processor.on_end(&mut FinishedSpan::new(span)); } processor.force_flush().unwrap(); @@ -1617,7 +1636,7 @@ mod tests { let processor_clone = Arc::clone(&processor); let handle = tokio::spawn(async move { let span = new_test_export_span_data(); - processor_clone.on_end(span); + processor_clone.on_end(&mut FinishedSpan::new(span)); }); handles.push(handle); } diff --git a/opentelemetry-sdk/src/trace/span_processor_with_async_runtime.rs b/opentelemetry-sdk/src/trace/span_processor_with_async_runtime.rs index a667624777..11bceb730a 100644 --- a/opentelemetry-sdk/src/trace/span_processor_with_async_runtime.rs +++ b/opentelemetry-sdk/src/trace/span_processor_with_async_runtime.rs @@ -4,7 +4,7 @@ use crate::runtime::{to_interval_stream, RuntimeChannel, TrySend}; use crate::trace::BatchConfig; use crate::trace::Span; use crate::trace::SpanProcessor; -use crate::trace::{SpanData, SpanExporter}; +use crate::trace::{FinishedSpan, ReadableSpan, SpanData, SpanExporter}; use futures_channel::oneshot; use futures_util::{ future::{self, BoxFuture, Either}, @@ -105,10 +105,11 @@ impl SpanProcessor for BatchSpanProcessor { // Ignored } - fn on_end(&self, span: SpanData) { - if !span.span_context.is_sampled() { + fn on_end(&self, span: &mut FinishedSpan) { + if !span.context().is_sampled() { return; } + let Some(span) = span.consume() else { return }; let result = self.message_sender.try_send(BatchMessage::ExportSpan(span)); @@ -455,7 +456,7 @@ mod tests { OTEL_BSP_MAX_QUEUE_SIZE_DEFAULT, OTEL_BSP_SCHEDULE_DELAY, OTEL_BSP_SCHEDULE_DELAY_DEFAULT, }; use crate::trace::{BatchConfig, BatchConfigBuilder, InMemorySpanExporterBuilder}; - use crate::trace::{SpanData, SpanExporter}; + use crate::trace::{FinishedSpan, SpanData, SpanExporter}; use futures_util::Future; use std::fmt::Debug; use std::sync::atomic::{AtomicBool, AtomicUsize, Ordering}; @@ -577,7 +578,7 @@ mod tests { } }); tokio::time::sleep(Duration::from_secs(1)).await; // skip the first - processor.on_end(new_test_export_span_data()); + processor.on_end(&mut FinishedSpan::new(new_test_export_span_data())); let flush_res = processor.force_flush(); assert!(flush_res.is_ok()); let _shutdown_result = processor.shutdown(); @@ -604,7 +605,7 @@ mod tests { }; let processor = BatchSpanProcessor::new(exporter, config, runtime::TokioCurrentThread); tokio::time::sleep(Duration::from_secs(1)).await; // skip the first - processor.on_end(new_test_export_span_data()); + processor.on_end(&mut FinishedSpan::new(new_test_export_span_data())); let flush_res = processor.force_flush(); if time_out { assert!(flush_res.is_err()); @@ -653,9 +654,9 @@ mod tests { let processor = BatchSpanProcessor::new(exporter, config, runtime::Tokio); // Finish three spans in rapid succession. - processor.on_end(new_test_export_span_data()); - processor.on_end(new_test_export_span_data()); - processor.on_end(new_test_export_span_data()); + processor.on_end(&mut FinishedSpan::new(new_test_export_span_data())); + processor.on_end(&mut FinishedSpan::new(new_test_export_span_data())); + processor.on_end(&mut FinishedSpan::new(new_test_export_span_data())); // Wait until everything has been exported. processor.force_flush().expect("force flush failed"); @@ -690,9 +691,9 @@ mod tests { let processor = BatchSpanProcessor::new(exporter, config, runtime::Tokio); // Finish several spans quickly. - processor.on_end(new_test_export_span_data()); - processor.on_end(new_test_export_span_data()); - processor.on_end(new_test_export_span_data()); + processor.on_end(&mut FinishedSpan::new(new_test_export_span_data())); + processor.on_end(&mut FinishedSpan::new(new_test_export_span_data())); + processor.on_end(&mut FinishedSpan::new(new_test_export_span_data())); processor.force_flush().expect("force flush failed"); processor.shutdown().expect("shutdown failed"); diff --git a/opentelemetry-sdk/src/trace/tracer.rs b/opentelemetry-sdk/src/trace/tracer.rs index bb454defb9..53ca8afb78 100644 --- a/opentelemetry-sdk/src/trace/tracer.rs +++ b/opentelemetry-sdk/src/trace/tracer.rs @@ -140,6 +140,7 @@ impl SdkTracer { name, start_time, end_time: start_time, + end_time_set: false, attributes: attribute_options, dropped_attributes_count, events: span_events, diff --git a/stress/src/traces.rs b/stress/src/traces.rs index 157e7dcc40..e110a5c932 100644 --- a/stress/src/traces.rs +++ b/stress/src/traces.rs @@ -20,7 +20,7 @@ use opentelemetry::{ }; use opentelemetry_sdk::{ error::OTelSdkResult, - trace::{self as sdktrace, SpanData, SpanProcessor}, + trace::{self as sdktrace, FinishedSpan, SpanProcessor}, }; use std::time::Duration; @@ -42,7 +42,7 @@ impl SpanProcessor for NoOpSpanProcessor { // No-op } - fn on_end(&self, _span: SpanData) { + fn on_end(&self, _span: &mut FinishedSpan) { // No-op }