Merge pull request #23808 from vespa-engine/havardpe/rank-profiling-when-searching

perform rank profiling when appropriate

5 files changed, 34 insertions, 15 deletions

diff --git a/searchcore/src/tests/proton/matching/matching_test.cpp b/searchcore/src/tests/proton/matching/matching_test.cpp
index 5f9a3163a16..dbf4200a24a 100644
--- a/searchcore/src/tests/proton/matching/matching_test.cpp
+++ b/searchcore/src/tests/proton/matching/matching_test.cpp
@@ -378,7 +378,7 @@ struct MyWorld {
         MatchToolsFactory::UP match_tools_factory = matcher->create_match_tools_factory(
                 *request, searchContext, attributeContext, metaStore, overrides, true);
         MatchTools::UP match_tools = match_tools_factory->createMatchTools();
-        match_tools->setup_first_phase();
+        match_tools->setup_first_phase(nullptr);
         return match_tools->match_data().get_termwise_limit();
     }
 
diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp b/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp
index 858c25f0dd2..2894ed2d23e 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp
@@ -272,7 +272,7 @@ MatchThread::match_loop_helper(MatchTools &tools, HitCollector &hits)
 search::ResultSet::UP
 MatchThread::findMatches(MatchTools &tools)
 {
-    tools.setup_first_phase();
+    tools.setup_first_phase(first_phase_profiler.get());
     if (isFirstThread()) {
         LOG(spam, "SearchIterator: %s", tools.search().asString().c_str());
     }
@@ -300,7 +300,7 @@ MatchThread::findMatches(MatchTools &tools)
             my_work.clear();
         }
         if (!my_work.empty()) {
-            tools.setup_second_phase();
+            tools.setup_second_phase(second_phase_profiler.get());
             DocumentScorer scorer(tools.rank_program(), tools.search());
             scorer.score(my_work);
         }
@@ -415,8 +415,14 @@ MatchThread::MatchThread(size_t thread_id_in,
     wait_time_s(0.0),
     match_with_ranking(mtf.has_first_phase_rank() && mp.save_rank_scores()),
     trace(std::make_unique<Trace>(relativeTime, traceLevel, profileDepth)),
+    first_phase_profiler(),
+    second_phase_profiler(),
     my_issues()
 {
+    if ((traceLevel > 0) && (profileDepth > 0)) {
+        first_phase_profiler = std::make_unique<vespalib::ExecutionProfiler>(profileDepth);
+        second_phase_profiler = std::make_unique<vespalib::ExecutionProfiler>(profileDepth);
+    }
 }
 
 void
@@ -448,6 +454,12 @@ MatchThread::run()
     trace->addEvent(4, "Start thread merge");
     mergeDirector.dualMerge(thread_id, *resultContext->result, resultContext->groupingSource);
     trace->addEvent(4, "MatchThread::run Done");
+    if (first_phase_profiler) {
+        first_phase_profiler->report(trace->createCursor("first_phase_profiling"));
+    }
+    if (second_phase_profiler) {
+        second_phase_profiler->report(trace->createCursor("second_phase_profiling"));
+    }
 }
 
 }
diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_thread.h b/searchcore/src/vespa/searchcore/proton/matching/match_thread.h
index 7e74f4d4ef4..2a48b26d393 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/match_thread.h
+++ b/searchcore/src/vespa/searchcore/proton/matching/match_thread.h
@@ -9,6 +9,7 @@
 #include "result_processor.h"
 #include "docid_range_scheduler.h"
 #include <vespa/vespalib/util/runnable.h>
+#include <vespa/vespalib/util/execution_profiler.h>
 #include <vespa/vespalib/util/dual_merge_director.h>
 #include <vespa/searchlib/common/resultset.h>
 #include <vespa/searchlib/common/sortresults.h>
@@ -66,6 +67,8 @@ private:
     double                        wait_time_s;
     bool                          match_with_ranking;
     std::unique_ptr<Trace>        trace;
