Merge pull request #8415 from vespa-engine/balder/handle-late-timeout-detection

Record how long it took for you to detect that doom had already arrived.

6 files changed, 55 insertions, 6 deletions

diff --git a/searchcore/src/tests/proton/matching/matching_stats_test.cpp b/searchcore/src/tests/proton/matching/matching_stats_test.cpp
index 85960de2021..9bf627a6289 100644
--- a/searchcore/src/tests/proton/matching/matching_stats_test.cpp
+++ b/searchcore/src/tests/proton/matching/matching_stats_test.cpp
@@ -149,10 +149,17 @@ TEST("requireThatPartitionsAreAddedCorrectly") {
     EXPECT_EQUAL(0u, all1.docidSpaceCovered());
     EXPECT_EQUAL(0u, all1.docsMatched());
     EXPECT_EQUAL(0u, all1.getNumPartitions());
+    EXPECT_EQUAL(0u, all1.softDoomed());
+    EXPECT_EQUAL(0u, all1.doomOvertime());
 
     MatchingStats::Partition subPart;
     subPart.docsCovered(7).docsMatched(3).docsRanked(2).docsReRanked(1)
         .active_time(1.0).wait_time(0.5);
+    EXPECT_EQUAL(0u, subPart.softDoomed());
+    EXPECT_EQUAL(0u, subPart.softDoomed(false).softDoomed());
+    EXPECT_EQUAL(1u, subPart.softDoomed(true).softDoomed());
+    EXPECT_EQUAL(0l, subPart.doomOvertime());
+    EXPECT_EQUAL(1000, subPart.doomOvertime(1000).doomOvertime());
     EXPECT_EQUAL(7u, subPart.docsCovered());
     EXPECT_EQUAL(3u, subPart.docsMatched());
     EXPECT_EQUAL(2u, subPart.docsRanked());
@@ -172,6 +179,8 @@ TEST("requireThatPartitionsAreAddedCorrectly") {
     EXPECT_EQUAL(2u, all1.docsRanked());
     EXPECT_EQUAL(1u, all1.docsReRanked());
     EXPECT_EQUAL(1u, all1.getNumPartitions());
+    EXPECT_EQUAL(1u, all1.softDoomed());
+    EXPECT_EQUAL(1000, all1.doomOvertime());
     EXPECT_EQUAL(7u, all1.getPartition(0).docsCovered());
     EXPECT_EQUAL(3u, all1.getPartition(0).docsMatched());
     EXPECT_EQUAL(2u, all1.getPartition(0).docsRanked());
@@ -184,11 +193,15 @@ TEST("requireThatPartitionsAreAddedCorrectly") {
     EXPECT_EQUAL(0.5, all1.getPartition(0).wait_time_min());
     EXPECT_EQUAL(1.0, all1.getPartition(0).active_time_max());
     EXPECT_EQUAL(0.5, all1.getPartition(0).wait_time_max());
+    EXPECT_EQUAL(1u, all1.getPartition(0).softDoomed());
+    EXPECT_EQUAL(1000, all1.getPartition(0).doomOvertime());
 
     MatchingStats::Partition otherSubPart;
     otherSubPart.docsCovered(7).docsMatched(3).docsRanked(2).docsReRanked(1)
-        .active_time(0.5).wait_time(1.0);
+            .active_time(0.5).wait_time(1.0).softDoomed(true).doomOvertime(300);
     all1.merge_partition(otherSubPart, 1);
+    EXPECT_EQUAL(1u, all1.softDoomed());
+    EXPECT_EQUAL(1000, all1.doomOvertime());
     EXPECT_EQUAL(14u, all1.docidSpaceCovered());
     EXPECT_EQUAL(6u, all1.docsMatched());
     EXPECT_EQUAL(4u, all1.docsRanked());
@@ -205,12 +218,16 @@ TEST("requireThatPartitionsAreAddedCorrectly") {
     EXPECT_EQUAL(1.0, all1.getPartition(1).wait_time_min());
     EXPECT_EQUAL(0.5, all1.getPartition(1).active_time_max());
     EXPECT_EQUAL(1.0, all1.getPartition(1).wait_time_max());
+    EXPECT_EQUAL(1u, all1.getPartition(1).softDoomed());
+    EXPECT_EQUAL(300, all1.getPartition(1).doomOvertime());
 
     MatchingStats all2;
     all2.merge_partition(otherSubPart, 0);
     all2.merge_partition(subPart, 1);
 
     all1.add(all2);
+    EXPECT_EQUAL(2u, all1.softDoomed());
+    EXPECT_EQUAL(1000, all1.doomOvertime());
     EXPECT_EQUAL(28u, all1.docidSpaceCovered());
     EXPECT_EQUAL(12u, all1.docsMatched());
     EXPECT_EQUAL(8u, all1.docsRanked());
@@ -227,6 +244,8 @@ TEST("requireThatPartitionsAreAddedCorrectly") {
     EXPECT_EQUAL(0.5, all1.getPartition(0).wait_time_min());
     EXPECT_EQUAL(1.0, all1.getPartition(0).active_time_max());
     EXPECT_EQUAL(1.0, all1.getPartition(0).wait_time_max());
+    EXPECT_EQUAL(2u, all1.getPartition(0).softDoomed());
+    EXPECT_EQUAL(1000, all1.getPartition(0).doomOvertime());
     EXPECT_EQUAL(6u, all1.getPartition(1).docsMatched());
     EXPECT_EQUAL(4u, all1.getPartition(1).docsRanked());
     EXPECT_EQUAL(2u, all1.getPartition(1).docsReRanked());
@@ -238,6 +257,8 @@ TEST("requireThatPartitionsAreAddedCorrectly") {
     EXPECT_EQUAL(0.5, all1.getPartition(1).wait_time_min());
     EXPECT_EQUAL(1.0, all1.getPartition(1).active_time_max());
     EXPECT_EQUAL(1.0, all1.getPartition(1).wait_time_max());
+    EXPECT_EQUAL(2u, all1.getPartition(1).softDoomed());
+    EXPECT_EQUAL(1000, all1.getPartition(1).doomOvertime());
 }
 
 TEST("requireThatSoftDoomIsSetAndAdded") {
diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp b/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp
index fc4c62353d8..2e92f2d63c3 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp
@@ -178,6 +178,7 @@ MatchThread::match_loop(MatchTools &tools, HitCollector &hits)
 {
     bool softDoomed = false;
     uint32_t docsCovered = 0;
+    fastos::TimeStamp overtime(0);
     Context context(matchParams.rankDropLimit, tools, hits, num_threads);
     for (DocidRange docid_range = scheduler.first_range(thread_id);
          !docid_range.empty();
@@ -186,6 +187,9 @@ MatchThread::match_loop(MatchTools &tools, HitCollector &hits)
         if (!softDoomed) {
             uint32_t lastCovered = inner_match_loop<Strategy, do_rank, do_limit, do_share_work>(context, tools, docid_range);
             softDoomed = (lastCovered < docid_range.end);
+            if (softDoomed) {
+                overtime = - context.timeLeft();
+            }
             docsCovered += std::min(lastCovered, docid_range.end) - docid_range.begin;
         }
     }
@@ -200,6 +204,9 @@ MatchThread::match_loop(MatchTools &tools, HitCollector &hits)
     thread_stats.docsCovered(docsCovered);
     thread_stats.docsMatched(matches);
     thread_stats.softDoomed(softDoomed);
+    if (softDoomed) {
+        thread_stats.doomOvertime(overtime);
+    }
     if (do_rank) {
         thread_stats.docsRanked(matches);
     }
diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_thread.h b/searchcore/src/vespa/searchcore/proton/matching/match_thread.h
index 8384a45e0e2..06728dc006a 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/match_thread.h
+++ b/searchcore/src/vespa/searchcore/proton/matching/match_thread.h
@@ -58,6 +58,7 @@ private:
         bool isBelowLimit() const { return matches < _matches_limit; }
         bool    isAtLimit() const { return matches == _matches_limit; }
         bool   atSoftDoom() const { return _softDoom.doom(); }
+        fastos::TimeStamp timeLeft() const { return _softDoom.left(); }
         uint32_t                 matches;
     private:
         uint32_t                 _matches_limit;
diff --git a/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp b/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp
index 100f3eff0e7..382e197c16b 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp
@@ -311,16 +311,21 @@ Matcher::match(const SearchRequest &request, vespalib::ThreadBundle &threadBundl
     total_matching_time.stop();
     my_stats.queryCollateralTime(total_matching_time.elapsed().sec() - my_stats.queryLatencyAvg());
     {
-        fastos::TimeStamp softLimit = uint64_t((1.0 - _rankSetup->getSoftTimeoutTailCost()) * request.getTimeout());
         fastos::TimeStamp duration = request.getTimeUsed();
         std::lock_guard<std::mutex> guard(_statsLock);
         _stats.add(my_stats);
         if (my_stats.softDoomed()) {
             double old = _stats.softDoomFactor();
-            _stats.updatesoftDoomFactor(request.getTimeout(), softLimit, duration);
-            LOG(info, "Triggered softtimeout factor adjustment. limit=%1.3f and duration=%1.3f, rankprofile=%s"
+            fastos::TimeStamp softLimit = uint64_t((1.0 - _rankSetup->getSoftTimeoutTailCost()) * request.getTimeout());
+            fastos::TimeStamp adjustedDuration = duration - my_stats.doomOvertime();
+            if (adjustedDuration < 0) {
+                adjustedDuration = 0;
+            }
+            _stats.updatesoftDoomFactor(request.getTimeout(), softLimit, adjustedDuration);
+            LOG(info, "Triggered softtimeout factor adjustment. request=%1.3f, doomOvertime=%1.3f, limit=%1.3f and duration=%1.3f, rankprofile=%s"
                       ", factor adjusted from %1.3f to %1.3f",
-                softLimit.sec(), duration.sec(), request.ranking.c_str(), old, _stats.softDoomFactor());
+                request.getTimeout().sec(), my_stats.doomOvertime().sec(), softLimit.sec(), duration.sec(),
+                request.ranking.c_str(), old, _stats.softDoomFactor());
         }
     }
     return reply;
diff --git a/searchcore/src/vespa/searchcore/proton/matching/matching_stats.cpp b/searchcore/src/vespa/searchcore/proton/matching/matching_stats.cpp
index 4fb0e1d72e2..3bdc8efaa1c 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/matching_stats.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/matching_stats.cpp
@@ -27,6 +27,7 @@ MatchingStats::MatchingStats()
       _docsRanked(0),
       _docsReRanked(0),
       _softDoomed(0),
+      _doomOvertime(),
       _softDoomFactor(0.5),
       _queryCollateralTime(),
       _queryLatency(),
@@ -47,6 +48,7 @@ MatchingStats::merge_partition(const Partition &partition, size_t id)
     _docsMatched += partition.docsMatched();
     _docsRanked += partition.docsRanked();
     _docsReRanked += partition.docsReRanked();
+    _doomOvertime.add(partition._doomOvertime);
     if (partition.softDoomed()) {
         _softDoomed = 1;
     }
@@ -65,6 +67,7 @@ MatchingStats::add(const MatchingStats &rhs)
     _docsRanked += rhs._docsRanked;
     _docsReRanked += rhs._docsReRanked;
     _softDoomed += rhs.softDoomed();
+    _doomOvertime.add(rhs._doomOvertime);
 
 
     _queryCollateralTime.add(rhs._queryCollateralTime);
diff --git a/searchcore/src/vespa/searchcore/proton/matching/matching_stats.h b/searchcore/src/vespa/searchcore/proton/matching/matching_stats.h
index b58468fe1bc..0e1a9b2f791 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/matching_stats.h
+++ b/searchcore/src/vespa/searchcore/proton/matching/matching_stats.h
@@ -4,6 +4,7 @@
 
 #include <vector>
 #include <cstddef>
+#include <vespa/fastos/timestamp.h>
 
 namespace proton::matching {
 
@@ -23,11 +24,12 @@ private:
         double _max;
     public:
         Avg() : _value(0.0), _count(0), _min(0.0), _max(0.0) {}
-        void set(double value) {
+        Avg & set(double value) {
             _value = value;
             _count = 1;
             _min = value;
             _max = value;
+            return *this;
         }
         double avg() const {
             return (_count > 0) ? (_value / _count) : 0;
@@ -60,8 +62,10 @@ public:
         size_t _docsRanked;
         size_t _docsReRanked;
         size_t _softDoomed;
+        Avg    _doomOvertime;
         Avg    _active_time;
         Avg    _wait_time;
+        friend MatchingStats;
     public:
         Partition()
             : _docsCovered(0),
@@ -69,6 +73,7 @@ public:
               _docsRanked(0),
               _docsReRanked(0),
               _softDoomed(0),
+              _doomOvertime(),
               _active_time(),
               _wait_time() { }
 
@@ -82,6 +87,8 @@ public:
         size_t docsReRanked() const { return _docsReRanked; }
         Partition &softDoomed(bool v) { _softDoomed += v ? 1 : 0; return *this; }
         size_t softDoomed() const { return _softDoomed; }
+        Partition & doomOvertime(fastos::TimeStamp overtime) { _doomOvertime.set(overtime.sec()); return *this; }
+        fastos::TimeStamp doomOvertime() const { return fastos::TimeStamp::fromSec(_doomOvertime.max()); }
 
         Partition &active_time(double time_s) { _active_time.set(time_s); return *this; }
         double active_time_avg() const { return _active_time.avg(); }
@@ -100,6 +107,7 @@ public:
             _docsRanked += rhs._docsRanked;
             _docsReRanked += rhs._docsReRanked;
             _softDoomed += rhs._softDoomed;
+            _doomOvertime.add(rhs._doomOvertime);
 
             _active_time.add(rhs._active_time);
             _wait_time.add(rhs._wait_time);
@@ -115,6 +123,7 @@ private:
     size_t                 _docsRanked;
     size_t                 _docsReRanked;
     size_t                 _softDoomed;
+    Avg                    _doomOvertime;
     double                 _softDoomFactor;
     Avg                    _queryCollateralTime;
     Avg                    _queryLatency;
@@ -151,6 +160,9 @@ public:
 
     MatchingStats &softDoomed(size_t value) { _softDoomed = value; return *this; }
     size_t softDoomed() const { return _softDoomed; }
+
+    fastos::TimeStamp doomOvertime() const { return fastos::TimeStamp::fromSec(_doomOvertime.max()); }
+
     MatchingStats &softDoomFactor(double value) { _softDoomFactor = value; return *this; }
     double softDoomFactor() const { return _softDoomFactor; }
     MatchingStats &updatesoftDoomFactor(double hardLimit, double softLimit, double duration);