add a metric tracking coprocessor latency (#3513)

Fix #2924 

Introduces a new metric for the router:

```
apollo.router.operations.coprocessor.duration
```

It has one attributes:

```
coprocessor.stage: string (RouterRequest, RouterResponse, SubgraphRequest, SubgraphResponse)
```

It is an histogram metric tracking the time spent calling into the
coprocessor

.changesets/feat_geal_coprocessor_latency_metric.md

@@ -0,0 +1,17 @@
+### add a metric tracking coprocessor latency ([Issue #2924](https://github.com/apollographql/router/issues/2924))
+
+Introduces a new metric for the router:
+
+```
+apollo.router.operations.coprocessor.duration
+```
+
+It has one attributes:
+
+```
+coprocessor.stage: string (RouterRequest, RouterResponse, SubgraphRequest, SubgraphResponse)
+```
+
+It is an histogram metric tracking the time spent calling into the coprocessor
+
+By [@Geal](https://github.com/Geal) in https://github.com/apollographql/router/pull/3513

apollo-router/src/plugins/coprocessor.rs

@@ -5,6 +5,7 @@ use std::ops::ControlFlow;
 use std::str::FromStr;
 use std::sync::Arc;
 use std::time::Duration;
+use std::time::Instant;
 
 use bytes::Bytes;
 use futures::future::ready;
@@ -557,8 +558,15 @@ where
 
     tracing::debug!(?payload, "externalized output");
     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();
     drop(guard);
+    tracing::info!(
+        histogram.apollo.router.operations.coprocessor.duration = duration,
+        coprocessor.stage = %PipelineStep::RouterRequest,
+    );
+
     tracing::debug!(?co_processor_result, "co-processor returned");
     let co_processor_output = co_processor_result?;
 
@@ -706,8 +714,15 @@ where
     // Second, call our co-processor and get a reply.
     tracing::debug!(?payload, "externalized output");
     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();
     drop(guard);
+    tracing::info!(
+        histogram.apollo.router.operations.coprocessor.duration = duration,
+        coprocessor.stage = %PipelineStep::RouterResponse,
+    );
+
     tracing::debug!(?co_processor_result, "co-processor returned");
     let co_processor_output = co_processor_result?;
 
@@ -871,8 +886,15 @@ where
 
     tracing::debug!(?payload, "externalized output");
     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();
     drop(guard);
+    tracing::info!(
+        histogram.apollo.router.operations.coprocessor.duration = duration,
+        coprocessor.stage = %PipelineStep::SubgraphRequest,
+    );
+
     tracing::debug!(?co_processor_result, "co-processor returned");
     let co_processor_output = co_processor_result?;
     validate_coprocessor_output(&co_processor_output, PipelineStep::SubgraphRequest)?;
@@ -1003,8 +1025,15 @@ where
 
     tracing::debug!(?payload, "externalized output");
     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();
     drop(guard);
+    tracing::info!(
+        histogram.apollo.router.operations.coprocessor.duration = duration,
+        coprocessor.stage = %PipelineStep::SubgraphResponse,
+    );
+
     tracing::debug!(?co_processor_result, "co-processor returned");
     let co_processor_output = co_processor_result?;
 

docs/source/configuration/metrics.mdx

@@ -92,6 +92,7 @@ All cache metrics listed above have the following attributes:
 #### Coprocessor
 
 - `apollo_router_operations_coprocessor_total` - Total operations with co-processors enabled.
+- `apollo_router_operations_coprocessor.duration` - Time spent waiting for the coprocessor to answer, in seconds
 
 The coprocessor operations metric has the following attributes: