From 1cecaeabf4692ee7f67202bd76055872f42b3fb8 Mon Sep 17 00:00:00 2001 From: Cijo Thomas Date: Tue, 26 Nov 2024 14:05:26 -0800 Subject: [PATCH] Add few internal logs for Metrics sdks (#2350) --- examples/self-diagnostics/src/main.rs | 18 +++++++--- .../src/metrics/meter_provider.rs | 35 +++++++++++++++---- .../src/metrics/periodic_reader.rs | 1 + opentelemetry-sdk/src/metrics/pipeline.rs | 8 +++++ 4 files changed, 50 insertions(+), 12 deletions(-) diff --git a/examples/self-diagnostics/src/main.rs b/examples/self-diagnostics/src/main.rs index 02ea356b0d..2c38458d84 100644 --- a/examples/self-diagnostics/src/main.rs +++ b/examples/self-diagnostics/src/main.rs @@ -1,6 +1,7 @@ use opentelemetry::global; use opentelemetry::KeyValue; use opentelemetry_sdk::metrics::PeriodicReader; +use opentelemetry_sdk::Resource; use std::error::Error; use tracing::info; use tracing_subscriber::fmt; @@ -13,6 +14,10 @@ fn init_meter_provider() -> opentelemetry_sdk::metrics::SdkMeterProvider { let reader = PeriodicReader::builder(exporter, opentelemetry_sdk::runtime::Tokio).build(); let provider = opentelemetry_sdk::metrics::SdkMeterProvider::builder() + .with_resource(Resource::new([KeyValue::new( + "service.name", + "self-diagnostics-example", + )])) .with_reader(reader) .build(); @@ -26,7 +31,7 @@ async fn main() -> Result<(), Box> { // OpenTelemetry uses `tracing` crate for its internal logging. Unless a // tracing subscriber is set, the logs will be discarded. In this example, // we configure a `tracing` subscriber to: - // 1. Print logs of level INFO or higher to stdout using tracing's fmt layer. + // 1. Print logs of level DEBUG or higher to stdout using tracing's fmt layer. // 2. Filter logs from OpenTelemetry's dependencies (like tonic, hyper, // reqwest etc. which are commonly used by the OTLP exporter) to only print // ERROR-level logs. This filtering helps reduce repetitive log messages @@ -39,7 +44,7 @@ async fn main() -> Result<(), Box> { // Hence, one may use "add_directive("opentelemetry=off".parse().unwrap())" // to turn off all logs from OpenTelemetry. - let filter = EnvFilter::new("info") + let filter = EnvFilter::new("debug") .add_directive("hyper=error".parse().unwrap()) .add_directive("tonic=error".parse().unwrap()) .add_directive("h2=error".parse().unwrap()) @@ -54,11 +59,14 @@ async fn main() -> Result<(), Box> { info!("Starting self-diagnostics example"); let meter = global::meter("example"); - // Create a counter using an invalid name to trigger - // internal log about the same. - let counter = meter.u64_counter("my_counter with_space").build(); + let counter = meter.u64_counter("my_counter").build(); counter.add(10, &[KeyValue::new("key", "value")]); + let _observable_counter = meter + .u64_observable_counter("my_observable_counter") + .with_callback(|observer| observer.observe(10, &[KeyValue::new("key", "value")])) + .build(); + meter_provider.shutdown()?; info!("Shutdown complete. Bye!"); Ok(()) diff --git a/opentelemetry-sdk/src/metrics/meter_provider.rs b/opentelemetry-sdk/src/metrics/meter_provider.rs index 032ea747e6..b57e614959 100644 --- a/opentelemetry-sdk/src/metrics/meter_provider.rs +++ b/opentelemetry-sdk/src/metrics/meter_provider.rs @@ -174,6 +174,10 @@ impl MeterProvider for SdkMeterProvider { fn meter_with_scope(&self, scope: InstrumentationScope) -> Meter { if self.inner.is_shutdown.load(Ordering::Relaxed) { + otel_debug!( + name: "MeterProvider.NoOpMeterReturned", + meter_name = scope.name(), + ); return Meter::new(Arc::new(NoopMeter::new())); } @@ -182,14 +186,26 @@ impl MeterProvider for SdkMeterProvider { }; if let Ok(mut meters) = self.inner.meters.lock() { - let meter = meters - .entry(scope) - .or_insert_with_key(|scope| { - Arc::new(SdkMeter::new(scope.clone(), self.inner.pipes.clone())) - }) - .clone(); - Meter::new(meter) + if let Some(existing_meter) = meters.get(&scope) { + otel_debug!( + name: "MeterProvider.ExistingMeterReturned", + meter_name = scope.name(), + ); + Meter::new(existing_meter.clone()) + } else { + let new_meter = Arc::new(SdkMeter::new(scope.clone(), self.inner.pipes.clone())); + meters.insert(scope.clone(), new_meter.clone()); + otel_debug!( + name: "MeterProvider.NewMeterCreated", + meter_name = scope.name(), + ); + Meter::new(new_meter) + } } else { + otel_debug!( + name: "MeterProvider.NoOpMeterReturned", + meter_name = scope.name(), + ); Meter::new(Arc::new(NoopMeter::new())) } } @@ -242,6 +258,11 @@ impl MeterProviderBuilder { /// Construct a new [MeterProvider] with this configuration. pub fn build(self) -> SdkMeterProvider { + otel_debug!( + name: "MeterProvider.Building", + builder = format!("{:?}", &self), + ); + let meter_provider = SdkMeterProvider { inner: Arc::new(SdkMeterProviderInner { pipes: Arc::new(Pipelines::new( diff --git a/opentelemetry-sdk/src/metrics/periodic_reader.rs b/opentelemetry-sdk/src/metrics/periodic_reader.rs index c0a40b5f8c..f8dffdcbd0 100644 --- a/opentelemetry-sdk/src/metrics/periodic_reader.rs +++ b/opentelemetry-sdk/src/metrics/periodic_reader.rs @@ -132,6 +132,7 @@ where name: "PeriodicReader.BuildCompleted", message = "Periodic reader built.", interval_in_secs = self.interval.as_secs(), + temporality = format!("{:?}", self.exporter.temporality()), ); PeriodicReader { diff --git a/opentelemetry-sdk/src/metrics/pipeline.rs b/opentelemetry-sdk/src/metrics/pipeline.rs index 8da41f38fb..add9ba16dc 100644 --- a/opentelemetry-sdk/src/metrics/pipeline.rs +++ b/opentelemetry-sdk/src/metrics/pipeline.rs @@ -72,6 +72,10 @@ impl Pipeline { /// unique values. fn add_sync(&self, scope: InstrumentationScope, i_sync: InstrumentSync) { let _ = self.inner.lock().map(|mut inner| { + otel_debug!( + name : "InstrumentCreated", + instrument_name = i_sync.name.as_ref(), + ); inner.aggregations.entry(scope).or_default().push(i_sync); }); } @@ -99,6 +103,10 @@ impl SdkProducer for Pipeline { /// Returns aggregated metrics from a single collection. fn produce(&self, rm: &mut ResourceMetrics) -> MetricResult<()> { let inner = self.inner.lock()?; + otel_debug!( + name: "MeterProviderInvokingObservableCallbacks", + count = inner.callbacks.len(), + ); for cb in &inner.callbacks { // TODO consider parallel callbacks. cb();