From dd7bac0e9269fbe8c1b3be431cf9e4373862d084 Mon Sep 17 00:00:00 2001
From: Geoffroy Couprie <apollo@geoffroycouprie.com>
Date: Wed, 9 Aug 2023 11:28:33 +0200
Subject: [PATCH] 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
---
 .../feat_geal_coprocessor_latency_metric.md   | 17 +++++++++++
 apollo-router/src/plugins/coprocessor.rs      | 29 +++++++++++++++++++
 docs/source/configuration/metrics.mdx         |  1 +
 3 files changed, 47 insertions(+)
 create mode 100644 .changesets/feat_geal_coprocessor_latency_metric.md

diff --git a/.changesets/feat_geal_coprocessor_latency_metric.md b/.changesets/feat_geal_coprocessor_latency_metric.md
new file mode 100644
index 0000000000..3b46315643
--- /dev/null
+++ b/.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
\ No newline at end of file
diff --git a/apollo-router/src/plugins/coprocessor.rs b/apollo-router/src/plugins/coprocessor.rs
index cf41be8a39..fdad623cf8 100644
--- a/apollo-router/src/plugins/coprocessor.rs
+++ b/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?;
 
diff --git a/docs/source/configuration/metrics.mdx b/docs/source/configuration/metrics.mdx
index e00779253a..bd6d2d37c4 100644
--- a/docs/source/configuration/metrics.mdx
+++ b/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: