From 8855c9b79a2b2b8d8e5d8c203f4d9c93559dcb82 Mon Sep 17 00:00:00 2001 From: Geoffroy Couprie Date: Fri, 28 Jul 2023 14:43:34 +0200 Subject: [PATCH 1/5] add a metric tracking coprocessor latency --- apollo-router/src/plugins/coprocessor.rs | 29 ++++++++++++++++++++++++ 1 file changed, 29 insertions(+) diff --git a/apollo-router/src/plugins/coprocessor.rs b/apollo-router/src/plugins/coprocessor.rs index cf41be8a39..b8996e675d 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, + 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, + 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, + 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, + coprocessor.stage = %PipelineStep::SubgraphResponse, + ); + tracing::debug!(?co_processor_result, "co-processor returned"); let co_processor_output = co_processor_result?; From a5344e427efea8394cff8dc846c7418c739e4eba Mon Sep 17 00:00:00 2001 From: Geoffroy Couprie Date: Fri, 28 Jul 2023 14:47:17 +0200 Subject: [PATCH 2/5] docs --- docs/source/configuration/metrics.mdx | 1 + 1 file changed, 1 insertion(+) diff --git a/docs/source/configuration/metrics.mdx b/docs/source/configuration/metrics.mdx index e00779253a..1a5ed8a5a1 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_request_time` - Time spent waiting for the coprocessor to answer, in seconds The coprocessor operations metric has the following attributes: From 183f5c3fdd05510fecd17b7d443ee24670e281eb Mon Sep 17 00:00:00 2001 From: Geoffroy Couprie Date: Fri, 28 Jul 2023 14:48:27 +0200 Subject: [PATCH 3/5] changeset --- .../feat_geal_coprocessor_latency_metric.md | 17 +++++++++++++++++ 1 file changed, 17 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..8896740c9e --- /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_request_time +``` + +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 From 81c575cdf61bb450338d3c672a955e6ad640481b Mon Sep 17 00:00:00 2001 From: Geoffroy Couprie Date: Fri, 28 Jul 2023 14:50:01 +0200 Subject: [PATCH 4/5] rename --- apollo-router/src/plugins/coprocessor.rs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/apollo-router/src/plugins/coprocessor.rs b/apollo-router/src/plugins/coprocessor.rs index b8996e675d..a2901a16a4 100644 --- a/apollo-router/src/plugins/coprocessor.rs +++ b/apollo-router/src/plugins/coprocessor.rs @@ -563,7 +563,7 @@ where let duration = start.elapsed().as_secs_f64(); drop(guard); tracing::info!( - histogram.apollo.router.operations.coprocessor = duration, + histogram.apollo.router.operations.coprocessor_request_time = duration, coprocessor.stage = %PipelineStep::RouterRequest, ); @@ -719,7 +719,7 @@ where let duration = start.elapsed().as_secs_f64(); drop(guard); tracing::info!( - histogram.apollo.router.operations.coprocessor = duration, + histogram.apollo.router.operations.coprocessor_request_time = duration, coprocessor.stage = %PipelineStep::RouterResponse, ); @@ -891,7 +891,7 @@ where let duration = start.elapsed().as_secs_f64(); drop(guard); tracing::info!( - histogram.apollo.router.operations.coprocessor = duration, + histogram.apollo.router.operations.coprocessor_request_time = duration, coprocessor.stage = %PipelineStep::SubgraphRequest, ); @@ -1030,7 +1030,7 @@ where let duration = start.elapsed().as_secs_f64(); drop(guard); tracing::info!( - histogram.apollo.router.operations.coprocessor = duration, + histogram.apollo.router.operations.coprocessor_request_time = duration, coprocessor.stage = %PipelineStep::SubgraphResponse, ); From 17904c0b41ee44557034fe7c8f77ad678af02589 Mon Sep 17 00:00:00 2001 From: Geoffroy Couprie Date: Mon, 7 Aug 2023 17:30:32 +0200 Subject: [PATCH 5/5] rename --- .changesets/feat_geal_coprocessor_latency_metric.md | 2 +- apollo-router/src/plugins/coprocessor.rs | 8 ++++---- docs/source/configuration/metrics.mdx | 2 +- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/.changesets/feat_geal_coprocessor_latency_metric.md b/.changesets/feat_geal_coprocessor_latency_metric.md index 8896740c9e..3b46315643 100644 --- a/.changesets/feat_geal_coprocessor_latency_metric.md +++ b/.changesets/feat_geal_coprocessor_latency_metric.md @@ -3,7 +3,7 @@ Introduces a new metric for the router: ``` -apollo.router.operations.coprocessor_request_time +apollo.router.operations.coprocessor.duration ``` It has one attributes: diff --git a/apollo-router/src/plugins/coprocessor.rs b/apollo-router/src/plugins/coprocessor.rs index a2901a16a4..fdad623cf8 100644 --- a/apollo-router/src/plugins/coprocessor.rs +++ b/apollo-router/src/plugins/coprocessor.rs @@ -563,7 +563,7 @@ where let duration = start.elapsed().as_secs_f64(); drop(guard); tracing::info!( - histogram.apollo.router.operations.coprocessor_request_time = duration, + histogram.apollo.router.operations.coprocessor.duration = duration, coprocessor.stage = %PipelineStep::RouterRequest, ); @@ -719,7 +719,7 @@ where let duration = start.elapsed().as_secs_f64(); drop(guard); tracing::info!( - histogram.apollo.router.operations.coprocessor_request_time = duration, + histogram.apollo.router.operations.coprocessor.duration = duration, coprocessor.stage = %PipelineStep::RouterResponse, ); @@ -891,7 +891,7 @@ where let duration = start.elapsed().as_secs_f64(); drop(guard); tracing::info!( - histogram.apollo.router.operations.coprocessor_request_time = duration, + histogram.apollo.router.operations.coprocessor.duration = duration, coprocessor.stage = %PipelineStep::SubgraphRequest, ); @@ -1030,7 +1030,7 @@ where let duration = start.elapsed().as_secs_f64(); drop(guard); tracing::info!( - histogram.apollo.router.operations.coprocessor_request_time = duration, + histogram.apollo.router.operations.coprocessor.duration = duration, coprocessor.stage = %PipelineStep::SubgraphResponse, ); diff --git a/docs/source/configuration/metrics.mdx b/docs/source/configuration/metrics.mdx index 1a5ed8a5a1..bd6d2d37c4 100644 --- a/docs/source/configuration/metrics.mdx +++ b/docs/source/configuration/metrics.mdx @@ -92,7 +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_request_time` - Time spent waiting for the coprocessor to answer, in seconds +- `apollo_router_operations_coprocessor.duration` - Time spent waiting for the coprocessor to answer, in seconds The coprocessor operations metric has the following attributes: