Merge pull request #25967 from vespa-engine/havardpe/trace-global-filter-iterator-tree

trace global filter iterator tree

4 files changed, 140 insertions, 36 deletions

diff --git a/searchlib/src/tests/queryeval/global_filter/global_filter_test.cpp b/searchlib/src/tests/queryeval/global_filter/global_filter_test.cpp
index dcf175a6fdd..49d579b6d3d 100644
--- a/searchlib/src/tests/queryeval/global_filter/global_filter_test.cpp
+++ b/searchlib/src/tests/queryeval/global_filter/global_filter_test.cpp
@@ -8,12 +8,15 @@
 #include <vespa/searchlib/queryeval/global_filter.h>
 #include <vespa/searchlib/queryeval/intermediate_blueprints.h>
 #include <vespa/searchlib/queryeval/leaf_blueprints.h>
+#include <vespa/searchlib/engine/trace.h>
+#include <vespa/vespalib/data/slime/slime.h>
 
 #include <gmock/gmock.h>
 #include <vector>
 
 using namespace testing;
 using namespace search::queryeval;
+using namespace search::engine;
 
 using search::BitVector;
 using vespalib::RequireFailedException;
@@ -217,4 +220,15 @@ TEST(GlobalFilterTest, global_filter_not_matching_any_document_becomes_empty) {
     verify(*filter, 1000, 100);
 }
 
+TEST(GlobalFilterTest, global_filter_with_profiling_and_tracing) {
+    SimpleThreadBundle thread_bundle(4);
+    auto blueprint = create_blueprint();
+    RelativeTime my_time(std::make_unique<SteadyClock>());
+    Trace trace(my_time, 7);
+    trace.match_profile_depth(64);
+    auto filter = GlobalFilter::create(*blueprint, 100, thread_bundle, &trace);
+    verify(*filter);
+    fprintf(stderr, "trace: %s\n", trace.getSlime().toString().c_str());
+}
+
 GTEST_MAIN_RUN_ALL_TESTS()
diff --git a/searchlib/src/vespa/searchlib/engine/trace.cpp b/searchlib/src/vespa/searchlib/engine/trace.cpp
index 27e652db651..351a8f636bb 100644
--- a/searchlib/src/vespa/searchlib/engine/trace.cpp
+++ b/searchlib/src/vespa/searchlib/engine/trace.cpp
@@ -26,6 +26,59 @@ Trace::constructTraces() const {
     _traces = & root().setArray("traces");
 }
 
+vespalib::slime::Cursor &
+LazyTraceInserter::get_entry() {
+    if (!_entry) {
+        _entry = &_parent.createCursor(_name);
+    }
+    return *_entry;
+}
+
+vespalib::slime::Inserter &
+LazyTraceInserter::get_thread_inserter()
+{
+    if (!_thread_inserter) {
+        _thread_inserter = std::make_unique<vespalib::slime::ArrayInserter>(get_entry().setArray("threads"));
+    }
+    return *_thread_inserter;
+}
+
+LazyTraceInserter::LazyTraceInserter(search::engine::Trace &parent, vespalib::StaticStringView name) noexcept
+  : _parent(parent), _name(name), _entry(nullptr), _thread_inserter()
+{
+}
+
+LazyTraceInserter::~LazyTraceInserter() = default;
+
+void
+LazyTraceInserter::handle_nested(const search::engine::Trace &nested_trace)
+{
+    if (nested_trace.hasTrace()) {
+        vespalib::slime::ObjectInserter inserter(get_entry(), "traces");
+        vespalib::slime::inject(nested_trace.getTraces(), inserter);
+    }
+}
+
+void
+LazyTraceInserter::handle_thread(const search::engine::Trace &thread_trace)
+{
+    if (thread_trace.hasTrace()) {
+        vespalib::slime::inject(thread_trace.getRoot(), get_thread_inserter());
+    }
+}
+
+Trace::Trace(const Trace &parent, ctor_tag)
+    : _trace(),
+      _root(nullptr),
+      _traces(nullptr),
+      _relativeTime(parent._relativeTime),
+      _level(parent._level),
+      _match_profile_depth(parent._match_profile_depth),
+      _first_phase_profile_depth(parent._first_phase_profile_depth),
+      _second_phase_profile_depth(parent._second_phase_profile_depth)
+{
+}
+
 Trace::Trace(const RelativeTime & relativeTime, uint32_t level)
     : _trace(),
       _root(nullptr),
