Merge pull request #22288 from vespa-engine/geirst/reapply-improve-query-setup-tracing

Improve and re-structure trace logging from the query setup part of m…

8 files changed, 70 insertions, 39 deletions

diff --git a/searchcore/src/tests/proton/matching/query_test.cpp b/searchcore/src/tests/proton/matching/query_test.cpp
index 7f0232120e7..1c31cb1d1ad 100644
--- a/searchcore/src/tests/proton/matching/query_test.cpp
+++ b/searchcore/src/tests/proton/matching/query_test.cpp
@@ -1138,19 +1138,19 @@ Test::global_filter_is_calculated_and_handled()
     uint32_t docid_limit = 10;
     { // global filter is not wanted
         GlobalFilterBlueprint bp(result, false);
-        auto res = Query::handle_global_filter(bp, docid_limit, 0, 1);
+        auto res = Query::handle_global_filter(bp, docid_limit, 0, 1, nullptr);
         EXPECT_FALSE(res);
         EXPECT_FALSE(bp.filter);
     }
     { // estimated_hit_ratio < global_filter_lower_limit
         GlobalFilterBlueprint bp(result, true);
-        auto res = Query::handle_global_filter(bp, docid_limit, 0.31, 1);
+        auto res = Query::handle_global_filter(bp, docid_limit, 0.31, 1, nullptr);
         EXPECT_FALSE(res);
         EXPECT_FALSE(bp.filter);
     }
     { // estimated_hit_ratio <= global_filter_upper_limit
         GlobalFilterBlueprint bp(result, true);
-        auto res = Query::handle_global_filter(bp, docid_limit, 0, 0.3);
+        auto res = Query::handle_global_filter(bp, docid_limit, 0, 0.3, nullptr);
         EXPECT_TRUE(res);
         EXPECT_TRUE(bp.filter);
         EXPECT_TRUE(bp.filter->has_filter());
@@ -1163,7 +1163,7 @@ Test::global_filter_is_calculated_and_handled()
     }
     { // estimated_hit_ratio > global_filter_upper_limit
         GlobalFilterBlueprint bp(result, true);
-        auto res = Query::handle_global_filter(bp, docid_limit, 0, 0.29);
+        auto res = Query::handle_global_filter(bp, docid_limit, 0, 0.29, nullptr);
         EXPECT_TRUE(res);
         EXPECT_TRUE(bp.filter);
         EXPECT_FALSE(bp.filter->has_filter());
diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp b/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp
index 3ff0a7d1808..624922eb27b 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp
@@ -109,7 +109,7 @@ MatchMaster::match(search::engine::Trace & trace,
     double match_time_s = 0.0;
     std::unique_ptr<vespalib::slime::Inserter> inserter;
     if (trace.shouldTrace(4)) {
-        inserter = std::make_unique<vespalib::slime::ArrayInserter>(trace.createCursor("match_threads").setArray("threads"));
+        inserter = std::make_unique<vespalib::slime::ArrayInserter>(trace.createCursor("query_execution").setArray("threads"));
     }
     for (size_t i = 0; i < threadState.size(); ++i) {
         const MatchThread & matchThread = *threadState[i];
diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp b/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp
index 37635825295..3d8d56f0150 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp
@@ -3,12 +3,15 @@
 #include "match_tools.h"
 #include "querynodes.h"
 #include <vespa/searchcorespi/index/indexsearchable.h>
+#include <vespa/searchlib/attribute/attribute_blueprint_params.h>
+#include <vespa/searchlib/attribute/attribute_operation.h>
+#include <vespa/searchlib/attribute/diversity.h>
+#include <vespa/searchlib/engine/trace.h>
 #include <vespa/searchlib/fef/indexproperties.h>
 #include <vespa/searchlib/fef/ranksetup.h>
-#include <vespa/searchlib/engine/trace.h>
-#include <vespa/searchlib/attribute/diversity.h>
-#include <vespa/searchlib/attribute/attribute_operation.h>
-#include <vespa/searchlib/attribute/attribute_blueprint_params.h>
+#include <vespa/vespalib/data/slime/cursor.h>
+#include <vespa/vespalib/data/slime/inject.h>
+#include <vespa/vespalib/data/slime/inserter.h>
 #include <vespa/vespalib/util/issue.h>
 
 #include <vespa/log/log.h>
@@ -167,7 +170,7 @@ MatchToolsFactory(QueryLimiter               & queryLimiter,
                   const vespalib::Doom       & doom,
                   ISearchContext             & searchContext,
                   IAttributeContext          & attributeContext,
-                  search::engine::Trace      & trace,
+                  search::engine::Trace      & root_trace,
                   vespalib::stringref          queryStack,
                   const vespalib::string     & location,
                   const ViewResolver         & viewResolver,
@@ -188,34 +191,35 @@ MatchToolsFactory(QueryLimiter               & queryLimiter,
       _diversityParams(),
       _valid(false)
 {
-    trace.addEvent(4, "MTF: Start");
+    search::engine::Trace trace(root_trace.getRelativeTime(), root_trace.getLevel());
+    trace.addEvent(4, "Start query setup");
     _query.setWhiteListBlueprint(metaStore.createWhiteListBlueprint());
-    trace.addEvent(5, "MTF: Build query");
+    trace.addEvent(5, "Deserialize and build query tree");
     _valid = _query.buildTree(queryStack, location, viewResolver, indexEnv,
                               rankSetup.split_unpacking_iterators(),
                               rankSetup.delay_unpacking_iterators());
     if (_valid) {
         _query.extractTerms(_queryEnv.terms());
         _query.extractLocations(_queryEnv.locations());
-        trace.addEvent(5, "MTF: reserve handles");
+        trace.addEvent(5, "Build query execution plan");
         _query.reserveHandles(_requestContext, searchContext, _mdl);
+        trace.addEvent(5, "Optimize query execution plan");
         _query.optimize();
-        trace.addEvent(4, "MTF: Fetch Postings");
+        trace.addEvent(4, "Perform dictionary lookups and posting lists initialization");
         _query.fetchPostings();
         if (is_search) {
-            trace.addEvent(5, "MTF: Handle Global Filters");
             double lower_limit = GlobalFilterLowerLimit::lookup(rankProperties, rankSetup.get_global_filter_lower_limit());
             double upper_limit = GlobalFilterUpperLimit::lookup(rankProperties, rankSetup.get_global_filter_upper_limit());
-            _query.handle_global_filter(searchContext.getDocIdLimit(), lower_limit, upper_limit);
+            _query.handle_global_filter(searchContext.getDocIdLimit(), lower_limit, upper_limit, trace);
         }
         _query.freeze();
-        trace.addEvent(5, "MTF: prepareSharedState");
+        trace.addEvent(5, "Prepare shared state for multi-threaded rank executors");
         _rankSetup.prepareSharedState(_queryEnv, _queryEnv.getObjectStore());
         _diversityParams = extractDiversityParams(_rankSetup, rankProperties);
         DegradationParams degradationParams = extractDegradationParams(_rankSetup, rankProperties);
 
         if (degradationParams.enabled()) {
-            trace.addEvent(5, "MTF: Build MatchPhaseLimiter");
+            trace.addEvent(5, "Setup match phase limiter");
             _match_limiter = std::make_unique<MatchPhaseLimiter>(metaStore.getCommittedDocIdLimit(), searchContext.getAttributes(),
                                                                  _requestContext, degradationParams, _diversityParams);
         }
@@ -223,7 +227,11 @@ MatchToolsFactory(QueryLimiter               & queryLimiter,
     if ( ! _match_limiter) {
         _match_limiter = std::make_unique<NoMatchPhaseLimiter>();
     }
-    trace.addEvent(4, "MTF: Complete");
+    trace.addEvent(4, "Complete query setup");
+    if (root_trace.shouldTrace(4)) {
+        vespalib::slime::ObjectInserter inserter(root_trace.createCursor("query_setup"), "traces");
+        vespalib::slime::inject(trace.getTraces(), inserter);
+    }
 }
 
 MatchToolsFactory::~MatchToolsFactory() = default;
diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_tools.h b/searchcore/src/vespa/searchcore/proton/matching/match_tools.h
index 4b5f9cf76cc..a7d39a0c3e8 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/match_tools.h
+++ b/searchcore/src/vespa/searchcore/proton/matching/match_tools.h
@@ -114,7 +114,7 @@ public:
                       const vespalib::Doom & softDoom,
                       ISearchContext &searchContext,
                       search::attribute::IAttributeContext &attributeContext,
-                      search::engine::Trace & trace,
+                      search::engine::Trace & root_trace,
                       vespalib::stringref queryStack,
                       const vespalib::string &location,
                       const ViewResolver &viewResolver,
diff --git a/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp b/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp
index e945bbb850b..756af216988 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/matcher.cpp
@@ -176,7 +176,7 @@ namespace {
     void traceQuery(uint32_t traceLevel, Trace & trace, const Query & query) {
         if (traceLevel <= trace.getLevel()) {
             if (query.peekRoot()) {
-                vespalib::slime::ObjectInserter inserter(trace.createCursor("blueprint"), "optimized");
+                vespalib::slime::ObjectInserter inserter(trace.createCursor("query_execution_plan"), "optimized");
                 query.peekRoot()->asSlime(inserter);
             }
         }
diff --git a/searchcore/src/vespa/searchcore/proton/matching/query.cpp b/searchcore/src/vespa/searchcore/proton/matching/query.cpp
index 95fe846a088..84671ec72c7 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/query.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/query.cpp
@@ -1,15 +1,16 @@
 // Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 
-#include "query.h"
 #include "blueprintbuilder.h"
 #include "matchdatareservevisitor.h"
+#include "query.h"
 #include "resolveviewvisitor.h"
-#include "termdataextractor.h"
 #include "sameelementmodifier.h"
+#include "termdataextractor.h"
 #include "unpacking_iterators_optimizer.h"
 #include <vespa/document/datatype/positiondatatype.h>
-#include <vespa/searchlib/common/geo_location_spec.h>
 #include <vespa/searchlib/common/geo_location_parser.h>
+#include <vespa/searchlib/common/geo_location_spec.h>
+#include <vespa/searchlib/engine/trace.h>
 #include <vespa/searchlib/parsequery/stackdumpiterator.h>
 #include <vespa/searchlib/queryeval/intermediate_blueprints.h>
 #include <vespa/vespalib/util/issue.h>
@@ -27,19 +28,19 @@ using search::fef::IIndexEnvironment;
 using search::fef::ITermData;
 using search::fef::MatchData;
 using search::fef::MatchDataLayout;
+using search::query::LocationTerm;
 using search::query::Node;
 using search::query::QueryTreeCreator;
 using search::query::Weight;
 using search::queryeval::AndBlueprint;
 using search::queryeval::AndNotBlueprint;
-using search::queryeval::RankBlueprint;
-using search::queryeval::IntermediateBlueprint;
 using search::queryeval::Blueprint;
 using search::queryeval::IRequestContext;
+using search::queryeval::IntermediateBlueprint;
+using search::queryeval::RankBlueprint;
 using search::queryeval::SearchIterator;
-using search::query::LocationTerm;
-using vespalib::string;
 using vespalib::Issue;
+using vespalib::string;
 using std::vector;
 
 namespace proton::matching {
@@ -244,12 +245,14 @@ Query::fetchPostings()
 }
 
 void
-Query::handle_global_filter(uint32_t docid_limit, double global_filter_lower_limit, double global_filter_upper_limit)
+Query::handle_global_filter(uint32_t docid_limit, double global_filter_lower_limit, double global_filter_upper_limit,
+                            search::engine::Trace& trace)
 {
-    if (!handle_global_filter(*_blueprint, docid_limit, global_filter_lower_limit, global_filter_upper_limit)) {
+    if (!handle_global_filter(*_blueprint, docid_limit, global_filter_lower_limit, global_filter_upper_limit, &trace)) {
         return;
     }
     // optimized order may change after accounting for global filter:
+    trace.addEvent(5, "Optimize query execution plan to account for global filter");
     _blueprint = Blueprint::optimize(std::move(_blueprint));
     LOG(debug, "blueprint after handle_global_filter:\n%s\n", _blueprint->asString().c_str());
     // strictness may change if optimized order changed:
@@ -257,7 +260,9 @@ Query::handle_global_filter(uint32_t docid_limit, double global_filter_lower_lim
 }
 
 bool
-Query::handle_global_filter(Blueprint& blueprint, uint32_t docid_limit, double global_filter_lower_limit, double global_filter_upper_limit)
+Query::handle_global_filter(Blueprint& blueprint, uint32_t docid_limit,
+                            double global_filter_lower_limit, double global_filter_upper_limit,
+                            search::engine::Trace* trace)
 {
     using search::queryeval::GlobalFilter;
     double estimated_hit_ratio = blueprint.getState().hit_ratio(docid_limit);
@@ -265,24 +270,37 @@ Query::handle_global_filter(Blueprint& blueprint, uint32_t docid_limit, double g
         return false;
     }
 
-    LOG(debug, "docid_limit=%d, estimated_hit_ratio=%1.2f, global_filter_lower_limit=%1.2f, global_filter_upper_limit=%1.2f",
-        docid_limit, estimated_hit_ratio, global_filter_lower_limit, global_filter_upper_limit);
     if (estimated_hit_ratio < global_filter_lower_limit) {
+        if (trace && trace->shouldTrace(5)) {
+            trace->addEvent(5, vespalib::make_string("Skip calculate global filter (estimated_hit_ratio (%f) < lower_limit (%f))",
+                                                     estimated_hit_ratio, global_filter_lower_limit));
+        }
         return false;
     }
 
+    std::shared_ptr<GlobalFilter> global_filter;
     if (estimated_hit_ratio <= global_filter_upper_limit) {
+        if (trace && trace->shouldTrace(5)) {
+            trace->addEvent(5, vespalib::make_string("Calculate global filter (estimated_hit_ratio (%f) <= upper_limit (%f))",
+                                                     estimated_hit_ratio, global_filter_upper_limit));
+        }
         auto constraint = Blueprint::FilterConstraint::UPPER_BOUND;
         bool strict = true;
         auto filter_iterator = blueprint.createFilterSearch(strict, constraint);
         filter_iterator->initRange(1, docid_limit);
         auto white_list = filter_iterator->get_hits(1);
-        auto global_filter = GlobalFilter::create(std::move(white_list));
-        blueprint.set_global_filter(*global_filter);
+        global_filter = GlobalFilter::create(std::move(white_list));
     } else {
-        auto no_filter = GlobalFilter::create();
-        blueprint.set_global_filter(*no_filter);
+        if (trace && trace->shouldTrace(5)) {
+            trace->addEvent(5, vespalib::make_string("Create match all global filter (estimated_hit_ratio (%f) > upper_limit (%f))",
+                                                     estimated_hit_ratio, global_filter_upper_limit));
+        }
+        global_filter = GlobalFilter::create();
+    }
+    if (trace) {
+        trace->addEvent(5, "Handle global filter in query execution plan");
     }
+    blueprint.set_global_filter(*global_filter);
     return true;
 }
 
diff --git a/searchcore/src/vespa/searchcore/proton/matching/query.h b/searchcore/src/vespa/searchcore/proton/matching/query.h
index 29bca310502..09eaed5c4a9 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/query.h
+++ b/searchcore/src/vespa/searchcore/proton/matching/query.h
@@ -10,6 +10,8 @@
 #include <vespa/searchlib/queryeval/blueprint.h>
 #include <vespa/searchlib/queryeval/irequestcontext.h>
 
+namespace search::engine { class Trace; }
+
 namespace proton::matching {
 
 class ViewResolver;
@@ -93,7 +95,8 @@ public:
     void optimize();
     void fetchPostings();
 
-    void handle_global_filter(uint32_t docid_limit, double global_filter_lower_limit, double global_filter_upper_limit);
+    void handle_global_filter(uint32_t docid_limit, double global_filter_lower_limit, double global_filter_upper_limit,
+                              search::engine::Trace& trace);
 
     /**
      * Calculates and handles the global filter if needed by the blueprint tree.
@@ -109,7 +112,8 @@ public:
      * @return whether the global filter was set on the blueprint.
      */
     static bool handle_global_filter(Blueprint& blueprint, uint32_t docid_limit,
-                                     double global_filter_lower_limit, double global_filter_upper_limit);
+                                     double global_filter_lower_limit, double global_filter_upper_limit,
+                                     search::engine::Trace* trace);
 
     void freeze();
 
diff --git a/searchlib/src/vespa/searchlib/engine/trace.h b/searchlib/src/vespa/searchlib/engine/trace.h
index 1940af5cf38..709dc05d93c 100644
--- a/searchlib/src/vespa/searchlib/engine/trace.h
+++ b/searchlib/src/vespa/searchlib/engine/trace.h
@@ -85,6 +85,7 @@ public:
     vespalib::string toString() const;
     bool hasTrace() const { return static_cast<bool>(_trace); }
     Cursor & getRoot() const { return root(); }
+    Cursor & getTraces() const { return traces(); }
     vespalib::Slime & getSlime() const { return slime(); }
     bool shouldTrace(uint32_t level) const { return level <= _level; }
     uint32_t getLevel() const { return _level; }