Added content.proton.documentdb.matching.rank_profile.query_setup_time.average to default public metric set. Replaces query_collateral_time

6 files changed, 42 insertions, 5 deletions

diff --git a/searchcore/src/tests/proton/matching/matching_stats_test.cpp b/searchcore/src/tests/proton/matching/matching_stats_test.cpp
index 48ab09ffcb2..607a644a302 100644
--- a/searchcore/src/tests/proton/matching/matching_stats_test.cpp
+++ b/searchcore/src/tests/proton/matching/matching_stats_test.cpp
@@ -48,43 +48,51 @@ TEST("requireThatAverageTimesAreRecorded") {
     EXPECT_APPROX(0.0, stats.groupingTimeAvg(), 0.00001);
     EXPECT_APPROX(0.0, stats.rerankTimeAvg(), 0.00001);
     EXPECT_APPROX(0.0, stats.queryCollateralTimeAvg(), 0.00001);
+    EXPECT_APPROX(0.0, stats.querySetupTimeAvg(), 0.00001);
     EXPECT_APPROX(0.0, stats.queryLatencyAvg(), 0.00001);
     EXPECT_EQUAL(0u, stats.matchTimeCount());
     EXPECT_EQUAL(0u, stats.groupingTimeCount());
     EXPECT_EQUAL(0u, stats.rerankTimeCount());
     EXPECT_EQUAL(0u, stats.queryCollateralTimeCount());
+    EXPECT_EQUAL(0u, stats.querySetupTimeCount());
     EXPECT_EQUAL(0u, stats.queryLatencyCount());
-    stats.matchTime(0.01).groupingTime(0.1).rerankTime(0.5).queryCollateralTime(2.0).queryLatency(1.0);
+    stats.matchTime(0.01).groupingTime(0.1).rerankTime(0.5).queryCollateralTime(2.0).querySetupTime(2.0).queryLatency(1.0);
     EXPECT_APPROX(0.01, stats.matchTimeAvg(), 0.00001);
     EXPECT_APPROX(0.1, stats.groupingTimeAvg(), 0.00001);
     EXPECT_APPROX(0.5, stats.rerankTimeAvg(), 0.00001);
     EXPECT_APPROX(2.0, stats.queryCollateralTimeAvg(), 0.00001);
+    EXPECT_APPROX(2.0, stats.querySetupTimeAvg(), 0.00001);
     EXPECT_APPROX(1.0, stats.queryLatencyAvg(), 0.00001);
-    stats.add(MatchingStats().matchTime(0.03).groupingTime(0.3).rerankTime(1.5).queryCollateralTime(6.0).queryLatency(3.0));
+    stats.add(MatchingStats().matchTime(0.03).groupingTime(0.3).rerankTime(1.5).queryCollateralTime(6.0).querySetupTime(6.0).queryLatency(3.0));
     EXPECT_APPROX(0.02, stats.matchTimeAvg(), 0.00001);
     EXPECT_APPROX(0.2, stats.groupingTimeAvg(), 0.00001);
     EXPECT_APPROX(1.0, stats.rerankTimeAvg(), 0.00001);
     EXPECT_APPROX(4.0, stats.queryCollateralTimeAvg(), 0.00001);
+    EXPECT_APPROX(4.0, stats.querySetupTimeAvg(), 0.00001);
     EXPECT_APPROX(2.0, stats.queryLatencyAvg(), 0.00001);
     stats.add(MatchingStats().matchTime(0.05)
               .groupingTime(0.5)
               .rerankTime(2.5)
               .queryCollateralTime(10.0)
+              .querySetupTime(10.0)
               .queryLatency(5.0));
     stats.add(MatchingStats().matchTime(0.05).matchTime(0.03)
               .groupingTime(0.5).groupingTime(0.3)
               .rerankTime(2.5).rerankTime(1.5)
               .queryCollateralTime(10.0).queryCollateralTime(6.0)
+              .querySetupTime(10.0).querySetupTime(6.0)
               .queryLatency(5.0).queryLatency(3.0));
     EXPECT_APPROX(0.03, stats.matchTimeAvg(), 0.00001);
     EXPECT_APPROX(0.3, stats.groupingTimeAvg(), 0.00001);
     EXPECT_APPROX(1.5, stats.rerankTimeAvg(), 0.00001);
     EXPECT_APPROX(6.0, stats.queryCollateralTimeAvg(), 0.00001);
+    EXPECT_APPROX(6.0, stats.querySetupTimeAvg(), 0.00001);
     EXPECT_APPROX(3.0, stats.queryLatencyAvg(), 0.00001);
     EXPECT_EQUAL(4u, stats.matchTimeCount());
     EXPECT_EQUAL(4u, stats.groupingTimeCount());
     EXPECT_EQUAL(4u, stats.rerankTimeCount());
     EXPECT_EQUAL(4u, stats.queryCollateralTimeCount());
+    EXPECT_EQUAL(4u, stats.querySetupTimeCount());
     EXPECT_EQUAL(4u, stats.queryLatencyCount());
 }
 