diff --git a/searchlib/src/vespa/searchlib/engine/trace.h b/searchlib/src/vespa/searchlib/engine/trace.h
index a76313ca5a5..8543e171b21 100644
--- a/searchlib/src/vespa/searchlib/engine/trace.h
+++ b/searchlib/src/vespa/searchlib/engine/trace.h
@@ -3,11 +3,13 @@
 #pragma once
 
 #include <vespa/vespalib/stllike/string.h>
+#include <vespa/vespalib/util/static_string.h>
 #include <vespa/vespalib/util/time.h>
 #include <memory>
 
 namespace vespalib { class Slime; }
 namespace vespalib::slime { struct Cursor; }
+namespace vespalib::slime { struct Inserter; }
 
 namespace search::engine {
 
@@ -46,14 +48,36 @@ private:
     std::unique_ptr<Clock>  _clock;
 };
 
+class Trace;
+
+// Helper class used to inject subtraces back into a parent trace
+class LazyTraceInserter
+{
+private:
+    Trace &_parent;
+    vespalib::stringref _name;
+    vespalib::slime::Cursor *_entry;
+    std::unique_ptr<vespalib::slime::Inserter> _thread_inserter;
+    vespalib::slime::Cursor &get_entry();
+    vespalib::slime::Inserter &get_thread_inserter();
+public:
+    LazyTraceInserter(search::engine::Trace &parent, vespalib::StaticStringView name) noexcept;
+    ~LazyTraceInserter();
+    void handle_nested(const search::engine::Trace &nested_trace);
+    void handle_thread(const search::engine::Trace &thread_trace);
+};
+
 /**
  * Used for adding traces to a request. Acquire a new Cursor for everytime you want to trace something.
  * Note that it is not thread safe. All use of any cursor aquired must be thread safe.
  */
 class Trace
 {
+private:
+    struct ctor_tag {};
 public:
     using Cursor = vespalib::slime::Cursor;
+    Trace(const Trace &parent, ctor_tag);
     Trace(const RelativeTime & relativeTime, uint32_t traceLevel);
     ~Trace();
 
@@ -102,7 +126,9 @@ public:
     int32_t match_profile_depth() const { return _match_profile_depth; }
     int32_t first_phase_profile_depth() const { return _first_phase_profile_depth; }
     int32_t second_phase_profile_depth() const { return _second_phase_profile_depth; }
-    const RelativeTime & getRelativeTime() const { return _relativeTime; }
+    Trace make_trace() const { return Trace(*this, ctor_tag()); }
+    std::unique_ptr<Trace> make_trace_up() const { return std::make_unique<Trace>(*this, ctor_tag()); }
+    LazyTraceInserter make_inserter(vespalib::StaticStringView name) { return {*this, name}; }
 private:
     vespalib::Slime & slime() const {
         if (!hasTrace()) {
diff --git a/searchlib/src/vespa/searchlib/queryeval/global_filter.cpp b/searchlib/src/vespa/searchlib/queryeval/global_filter.cpp
index f4ee9bf9bc2..d8a2c1c1d16 100644
--- a/searchlib/src/vespa/searchlib/queryeval/global_filter.cpp
+++ b/searchlib/src/vespa/searchlib/queryeval/global_filter.cpp
@@ -21,6 +21,8 @@ namespace search::queryeval {
 
 namespace {
 
+using namespace vespalib::literals;
+
 struct Inactive : GlobalFilter {
     bool is_active() const override { return false; }
     uint32_t size() const override { abort(); }
@@ -86,52 +88,62 @@ struct PartResult {
       : matches_any(Trinary::Undefined), bits(std::move(bits_in)) {}
 };
 
-PartResult make_part(Blueprint &blueprint, uint32_t begin, uint32_t end, ExecutionProfiler *profiler) {
-    bool strict = true;
-    auto constraint = Blueprint::FilterConstraint::UPPER_BOUND;
-    auto filter = blueprint.createFilterSearch(strict, constraint);
-    auto matches_any = filter->matches_any();
-    if (matches_any == Trinary::Undefined) {
-        if (profiler) {
-            filter = ProfiledIterator::profile(*profiler, std::move(filter));
-        }
-        filter->initRange(begin, end);
-        auto bits = filter->get_hits(begin);
-        // count bits in parallel and cache the results for later
-        bits->countTrueBits();
-        return PartResult(std::move(bits));
-    } else {
-        return PartResult(matches_any);
-    }
-}
-
 struct MakePart : Runnable {
     Blueprint &blueprint;
     uint32_t begin;
     uint32_t end;
     PartResult result;
+    std::unique_ptr<Trace> trace;
     std::unique_ptr<ExecutionProfiler> profiler;
     MakePart(MakePart &&) = default;
-    MakePart(Blueprint &blueprint_in, uint32_t begin_in, uint32_t end_in, int32_t profile_depth)
-      : blueprint(blueprint_in), begin(begin_in), end(end_in), result(), profiler()
+    MakePart(Blueprint &blueprint_in, uint32_t begin_in, uint32_t end_in, Trace *parent_trace)
+      : blueprint(blueprint_in), begin(begin_in), end(end_in), result(), trace(), profiler()
     {
-        if (profile_depth != 0) {
-            profiler = std::make_unique<ExecutionProfiler>(profile_depth);
+        if (parent_trace && parent_trace->getLevel() > 0) {
+            trace = parent_trace->make_trace_up();
+            if (int32_t profile_depth = trace->match_profile_depth(); profile_depth != 0) {
+                profiler = std::make_unique<ExecutionProfiler>(profile_depth);
+            }
+        }
+    }
+    bool is_first_thread() const { return (begin == 1); }
+    bool should_trace(int level) const { return trace && trace->shouldTrace(level); }
+    void run() override {
+        bool strict = true;
+        auto constraint = Blueprint::FilterConstraint::UPPER_BOUND;
+        auto filter = blueprint.createFilterSearch(strict, constraint);
+        if (is_first_thread() && should_trace(7)) {
+            vespalib::slime::ObjectInserter inserter(trace->createCursor("iterator"), "optimized");
+            filter->asSlime(inserter);
+        }
+        auto matches_any = filter->matches_any();
+        if (matches_any == Trinary::Undefined) {
+            if (profiler) {
+                filter = ProfiledIterator::profile(*profiler, std::move(filter));
+            }
+            filter->initRange(begin, end);
+            auto bits = filter->get_hits(begin);
+            // count bits in parallel and cache the results for later
+            bits->countTrueBits();
+            result = PartResult(std::move(bits));
+        } else {
+            result = PartResult(matches_any);
+        }
+        if (profiler) {
+            profiler->report(trace->createCursor("global_filter_profiling"));
         }
     }
-    void run() override { result = make_part(blueprint, begin, end, profiler.get()); }
     ~MakePart();
 };
 MakePart::~MakePart() = default;
 
-void maybe_insert_profiler_results(Trace *trace, int32_t profile_depth, const std::vector<MakePart> &parts) {
-    if (trace && profile_depth != 0) {
-        auto &obj = trace->createCursor("global_filter_execution");
-        auto &arr = obj.setArray("threads");
-        for (auto &&part: parts) {
-            auto &dst = arr.addObject().setArray("traces").addObject();
-            dst.setString("tag", "global_filter_profiling");
-            part.profiler->report(dst);
+void insert_traces(Trace *trace, const std::vector<MakePart> &parts) {
+    if (trace) {
+        auto inserter = trace->make_inserter("global_filter_execution"_ssv);
+        for (const auto &part: parts) {
+            if (part.trace) {
+                inserter.handle_thread(*part.trace);
+            }
         }
     }
 }
@@ -191,7 +203,6 @@ GlobalFilter::create(std::vector<std::unique_ptr<BitVector>> vectors)
 std::shared_ptr<GlobalFilter>
 GlobalFilter::create(Blueprint &blueprint, uint32_t docid_limit, ThreadBundle &thread_bundle, Trace *trace)
 {
-    int32_t profile_depth = (trace && trace->getLevel() > 0) ? trace->match_profile_depth() : 0;
     uint32_t num_threads = thread_bundle.size();
     std::vector<MakePart> parts;
     parts.reserve(num_threads);
@@ -200,13 +211,13 @@ GlobalFilter::create(Blueprint &blueprint, uint32_t docid_limit, ThreadBundle &t
     uint32_t rest_docs = (docid_limit - docid) % num_threads;
     while (docid < docid_limit) {
         uint32_t part_size = per_thread + (parts.size() < rest_docs);
-        parts.emplace_back(blueprint, docid, docid + part_size, profile_depth);
+        parts.emplace_back(blueprint, docid, docid + part_size, trace);
         docid += part_size;
     }
     assert(parts.size() <= num_threads);
     assert((docid == docid_limit) || parts.empty());
     thread_bundle.run(parts);
-    maybe_insert_profiler_results(trace, profile_depth, parts);
+    insert_traces(trace, parts);
     std::vector<std::unique_ptr<BitVector>> vectors;
     vectors.reserve(parts.size());
     for (MakePart &part: parts) {