diff options
author | HÃ¥vard Pettersen <3535158+havardpe@users.noreply.github.com> | 2023-02-10 11:26:48 +0100 |
---|---|---|
committer | GitHub <noreply@github.com> | 2023-02-10 11:26:48 +0100 |
commit | 3d5e5a56b7aed8315726b203117a2b6bc2dd0d31 (patch) | |
tree | 684d2a8634f589b1c3439e6a179d59ce1e68acb9 /searchlib | |
parent | 6cafa7d885b5e0fe2ca7e33a786d0fa79d0e48ff (diff) | |
parent | 37391e9cb5b375a5a8c1c4acc21a10805cb2f5e0 (diff) |
Merge pull request #25967 from vespa-engine/havardpe/trace-global-filter-iterator-tree
trace global filter iterator tree
Diffstat (limited to 'searchlib')
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) { |