@@ -94,53 +102,63 @@ TEST("requireThatMinMaxTimesAreRecorded") {
     EXPECT_APPROX(0.0, stats.groupingTimeMin(), 0.00001);
     EXPECT_APPROX(0.0, stats.rerankTimeMin(), 0.00001);
     EXPECT_APPROX(0.0, stats.queryCollateralTimeMin(), 0.00001);
+    EXPECT_APPROX(0.0, stats.querySetupTimeMin(), 0.00001);
     EXPECT_APPROX(0.0, stats.queryLatencyMin(), 0.00001);
     EXPECT_APPROX(0.0, stats.matchTimeMax(), 0.00001);
     EXPECT_APPROX(0.0, stats.groupingTimeMax(), 0.00001);
     EXPECT_APPROX(0.0, stats.rerankTimeMax(), 0.00001);
     EXPECT_APPROX(0.0, stats.queryCollateralTimeMax(), 0.00001);
+    EXPECT_APPROX(0.0, stats.querySetupTimeMax(), 0.00001);
     EXPECT_APPROX(0.0, stats.queryLatencyMax(), 0.00001);
-    stats.matchTime(0.01).groupingTime(0.1).rerankTime(0.5).queryCollateralTime(2.0).queryLatency(1.0);
+    stats.matchTime(0.01).groupingTime(0.1).rerankTime(0.5).queryCollateralTime(2.0).querySetupTime(2.0).queryLatency(1.0);
     EXPECT_APPROX(0.01, stats.matchTimeMin(), 0.00001);
     EXPECT_APPROX(0.1, stats.groupingTimeMin(), 0.00001);
     EXPECT_APPROX(0.5, stats.rerankTimeMin(), 0.00001);
     EXPECT_APPROX(2.0, stats.queryCollateralTimeMin(), 0.00001);
+    EXPECT_APPROX(2.0, stats.querySetupTimeMin(), 0.00001);
     EXPECT_APPROX(1.0, stats.queryLatencyMin(), 0.00001);
     EXPECT_APPROX(0.01, stats.matchTimeMax(), 0.00001);
     EXPECT_APPROX(0.1, stats.groupingTimeMax(), 0.00001);
     EXPECT_APPROX(0.5, stats.rerankTimeMax(), 0.00001);
     EXPECT_APPROX(2.0, stats.queryCollateralTimeMax(), 0.00001);
+    EXPECT_APPROX(2.0, stats.querySetupTimeMax(), 0.00001);
     EXPECT_APPROX(1.0, stats.queryLatencyMax(), 0.00001);
-    stats.add(MatchingStats().matchTime(0.03).groupingTime(0.3).rerankTime(1.5).queryCollateralTime(6.0).queryLatency(3.0));
+    stats.add(MatchingStats().matchTime(0.03).groupingTime(0.3).rerankTime(1.5).queryCollateralTime(6.0).querySetupTime(6.0).queryLatency(3.0));
     EXPECT_APPROX(0.01, stats.matchTimeMin(), 0.00001);
     EXPECT_APPROX(0.1, stats.groupingTimeMin(), 0.00001);
     EXPECT_APPROX(0.5, stats.rerankTimeMin(), 0.00001);
     EXPECT_APPROX(2.0, stats.queryCollateralTimeMin(), 0.00001);
+    EXPECT_APPROX(2.0, stats.querySetupTimeMin(), 0.00001);
     EXPECT_APPROX(1.0, stats.queryLatencyMin(), 0.00001);
     EXPECT_APPROX(0.03, stats.matchTimeMax(), 0.00001);
     EXPECT_APPROX(0.3, stats.groupingTimeMax(), 0.00001);
     EXPECT_APPROX(1.5, stats.rerankTimeMax(), 0.00001);
     EXPECT_APPROX(6.0, stats.queryCollateralTimeMax(), 0.00001);
+    EXPECT_APPROX(6.0, stats.querySetupTimeMax(), 0.00001);
     EXPECT_APPROX(3.0, stats.queryLatencyMax(), 0.00001);
     stats.add(MatchingStats().matchTime(0.05)
               .groupingTime(0.5)
               .rerankTime(2.5)
               .queryCollateralTime(10.0)
+              .querySetupTime(10.0)
               .queryLatency(5.0));
     stats.add(MatchingStats().matchTime(0.05).matchTime(0.03)
               .groupingTime(0.5).groupingTime(0.3)
               .rerankTime(2.5).rerankTime(1.5)
               .queryCollateralTime(10.0).queryCollateralTime(6.0)
+              .querySetupTime(10.0).querySetupTime(6.0)
               .queryLatency(5.0).queryLatency(3.0));
     EXPECT_APPROX(0.01, stats.matchTimeMin(), 0.00001);
     EXPECT_APPROX(0.1, stats.groupingTimeMin(), 0.00001);
     EXPECT_APPROX(0.5, stats.rerankTimeMin(), 0.00001);
     EXPECT_APPROX(2.0, stats.queryCollateralTimeMin(), 0.00001);
+    EXPECT_APPROX(2.0, stats.querySetupTimeMin(), 0.00001);
     EXPECT_APPROX(1.0, stats.queryLatencyMin(), 0.00001);
     EXPECT_APPROX(0.05, stats.matchTimeMax(), 0.00001);
     EXPECT_APPROX(0.5, stats.groupingTimeMax(), 0.00001);
     EXPECT_APPROX(2.5, stats.rerankTimeMax(), 0.00001);
     EXPECT_APPROX(10.0, stats.queryCollateralTimeMax(), 0.00001);
+    EXPECT_APPROX(10.0, stats.querySetupTimeMax(), 0.00001);
     EXPECT_APPROX(5.0, stats.queryLatencyMax(), 0.00001);
 }
 
