From d47691af72e19b1e5add4eb5965a841c9fef09b5 Mon Sep 17 00:00:00 2001
From: Felix Leupold <felixleupold90@gmail.com>
Date: Thu, 12 Oct 2023 10:38:01 +0200
Subject: [PATCH] [Trivial] Log price estimator timings (#1946)

# Description
#1931 didn't have the desired effect of reducing our p95 price estimate
latency. This PR adds a bunch of extra logging so we can at least find
the quote requests in which estimators took a long time and then
hopefully understand what's happening in these cases.

# Changes
Log remaining and finished number of requests (to allow seeing in what
order they finish) and their time to execution.

## How to test
See the logs
---
 .../src/price_estimation/competition.rs       | 21 ++++++++++++++++---
 1 file changed, 18 insertions(+), 3 deletions(-)

diff --git a/crates/shared/src/price_estimation/competition.rs b/crates/shared/src/price_estimation/competition.rs
index 992d91e955..c6550a7c82 100644
--- a/crates/shared/src/price_estimation/competition.rs
+++ b/crates/shared/src/price_estimation/competition.rs
@@ -13,7 +13,7 @@ use {
     },
     model::order::OrderKind,
     primitive_types::H160,
-    std::{cmp::Ordering, fmt::Debug, num::NonZeroUsize, sync::Arc},
+    std::{cmp::Ordering, fmt::Debug, num::NonZeroUsize, sync::Arc, time::Instant},
 };
 
 #[derive(Debug, Clone, Hash, Eq, PartialEq)]
@@ -80,6 +80,7 @@ impl<T: Send + Sync + 'static> RacingCompetitionEstimator<T> {
             + 'static,
         compare_results: impl Fn(&Result<R, E>, &Result<R, E>) -> Ordering + Send + 'static,
     ) -> futures::future::BoxFuture<'_, Result<R, E>> {
+        let start = Instant::now();
         async move {
             let mut results = vec![];
             let mut iter = self.inner.iter().enumerate().peekable();
@@ -120,7 +121,15 @@ impl<T: Send + Sync + 'static> RacingCompetitionEstimator<T> {
                 while let Some((estimator_index, result)) = futures.next().await {
                     results.push((estimator_index, result.clone()));
                     let estimator = &self.inner[estimator_index.0][estimator_index.1].0;
-                    tracing::debug!(?query, ?result, estimator, "new price estimate");
+                    tracing::debug!(
+                        ?query,
+                        ?result,
+                        estimator,
+                        requests = futures.len(),
+                        results = results.len(),
+                        elapsed = ?start.elapsed(),
+                        "new price estimate"
+                    );
 
                     if successes(&results) >= self.successful_results_for_early_return.get() {
                         break 'outer;
@@ -137,7 +146,13 @@ impl<T: Send + Sync + 'static> RacingCompetitionEstimator<T> {
                 .unwrap();
             let (estimator_index, result) = &results[best_index];
             let (estimator, _) = &self.inner[estimator_index.0][estimator_index.1];
-            tracing::debug!(?query, ?result, estimator, "winning price estimate");
+            tracing::debug!(
+                ?query,
+                ?result,
+                estimator,
+                elapsed = ?start.elapsed(),
+                "winning price estimate"
+            );
 
             let total_estimators = self.inner.iter().fold(0, |sum, inner| sum + inner.len()) as u64;
             let queried_estimators = results.len() as u64;