+    std::unique_ptr<vespalib::ExecutionProfiler> first_phase_profiler;
+    std::unique_ptr<vespalib::ExecutionProfiler> second_phase_profiler;
     UniqueIssues                  my_issues;
 
     class Context {
diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp b/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp
index e856478adfd..a2af40aae96 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp
@@ -70,7 +70,7 @@ extractDiversityParams(const RankSetup &rankSetup, const Properties &rankPropert
 } // namespace proton::matching::<unnamed>
 
 void
-MatchTools::setup(std::unique_ptr<RankProgram> rank_program, double termwise_limit)
+MatchTools::setup(std::unique_ptr<RankProgram> rank_program, ExecutionProfiler *profiler, double termwise_limit)
 {
     if (_search) {
         _match_data->soft_reset();
@@ -79,7 +79,7 @@ MatchTools::setup(std::unique_ptr<RankProgram> rank_program, double termwise_lim
     HandleRecorder recorder;
     {
         HandleRecorder::Binder bind(recorder);
-        _rank_program->setup(*_match_data, _queryEnv, _featureOverrides);
+        _rank_program->setup(*_match_data, _queryEnv, _featureOverrides, profiler);
     }
     bool can_reuse_search = (_search && !_search_has_changed &&
             contains_all(_used_handles, recorder.get_handles()));
@@ -123,34 +123,34 @@ MatchTools::has_second_phase_rank() const {
 }
 
 void
-MatchTools::setup_first_phase()
+MatchTools::setup_first_phase(ExecutionProfiler *profiler)
 {
-    setup(_rankSetup.create_first_phase_program(),
+    setup(_rankSetup.create_first_phase_program(), profiler,
           TermwiseLimit::lookup(_queryEnv.getProperties(), _rankSetup.get_termwise_limit()));
 }
 
 void
-MatchTools::setup_second_phase()
+MatchTools::setup_second_phase(ExecutionProfiler *profiler)
 {
-    setup(_rankSetup.create_second_phase_program());
+    setup(_rankSetup.create_second_phase_program(), profiler);
 }
 
 void
 MatchTools::setup_match_features()
 {
-    setup(_rankSetup.create_match_program());
+    setup(_rankSetup.create_match_program(), nullptr);
 }
 
 void
 MatchTools::setup_summary()
 {
-    setup(_rankSetup.create_summary_program());
+    setup(_rankSetup.create_summary_program(), nullptr);
 }
 
 void
 MatchTools::setup_dump()
 {
-    setup(_rankSetup.create_dump_program());
+    setup(_rankSetup.create_dump_program(), nullptr);
 }
 
 //-----------------------------------------------------------------------------
diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_tools.h b/searchcore/src/vespa/searchcore/proton/matching/match_tools.h
index 5d98fabeb11..e7a1ccfa568 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/match_tools.h
+++ b/searchcore/src/vespa/searchcore/proton/matching/match_tools.h
@@ -18,12 +18,15 @@
 #include <vespa/vespalib/util/doom.h>
 #include <vespa/vespalib/util/clock.h>
 
+namespace vespalib { class ExecutionProfiler; }
+
 namespace search::engine { class Trace; }
 
 namespace search::fef {
     class RankProgram;
     class RankSetup;
 }
+
 namespace proton::matching {
 
 class MatchTools
@@ -36,6 +39,7 @@ private:
     using Properties = search::fef::Properties;
     using RankProgram = search::fef::RankProgram;
     using RankSetup = search::fef::RankSetup;
+    using ExecutionProfiler = vespalib::ExecutionProfiler;
     QueryLimiter                    &_queryLimiter;
     const vespalib::Doom            &_doom;
     const Query                     &_query;
@@ -48,7 +52,7 @@ private:
     std::unique_ptr<SearchIterator>  _search;
     HandleRecorder::HandleMap        _used_handles;
     bool                             _search_has_changed;
-    void setup(std::unique_ptr<RankProgram>, double termwise_limit = 1.0);
+    void setup(std::unique_ptr<RankProgram>, ExecutionProfiler *profiler, double termwise_limit = 1.0);
 public:
     typedef std::unique_ptr<MatchTools> UP;
     MatchTools(const MatchTools &) = delete;
@@ -72,8 +76,8 @@ public:
     std::unique_ptr<SearchIterator> borrow_search() { return std::move(_search); }
     void give_back_search(std::unique_ptr<SearchIterator> search_in) { _search = std::move(search_in); }
     void tag_search_as_changed() { _search_has_changed = true; }
-    void setup_first_phase();
-    void setup_second_phase();
+    void setup_first_phase(ExecutionProfiler *profiler);
+    void setup_second_phase(ExecutionProfiler *profiler);
     void setup_match_features();
     void setup_summary();
     void setup_dump();