diff --git a/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp b/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp
index 6c97dc8c9ef..b9d242b7765 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp
@@ -287,7 +287,9 @@ Matcher::match(const SearchRequest &request, vespalib::ThreadBundle &threadBundl
             numThreadsPerSearch, _rankSetup->getNumThreadsPerSearch(), estHits, reply->totalHitCount,
             request.ranking.c_str());
     }
-    my_stats.queryCollateralTime(vespalib::to_s(total_matching_time.elapsed()) - my_stats.queryLatencyAvg());
+    double querySetupTime = vespalib::to_s(total_matching_time.elapsed()) - my_stats.queryLatencyAvg()
+    my_stats.queryCollateralTime(querySetupTime);
+    my_stats.querySetupTime(querySetupTime);
     {
         vespalib::duration duration = request.getTimeUsed();
         std::lock_guard<std::mutex> guard(_statsLock);
diff --git a/searchcore/src/vespa/searchcore/proton/matching/matching_stats.cpp b/searchcore/src/vespa/searchcore/proton/matching/matching_stats.cpp
index fff8c94c8be..dd93cc7073d 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/matching_stats.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/matching_stats.cpp
@@ -30,6 +30,7 @@ MatchingStats::MatchingStats()
       _doomOvertime(),
       _softDoomFactor(INITIAL_SOFT_DOOM_FACTOR),
       _queryCollateralTime(),
+      _querySetupTime(),
       _queryLatency(),
       _matchTime(),
       _groupingTime(),
@@ -70,6 +71,7 @@ MatchingStats::add(const MatchingStats &rhs)
     _doomOvertime.add(rhs._doomOvertime);
 
     _queryCollateralTime.add(rhs._queryCollateralTime);
+    _querySetupTime.add(rhs._querySetupTime);
     _queryLatency.add(rhs._queryLatency);
     _matchTime.add(rhs._matchTime);
     _groupingTime.add(rhs._groupingTime);
diff --git a/searchcore/src/vespa/searchcore/proton/matching/matching_stats.h b/searchcore/src/vespa/searchcore/proton/matching/matching_stats.h
index f5eccdd1127..d8e9eea67cf 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/matching_stats.h
+++ b/searchcore/src/vespa/searchcore/proton/matching/matching_stats.h
@@ -126,6 +126,7 @@ private:
     Avg                    _doomOvertime;
     double                 _softDoomFactor;
     Avg                    _queryCollateralTime;
+    Avg                    _querySetupTime;
     Avg                    _queryLatency;
     Avg                    _matchTime;
     Avg                    _groupingTime;
@@ -174,6 +175,12 @@ public:
     double queryCollateralTimeMin() const { return _queryCollateralTime.min(); }
     double queryCollateralTimeMax() const { return _queryCollateralTime.max(); }
 
+    MatchingStats &querySetupTime(double time_s) { _querySetupTime.set(time_s); return *this; }
+    double querySetupTimeAvg() const { return _querySetupTime.avg(); }
+    size_t querySetupTimeCount() const { return _querySetupTime.count(); }
+    double querySetupTimeMin() const { return _querySetupTime.min(); }
+    double querySetupTimeMax() const { return _querySetupTime.max(); }
+
     MatchingStats &queryLatency(double time_s) { _queryLatency.set(time_s); return *this; }
     double queryLatencyAvg() const { return _queryLatency.avg(); }
     size_t queryLatencyCount() const { return _queryLatency.count(); }
diff --git a/searchcore/src/vespa/searchcore/proton/metrics/documentdb_tagged_metrics.cpp b/searchcore/src/vespa/searchcore/proton/metrics/documentdb_tagged_metrics.cpp
index f4b8203f8e2..05370920354 100644
--- a/searchcore/src/vespa/searchcore/proton/metrics/documentdb_tagged_metrics.cpp
+++ b/searchcore/src/vespa/searchcore/proton/metrics/documentdb_tagged_metrics.cpp
@@ -119,6 +119,8 @@ DocumentDBTaggedMetrics::MatchingMetrics::update(const MatchingStats &stats)
     queries.inc(stats.queries());
     queryCollateralTime.addValueBatch(stats.queryCollateralTimeAvg(), stats.queryCollateralTimeCount(),
                                       stats.queryCollateralTimeMin(), stats.queryCollateralTimeMax());
+    querySetupTime.addValueBatch(stats.querySetupTimeAvg(), stats.querySetupTimeCount(),
+                                      stats.querySetupTimeMin(), stats.querySetupTimeMax());
     queryLatency.addValueBatch(stats.queryLatencyAvg(), stats.queryLatencyCount(),
                                stats.queryLatencyMin(), stats.queryLatencyMax());
 }
