Migrate histogram metrics to {f,u}64_histogram! (#6356)

.changesets/maint_renee_migrate_metrics_histograms.md

@@ -0,0 +1,5 @@
+### Migrate histogram metrics to `{f,u}64_histogram!` ([PR #6356](https://github.com/apollographql/router/pull/6356))
+
+Updates histogram metrics using the legacy `tracing::info!(histogram.*)` syntax to the new metrics macros.
+
+By [@goto-bus-stop](https://github.com/goto-bus-stop) in https://github.com/apollographql/router/pull/6356

apollo-router/src/cache/storage.rs

@@ -170,27 +170,31 @@ where
 
         match res {
             Some(v) => {
+                let duration = instant_memory.elapsed();
+                f64_histogram!(
+                    "apollo_router_cache_hit_time",
+                    "Time to get a value from the cache in seconds",
+                    duration.as_secs_f64(),
+                    kind = self.caller,
+                    storage = CacheStorageName::Memory.to_string()
+                );
                 u64_counter!(
                     "apollo_router_cache_hit_count",
                     "Number of cache hits",
                     1,
                     kind = self.caller,
                     storage = CacheStorageName::Memory.to_string()
                 );
-                let duration = instant_memory.elapsed().as_secs_f64();
-                tracing::info!(
-                    histogram.apollo_router_cache_hit_time = duration,
-                    kind = %self.caller,
-                    storage = &tracing::field::display(CacheStorageName::Memory),
-                );
                 Some(v)
             }
             None => {
-                let duration = instant_memory.elapsed().as_secs_f64();
-                tracing::info!(
-                    histogram.apollo_router_cache_miss_time = duration,
-                    kind = %self.caller,
-                    storage = &tracing::field::display(CacheStorageName::Memory),
+                let duration = instant_memory.elapsed();
+                f64_histogram!(
+                    "apollo_router_cache_miss_time",
+                    "Time to check the cache for an uncached value in seconds",
+                    duration.as_secs_f64(),
+                    kind = self.caller,
+                    storage = CacheStorageName::Memory.to_string()
                 );
                 u64_counter!(
                     "apollo_router_cache_miss_count",
@@ -218,35 +222,39 @@ where
                         Some(v) => {
                             self.insert_in_memory(key.clone(), v.0.clone()).await;
 
+                            let duration = instant_redis.elapsed();
+                            f64_histogram!(
+                                "apollo_router_cache_hit_time",
+                                "Time to get a value from the cache in seconds",
+                                duration.as_secs_f64(),
+                                kind = self.caller,
+                                storage = CacheStorageName::Redis.to_string()
+                            );
                             u64_counter!(
                                 "apollo_router_cache_hit_count",
                                 "Number of cache hits",
                                 1,
                                 kind = self.caller,
                                 storage = CacheStorageName::Redis.to_string()
                             );
-                            let duration = instant_redis.elapsed().as_secs_f64();
-                            tracing::info!(
-                                histogram.apollo_router_cache_hit_time = duration,
-                                kind = %self.caller,
-                                storage = &tracing::field::display(CacheStorageName::Redis),
-                            );
                             Some(v.0)
                         }
                         None => {
+                            let duration = instant_redis.elapsed();
+                            f64_histogram!(
+                                "apollo_router_cache_miss_time",
+                                "Time to check the cache for an uncached value in seconds",
+                                duration.as_secs_f64(),
+                                kind = self.caller,
+                                storage = CacheStorageName::Redis.to_string()
+                            );
                             u64_counter!(
                                 "apollo_router_cache_miss_count",
                                 "Number of cache misses",
                                 1,
                                 kind = self.caller,
                                 storage = CacheStorageName::Redis.to_string()
                             );
-                            let duration = instant_redis.elapsed().as_secs_f64();
-                            tracing::info!(
-                                histogram.apollo_router_cache_miss_time = duration,
-                                kind = %self.caller,
-                                storage = &tracing::field::display(CacheStorageName::Redis),
-                            );
                             None
                         }
                     }

apollo-router/src/graphql/request.rs

@@ -197,9 +197,11 @@ impl Request {
         let mut result = Request::allocate_result_array(value);
 
         if value.is_array() {
-            tracing::info!(
-                histogram.apollo.router.operations.batching.size = result.len() as f64,
-                mode = %BatchingMode::BatchHttpLink // Only supported mode right now
+            u64_histogram!(
+                "apollo.router.operations.batching.size",
+                "Number of queries contained within each query batch",
+                result.len() as u64,
+                mode = BatchingMode::BatchHttpLink.to_string() // Only supported mode right now
             );
 
             u64_counter!(
@@ -226,9 +228,11 @@ impl Request {
         let mut result = Request::allocate_result_array(value);
 
         if value.is_array() {
-            tracing::info!(
-                histogram.apollo.router.operations.batching.size = result.len() as f64,
-                mode = "batch_http_link" // Only supported mode right now
+            u64_histogram!(
+                "apollo.router.operations.batching.size",
+                "Number of queries contained within each query batch",
+                result.len() as u64,
+                mode = BatchingMode::BatchHttpLink.to_string() // Only supported mode right now
             );
 
             u64_counter!(

apollo-router/src/plugins/cache/metrics.rs

@@ -244,15 +244,21 @@ impl CacheCounter {
 
         for (typename, (cache_hit, total_entities)) in seen.into_iter() {
             if separate_metrics_per_type {
-                ::tracing::info!(
-                    histogram.apollo.router.operations.entity.cache_hit = (cache_hit as f64 / total_entities as f64) * 100f64,
-                    entity_type = %typename,
-                    subgraph = %subgraph_name,
+                f64_histogram!(
+                    "apollo.router.operations.entity.cache_hit",
+                    "Hit rate percentage of cached entities",
+                    (cache_hit as f64 / total_entities as f64) * 100f64,
+                    // Can't just `Arc::clone` these because they're `Arc<String>`,
+                    // while opentelemetry supports `Arc<str>`
+                    entity_type = typename.to_string(),
+                    subgraph = subgraph_name.to_string()
                 );
             } else {
-                ::tracing::info!(
-                    histogram.apollo.router.operations.entity.cache_hit = (cache_hit as f64 / total_entities as f64) * 100f64,
-                    subgraph = %subgraph_name,
+                f64_histogram!(
+                    "apollo.router.operations.entity.cache_hit",
+                    "Hit rate percentage of cached entities",
+                    (cache_hit as f64 / total_entities as f64) * 100f64,
+                    subgraph = subgraph_name.to_string()
                 );
             }
         }

apollo-router/src/plugins/coprocessor/execution.rs

@@ -10,7 +10,6 @@ use tower::BoxError;
 use tower::ServiceBuilder;
 use tower_service::Service;
 
-use super::externalize_header_map;
 use super::*;
 use crate::graphql;
 use crate::layers::async_checkpoint::OneShotAsyncCheckpointLayer;
@@ -235,12 +234,9 @@ where
     let guard = request.context.enter_active_request();
     let start = Instant::now();
     let co_processor_result = payload.call(http_client, &coprocessor_url).await;
-    let duration = start.elapsed().as_secs_f64();
+    let duration = start.elapsed();
     drop(guard);
-    tracing::info!(
-        histogram.apollo.router.operations.coprocessor.duration = duration,
-        coprocessor.stage = %PipelineStep::ExecutionRequest,
-    );
+    record_coprocessor_duration(PipelineStep::ExecutionRequest, duration);
 
     tracing::debug!(?co_processor_result, "co-processor returned");
     let co_processor_output = co_processor_result?;
@@ -381,12 +377,9 @@ where
     let guard = response.context.enter_active_request();
     let start = Instant::now();
     let co_processor_result = payload.call(http_client.clone(), &coprocessor_url).await;
-    let duration = start.elapsed().as_secs_f64();
+    let duration = start.elapsed();
     drop(guard);
-    tracing::info!(
-        histogram.apollo.router.operations.coprocessor.duration = duration,
-        coprocessor.stage = %PipelineStep::ExecutionResponse,
-    );
+    record_coprocessor_duration(PipelineStep::ExecutionResponse, duration);
 
     tracing::debug!(?co_processor_result, "co-processor returned");
     let co_processor_output = co_processor_result?;

apollo-router/src/plugins/coprocessor/mod.rs

@@ -343,6 +343,15 @@ fn default_timeout() -> Duration {
     DEFAULT_EXTERNALIZATION_TIMEOUT
 }
 
+fn record_coprocessor_duration(stage: PipelineStep, duration: Duration) {
+    f64_histogram!(
+        "apollo.router.operations.coprocessor.duration",
+        "Time spent waiting for the coprocessor to answer, in seconds",
+        duration.as_secs_f64(),
+        coprocessor.stage = stage.to_string()
+    );
+}
+
 #[derive(Clone, Debug, Default, Deserialize, PartialEq, Serialize, JsonSchema)]
 #[serde(default)]
 pub(super) struct RouterStage {
@@ -671,12 +680,9 @@ where
     let guard = request.context.enter_active_request();
     let start = Instant::now();
     let co_processor_result = payload.call(http_client, &coprocessor_url).await;
-    let duration = start.elapsed().as_secs_f64();
+    let duration = start.elapsed();
     drop(guard);
-    tracing::info!(
-        histogram.apollo.router.operations.coprocessor.duration = duration,
-        coprocessor.stage = %PipelineStep::RouterRequest,
-    );
+    record_coprocessor_duration(PipelineStep::RouterRequest, duration);
 
     tracing::debug!(?co_processor_result, "co-processor returned");
     let mut co_processor_output = co_processor_result?;
@@ -846,12 +852,9 @@ where
     let guard = response.context.enter_active_request();
     let start = Instant::now();
     let co_processor_result = payload.call(http_client.clone(), &coprocessor_url).await;
-    let duration = start.elapsed().as_secs_f64();
+    let duration = start.elapsed();
     drop(guard);
-    tracing::info!(
-        histogram.apollo.router.operations.coprocessor.duration = duration,
-        coprocessor.stage = %PipelineStep::RouterResponse,
-    );
+    record_coprocessor_duration(PipelineStep::RouterResponse, duration);
 
     tracing::debug!(?co_processor_result, "co-processor returned");
     let co_processor_output = co_processor_result?;
@@ -1034,12 +1037,9 @@ where
     let guard = request.context.enter_active_request();
     let start = Instant::now();
     let co_processor_result = payload.call(http_client, &coprocessor_url).await;
-    let duration = start.elapsed().as_secs_f64();
+    let duration = start.elapsed();
     drop(guard);
-    tracing::info!(
-        histogram.apollo.router.operations.coprocessor.duration = duration,
-        coprocessor.stage = %PipelineStep::SubgraphRequest,
-    );
+    record_coprocessor_duration(PipelineStep::SubgraphRequest, duration);
 
     tracing::debug!(?co_processor_result, "co-processor returned");
     let co_processor_output = co_processor_result?;
@@ -1193,12 +1193,9 @@ where
     let guard = response.context.enter_active_request();
     let start = Instant::now();
     let co_processor_result = payload.call(http_client, &coprocessor_url).await;
-    let duration = start.elapsed().as_secs_f64();
+    let duration = start.elapsed();
     drop(guard);
-    tracing::info!(
-        histogram.apollo.router.operations.coprocessor.duration = duration,
-        coprocessor.stage = %PipelineStep::SubgraphResponse,
-    );
+    record_coprocessor_duration(PipelineStep::SubgraphResponse, duration);
 
     tracing::debug!(?co_processor_result, "co-processor returned");
     let co_processor_output = co_processor_result?;

apollo-router/src/plugins/coprocessor/supergraph.rs

@@ -10,7 +10,6 @@ use tower::BoxError;
 use tower::ServiceBuilder;
 use tower_service::Service;
 
-use super::externalize_header_map;
 use super::*;
 use crate::graphql;
 use crate::layers::async_checkpoint::OneShotAsyncCheckpointLayer;
@@ -243,12 +242,9 @@ where
     let guard = request.context.enter_active_request();
     let start = Instant::now();
     let co_processor_result = payload.call(http_client, &coprocessor_url).await;
-    let duration = start.elapsed().as_secs_f64();
+    let duration = start.elapsed();
     drop(guard);
-    tracing::info!(
-        histogram.apollo.router.operations.coprocessor.duration = duration,
-        coprocessor.stage = %PipelineStep::SupergraphRequest,
-    );
+    record_coprocessor_duration(PipelineStep::SupergraphRequest, duration);
 
     tracing::debug!(?co_processor_result, "co-processor returned");
     let co_processor_output = co_processor_result?;
@@ -397,12 +393,9 @@ where
     let guard = response.context.enter_active_request();
     let start = Instant::now();
     let co_processor_result = payload.call(http_client.clone(), &coprocessor_url).await;
-    let duration = start.elapsed().as_secs_f64();
+    let duration = start.elapsed();
     drop(guard);
-    tracing::info!(
-        histogram.apollo.router.operations.coprocessor.duration = duration,
-        coprocessor.stage = %PipelineStep::SupergraphResponse,
-    );
+    record_coprocessor_duration(PipelineStep::SupergraphResponse, duration);
 
     tracing::debug!(?co_processor_result, "co-processor returned");
     let co_processor_output = co_processor_result?;

apollo-router/src/plugins/telemetry/utils.rs

@@ -4,7 +4,11 @@ use std::time::Instant;
 /// Timer implementing Drop to automatically compute the duration between the moment it has been created until it's dropped
 ///```ignore
 /// Timer::new(|duration| {
-///     tracing::info!(histogram.apollo_router_test = duration.as_secs_f64());
+///     f64_histogram!(
+///         "apollo_router_test",
+///         "Time spent testing the timer",
+///         duration.as_secs_f64()
+///     );
 /// })
 /// ```
 pub(crate) struct Timer<F>

apollo-router/src/query_planner/caching_query_planner.rs

@@ -138,8 +138,10 @@ where
         experimental_pql_prewarm: &PersistedQueriesPrewarmQueryPlanCache,
     ) {
         let _timer = Timer::new(|duration| {
-            ::tracing::info!(
-                histogram.apollo.router.query.planning.warmup.duration = duration.as_secs_f64()
+            f64_histogram!(
+                "apollo.router.query_planning.warmup.duration",
+                "Time spent warming up the query planner queries in seconds",
+                duration.as_secs_f64()
             );
         });
 

apollo-router/src/services/subgraph_service.rs

@@ -871,9 +871,12 @@ pub(crate) async fn process_batch(
     let client = client_factory.create(&service);
 
     // Update our batching metrics (just before we fetch)
-    tracing::info!(histogram.apollo.router.operations.batching.size = listener_count as f64,
-        mode = %BatchingMode::BatchHttpLink, // Only supported mode right now
-        subgraph = &service
+    u64_histogram!(
+        "apollo.router.operations.batching.size",
+        "Number of queries contained within each query batch",
+        listener_count as u64,
+        mode = BatchingMode::BatchHttpLink.to_string(), // Only supported mode right now
+        subgraph = service.clone()
     );
 
     u64_counter!(