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

7 files changed, 39 insertions, 69 deletions

diff --git a/searchcore/src/tests/proton/matching/query_test.cpp b/searchcore/src/tests/proton/matching/query_test.cpp
index 1c31cb1d1ad..7f0232120e7 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, nullptr);
+        auto res = Query::handle_global_filter(bp, docid_limit, 0, 1);
         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, nullptr);
+        auto res = Query::handle_global_filter(bp, docid_limit, 0.31, 1);
         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, nullptr);
+        auto res = Query::handle_global_filter(bp, docid_limit, 0, 0.3);
         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, nullptr);
+        auto res = Query::handle_global_filter(bp, docid_limit, 0, 0.29);
         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 624922eb27b..3ff0a7d1808 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("query_execution").setArray("threads"));
+        inserter = std::make_unique<vespalib::slime::ArrayInserter>(trace.createCursor("match_threads").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 3d8d56f0150..37635825295 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp
@@ -3,15 +3,12 @@
 #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/vespalib/data/slime/cursor.h>
-#include <vespa/vespalib/data/slime/inject.h>
-#include <vespa/vespalib/data/slime/inserter.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/util/issue.h>
 
 #include <vespa/log/log.h>
@@ -170,7 +167,7 @@ MatchToolsFactory(QueryLimiter               & queryLimiter,
                   const vespalib::Doom       & doom,
                   ISearchContext             & searchContext,
                   IAttributeContext          & attributeContext,
-                  search::engine::Trace      & root_trace,
+                  search::engine::Trace      & trace,
                   vespalib::stringref          queryStack,
                   const vespalib::string     & location,
                   const ViewResolver         & viewResolver,
@@ -191,35 +188,34 @@ MatchToolsFactory(QueryLimiter               & queryLimiter,
       _diversityParams(),
       _valid(false)
 {
-    search::engine::Trace trace(root_trace.getRelativeTime(), root_trace.getLevel());
-    trace.addEvent(4, "Start query setup");
+    trace.addEvent(4, "MTF: Start");
     _query.setWhiteListBlueprint(metaStore.createWhiteListBlueprint());
-    trace.addEvent(5, "Deserialize and build query tree");
+    trace.addEvent(5, "MTF: Build query");
     _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, "Build query execution plan");
+        trace.addEvent(5, "MTF: reserve handles");
         _query.reserveHandles(_requestContext, searchContext, _mdl);
-        trace.addEvent(5, "Optimize query execution plan");
         _query.optimize();
-        trace.addEvent(4, "Perform dictionary lookups and posting lists initialization");
+        trace.addEvent(4, "MTF: Fetch Postings");
         _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, trace);
+            _query.handle_global_filter(searchContext.getDocIdLimit(), lower_limit, upper_limit);
         }
         _query.freeze();
-        trace.addEvent(5, "Prepare shared state for multi-threaded rank executors");
+        trace.addEvent(5, "MTF: prepareSharedState");
         _rankSetup.prepareSharedState(_queryEnv, _queryEnv.getObjectStore());
         _diversityParams = extractDiversityParams(_rankSetup, rankProperties);
         DegradationParams degradationParams = extractDegradationParams(_rankSetup, rankProperties);
 
         if (degradationParams.enabled()) {
-            trace.addEvent(5, "Setup match phase limiter");
+            trace.addEvent(5, "MTF: Build MatchPhaseLimiter");
             _match_limiter = std::make_unique<MatchPhaseLimiter>(metaStore.getCommittedDocIdLimit(), searchContext.getAttributes(),
                                                                  _requestContext, degradationParams, _diversityParams);
         }
@@ -227,11 +223,7 @@ MatchToolsFactory(QueryLimiter               & queryLimiter,
     if ( ! _match_limiter) {
         _match_limiter = std::make_unique<NoMatchPhaseLimiter>();
     }
-    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);
-    }
+    trace.addEvent(4, "MTF: Complete");
 }
 
 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 a7d39a0c3e8..4b5f9cf76cc 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 & root_trace,
+                      search::engine::Trace & 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 756af216988..e945bbb850b 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("query_execution_plan"), "optimized");
+                vespalib::slime::ObjectInserter inserter(trace.createCursor("blueprint"), "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 84671ec72c7..95fe846a088 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/query.cpp
+++ b/searchcore/src/vespa/searchcore/proton/matching/query.cpp
@@ -1,16 +1,15 @@
 // 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 "sameelementmodifier.h"
 #include "termdataextractor.h"
+#include "sameelementmodifier.h"
 #include "unpacking_iterators_optimizer.h"
 #include <vespa/document/datatype/positiondatatype.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/common/geo_location_parser.h>
 #include <vespa/searchlib/parsequery/stackdumpiterator.h>
 #include <vespa/searchlib/queryeval/intermediate_blueprints.h>
 #include <vespa/vespalib/util/issue.h>
@@ -28,19 +27,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 vespalib::Issue;
+using search::query::LocationTerm;
 using vespalib::string;
+using vespalib::Issue;
 using std::vector;
 
 namespace proton::matching {
@@ -245,14 +244,12 @@ Query::fetchPostings()
 }
 
 void
-Query::handle_global_filter(uint32_t docid_limit, double global_filter_lower_limit, double global_filter_upper_limit,
-                            search::engine::Trace& trace)
+Query::handle_global_filter(uint32_t docid_limit, double global_filter_lower_limit, double global_filter_upper_limit)
 {
-    if (!handle_global_filter(*_blueprint, docid_limit, global_filter_lower_limit, global_filter_upper_limit, &trace)) {
+    if (!handle_global_filter(*_blueprint, docid_limit, global_filter_lower_limit, global_filter_upper_limit)) {
         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:
@@ -260,9 +257,7 @@ 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,
-                            search::engine::Trace* trace)
+Query::handle_global_filter(Blueprint& blueprint, uint32_t docid_limit, double global_filter_lower_limit, double global_filter_upper_limit)
 {
     using search::queryeval::GlobalFilter;
     double estimated_hit_ratio = blueprint.getState().hit_ratio(docid_limit);
@@ -270,37 +265,24 @@ Query::handle_global_filter(Blueprint& blueprint, uint32_t docid_limit,
         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);
-        global_filter = GlobalFilter::create(std::move(white_list));
+        auto global_filter = GlobalFilter::create(std::move(white_list));
+        blueprint.set_global_filter(*global_filter);
     } else {
-        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");
+        auto no_filter = GlobalFilter::create();
+        blueprint.set_global_filter(*no_filter);
     }
-    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 09eaed5c4a9..29bca310502 100644
--- a/searchcore/src/vespa/searchcore/proton/matching/query.h
+++ b/searchcore/src/vespa/searchcore/proton/matching/query.h
@@ -10,8 +10,6 @@
 #include <vespa/searchlib/queryeval/blueprint.h>
 #include <vespa/searchlib/queryeval/irequestcontext.h>
 
-namespace search::engine { class Trace; }
-
 namespace proton::matching {
 
 class ViewResolver;
@@ -95,8 +93,7 @@ public:
     void optimize();
     void fetchPostings();
 
-    void handle_global_filter(uint32_t docid_limit, double global_filter_lower_limit, double global_filter_upper_limit,
-                              search::engine::Trace& trace);
+    void handle_global_filter(uint32_t docid_limit, double global_filter_lower_limit, double global_filter_upper_limit);
 
     /**
      * Calculates and handles the global filter if needed by the blueprint tree.
@@ -112,8 +109,7 @@ 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,
-                                     search::engine::Trace* trace);
+                                     double global_filter_lower_limit, double global_filter_upper_limit);
 
     void freeze();