From b6a1d963deb0a71d4a3981d37b26d6fe388779c5 Mon Sep 17 00:00:00 2001 From: Henning Baldersheim Date: Thu, 7 Feb 2019 13:41:57 +0000 Subject: Record how long it took for you to detect that doom had already arrived. --- .../tests/proton/matching/matching_stats_test.cpp | 23 +++++++++++++++++++++- .../searchcore/proton/matching/match_thread.cpp | 9 +++++++++ .../searchcore/proton/matching/match_thread.h | 1 + .../vespa/searchcore/proton/matching/matcher.cpp | 9 ++++++--- .../searchcore/proton/matching/matching_stats.cpp | 3 +++ .../searchcore/proton/matching/matching_stats.h | 14 ++++++++++++- 6 files changed, 54 insertions(+), 5 deletions(-) (limited to 'searchcore') diff --git a/searchcore/src/tests/proton/matching/matching_stats_test.cpp b/searchcore/src/tests/proton/matching/matching_stats_test.cpp index 85960de2021..e61d8de48e6 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.timeLeftAtDoom()); 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.timeLeftAtDoom()); + EXPECT_EQUAL(1000, subPart.timeLeftAtDoom(1000).timeLeftAtDoom()); 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.timeLeftAtDoom()); 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).timeLeftAtDoom()); 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).timeLeftAtDoom(-300); all1.merge_partition(otherSubPart, 1); + EXPECT_EQUAL(1u, all1.softDoomed()); + EXPECT_EQUAL(-300, all1.timeLeftAtDoom()); 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).timeLeftAtDoom()); MatchingStats all2; all2.merge_partition(otherSubPart, 0); all2.merge_partition(subPart, 1); all1.add(all2); + EXPECT_EQUAL(2u, all1.softDoomed()); + EXPECT_EQUAL(-300, all1.timeLeftAtDoom()); 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(-300, all1.getPartition(0).timeLeftAtDoom()); 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(-300, all1.getPartition(1).timeLeftAtDoom()); } 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..defae440971 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 left(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(context, tools, docid_range); softDoomed = (lastCovered < docid_range.end); + if (softDoomed) { + left = context.timeLeft(); + } docsCovered += std::min(lastCovered, docid_range.end) - docid_range.begin; } } @@ -200,6 +204,11 @@ MatchThread::match_loop(MatchTools &tools, HitCollector &hits) thread_stats.docsCovered(docsCovered); thread_stats.docsMatched(matches); thread_stats.softDoomed(softDoomed); + if (softDoomed) { + thread_stats.timeLeftAtDoom(left); + } else { + thread_stats.timeLeftAtDoom(context.timeLeft()); + } 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 b32af7e3e5a..23cfb24a5a9 100644 --- a/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp +++ b/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp @@ -311,16 +311,19 @@ 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 guard(_statsLock); _stats.add(my_stats); if (my_stats.softDoomed()) { double old = _stats.softDoomFactor(); + fastos::TimeStamp left = my_stats.timeLeftAtDoom(); + fastos::TimeStamp realTimeout = (left >= 0) ? request.getTimeout() : (request.getTimeout() - left); + fastos::TimeStamp softLimit = uint64_t((1.0 - _rankSetup->getSoftTimeoutTailCost()) * realTimeout); _stats.updatesoftDoomFactor(request.getTimeout(), softLimit, duration); - LOG(info, "Triggered softtimeout factor adjustment. limit=%1.3f and duration=%1.3f, rankprofile=%s" + LOG(info, "Triggered softtimeout factor adjustment. request=%1.3f, real=%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(), realTimeout.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..9c86425c056 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), + _leftAtDoom(), _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(); + _leftAtDoom.add(Avg().set(partition.timeLeftAtDoom().sec())); if (partition.softDoomed()) { _softDoomed = 1; } @@ -65,6 +67,7 @@ MatchingStats::add(const MatchingStats &rhs) _docsRanked += rhs._docsRanked; _docsReRanked += rhs._docsReRanked; _softDoomed += rhs.softDoomed(); + _leftAtDoom.add(rhs._leftAtDoom); _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..76064cb5a3b 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 #include +#include 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,6 +62,7 @@ public: size_t _docsRanked; size_t _docsReRanked; size_t _softDoomed; + Avg _leftAtDoom; Avg _active_time; Avg _wait_time; public: @@ -69,6 +72,7 @@ public: _docsRanked(0), _docsReRanked(0), _softDoomed(0), + _leftAtDoom(), _active_time(), _wait_time() { } @@ -82,6 +86,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 & timeLeftAtDoom(fastos::TimeStamp leftAtDoom) { _leftAtDoom.set(leftAtDoom.sec()); return *this; } + fastos::TimeStamp timeLeftAtDoom() const { return fastos::TimeStamp::fromSec(_leftAtDoom.min()); } Partition &active_time(double time_s) { _active_time.set(time_s); return *this; } double active_time_avg() const { return _active_time.avg(); } @@ -100,6 +106,7 @@ public: _docsRanked += rhs._docsRanked; _docsReRanked += rhs._docsReRanked; _softDoomed += rhs._softDoomed; + _leftAtDoom.add(rhs._leftAtDoom); _active_time.add(rhs._active_time); _wait_time.add(rhs._wait_time); @@ -115,6 +122,7 @@ private: size_t _docsRanked; size_t _docsReRanked; size_t _softDoomed; + Avg _leftAtDoom; double _softDoomFactor; Avg _queryCollateralTime; Avg _queryLatency; @@ -151,6 +159,10 @@ public: MatchingStats &softDoomed(size_t value) { _softDoomed = value; return *this; } size_t softDoomed() const { return _softDoomed; } + + MatchingStats & timeLeftAtDoom(fastos::TimeStamp leftAtDoom) { _leftAtDoom.set(leftAtDoom.sec()); return *this; } + fastos::TimeStamp timeLeftAtDoom() const { return fastos::TimeStamp::fromSec(_leftAtDoom.min()); } + MatchingStats &softDoomFactor(double value) { _softDoomFactor = value; return *this; } double softDoomFactor() const { return _softDoomFactor; } MatchingStats &updatesoftDoomFactor(double hardLimit, double softLimit, double duration); -- cgit v1.2.3