@@ -131,6 +133,7 @@ DocumentDBTaggedMetrics::MatchingMetrics::MatchingMetrics(MetricSet *parent)
       queries("queries", {}, "Number of queries executed", this),
       softDoomedQueries("soft_doomed_queries", {}, "Number of queries hitting the soft timeout", this),
       queryCollateralTime("query_collateral_time", {}, "Average time (sec) spent setting up and tearing down queries", this),
+      querySetupTime("query_setup_time", {}, "Average time (sec) spent setting up and tearing down queries", this),
       queryLatency("query_latency", {}, "Total average latency (sec) when matching and ranking a query", this)
 {
 }
@@ -152,6 +155,7 @@ DocumentDBTaggedMetrics::MatchingMetrics::RankProfileMetrics::RankProfileMetrics
       groupingTime("grouping_time", {}, "Average time (sec) spent on grouping", this),
       rerankTime("rerank_time", {}, "Average time (sec) spent on 2nd phase ranking", this),
       queryCollateralTime("query_collateral_time", {}, "Average time (sec) spent setting up and tearing down queries", this),
+      querySetupTime("query_setup_time", {}, "Average time (sec) spent setting up and tearing down queries", this),
       queryLatency("query_latency", {}, "Total average latency (sec) when matching and ranking a query", this)
 {
     softDoomFactor.set(MatchingStats::INITIAL_SOFT_DOOM_FACTOR);
@@ -204,6 +208,8 @@ DocumentDBTaggedMetrics::MatchingMetrics::RankProfileMetrics::update(const Match
                              stats.rerankTimeMin(), stats.rerankTimeMax());
     queryCollateralTime.addValueBatch(stats.queryCollateralTimeAvg(), stats.queryCollateralTimeCount(),
                                       stats.queryCollateralTimeMin(), stats.queryCollateralTimeMax());
+    querySetupTime.addValueBatch(stats.querySetupTimeAvg(), stats.querySetupTimeCount(),
+                                      stats.querySetupTimeMin(), stats.querySetupTimeMax());
     queryLatency.addValueBatch(stats.queryLatencyAvg(), stats.queryLatencyCount(),
                                stats.queryLatencyMin(), stats.queryLatencyMax());
     if (stats.getNumPartitions() > 0) {
diff --git a/searchcore/src/vespa/searchcore/proton/metrics/documentdb_tagged_metrics.h b/searchcore/src/vespa/searchcore/proton/metrics/documentdb_tagged_metrics.h
index 01ba271a08f..26dd52a8577 100644
--- a/searchcore/src/vespa/searchcore/proton/metrics/documentdb_tagged_metrics.h
+++ b/searchcore/src/vespa/searchcore/proton/metrics/documentdb_tagged_metrics.h
@@ -116,6 +116,7 @@ struct DocumentDBTaggedMetrics : metrics::MetricSet
         metrics::LongCountMetric queries;
         metrics::LongCountMetric softDoomedQueries;
         metrics::DoubleAverageMetric queryCollateralTime;
+        metrics::DoubleAverageMetric querySetupTime;
         metrics::DoubleAverageMetric queryLatency;
 
         struct RankProfileMetrics : metrics::MetricSet {
@@ -145,6 +146,7 @@ struct DocumentDBTaggedMetrics : metrics::MetricSet
             metrics::DoubleAverageMetric groupingTime;
             metrics::DoubleAverageMetric rerankTime;
             metrics::DoubleAverageMetric queryCollateralTime;
+            metrics::DoubleAverageMetric querySetupTime;
             metrics::DoubleAverageMetric queryLatency;
             DocIdPartitions              partitions;