diff options
11 files changed, 229 insertions, 64 deletions
diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp b/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp index 4450b34296b..3a43e9a118e 100644 --- a/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp +++ b/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp @@ -24,20 +24,7 @@ using vespalib::Issue; namespace { -struct LazyThreadTraceInserter { - search::engine::Trace &root_trace; - std::unique_ptr<vespalib::slime::Inserter> inserter; - LazyThreadTraceInserter(search::engine::Trace &root_trace_in) - : root_trace(root_trace_in), inserter() {} - void handle(const search::engine::Trace &thread_trace) { - if (thread_trace.hasTrace()) { - if (!inserter) { - inserter = std::make_unique<vespalib::slime::ArrayInserter>(root_trace.createCursor("query_execution").setArray("threads")); - } - vespalib::slime::inject(thread_trace.getRoot(), *inserter); - } - } -}; +using namespace vespalib::literals; struct TimedMatchLoopCommunicator final : IMatchLoopCommunicator { IMatchLoopCommunicator &communicator; @@ -116,12 +103,12 @@ MatchMaster::match(search::engine::Trace & trace, double query_time_s = vespalib::to_s(query_latency_time.elapsed()); double rerank_time_s = vespalib::to_s(timedCommunicator.elapsed); double match_time_s = 0.0; - LazyThreadTraceInserter inserter(trace); + auto inserter = trace.make_inserter("query_execution"_ssv); for (size_t i = 0; i < threadState.size(); ++i) { const MatchThread & matchThread = *threadState[i]; match_time_s = std::max(match_time_s, matchThread.get_match_time()); _stats.merge_partition(matchThread.get_thread_stats(), i); - inserter.handle(matchThread.getTrace()); + inserter.handle_thread(matchThread.getTrace()); matchThread.get_issues().for_each_message([](const auto &msg){ Issue::report(Issue(msg)); }); } _stats.queryLatency(query_time_s); diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp b/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp index 620e4f1ff1d..acbd069aac7 100644 --- a/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp +++ b/searchcore/src/vespa/searchcore/proton/matching/match_thread.cpp @@ -420,15 +420,12 @@ MatchThread::MatchThread(size_t thread_id_in, match_time_s(0.0), wait_time_s(0.0), match_with_ranking(mtf.has_first_phase_rank() && mp.save_rank_scores()), - trace(std::make_unique<Trace>(parent_trace.getRelativeTime(), parent_trace.getLevel())), + trace(parent_trace.make_trace_up()), match_profiler(), first_phase_profiler(), second_phase_profiler(), my_issues() { - trace->match_profile_depth(parent_trace.match_profile_depth()); - trace->first_phase_profile_depth(parent_trace.first_phase_profile_depth()); - trace->second_phase_profile_depth(parent_trace.second_phase_profile_depth()); if (trace->getLevel() > 0) { if (int32_t depth = trace->match_profile_depth(); depth != 0) { match_profiler = std::make_unique<vespalib::ExecutionProfiler>(depth); diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp b/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp index 834e256c18f..ef9606f96a8 100644 --- a/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp +++ b/searchcore/src/vespa/searchcore/proton/matching/match_tools.cpp @@ -36,6 +36,8 @@ using search::fef::Properties; using search::fef::RankSetup; using search::fef::IIndexEnvironment; +using namespace vespalib::literals; + bool contains_all(const HandleRecorder::HandleMap &old_map, const HandleRecorder::HandleMap &new_map) { @@ -187,10 +189,7 @@ MatchToolsFactory(QueryLimiter & queryLimiter, _diversityParams(), _valid(false) { - search::engine::Trace trace(root_trace.getRelativeTime(), root_trace.getLevel()); - trace.match_profile_depth(root_trace.match_profile_depth()); - trace.first_phase_profile_depth(root_trace.first_phase_profile_depth()); - trace.second_phase_profile_depth(root_trace.second_phase_profile_depth()); + auto trace = root_trace.make_trace(); trace.addEvent(4, "Start query setup"); _query.setWhiteListBlueprint(metaStore.createWhiteListBlueprint()); trace.addEvent(5, "Deserialize and build query tree"); @@ -231,10 +230,7 @@ MatchToolsFactory(QueryLimiter & queryLimiter, _match_limiter = std::make_unique<NoMatchPhaseLimiter>(); } trace.addEvent(4, "Complete query setup"); - if (trace.hasTrace()) { - vespalib::slime::ObjectInserter inserter(root_trace.createCursor("query_setup"), "traces"); - vespalib::slime::inject(trace.getTraces(), inserter); - } + root_trace.make_inserter("query_setup"_ssv).handle_nested(trace); } MatchToolsFactory::~MatchToolsFactory() = default; 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) { diff --git a/vespalib/CMakeLists.txt b/vespalib/CMakeLists.txt index 76308260578..2720d8786cb 100644 --- a/vespalib/CMakeLists.txt +++ b/vespalib/CMakeLists.txt @@ -200,6 +200,7 @@ vespa_define_module( src/tests/util/mmap_file_allocator_factory src/tests/util/rcuvector src/tests/util/size_literals + src/tests/util/static_string src/tests/util/string_escape src/tests/valgrind src/tests/visit_ranges diff --git a/vespalib/src/tests/util/static_string/CMakeLists.txt b/vespalib/src/tests/util/static_string/CMakeLists.txt new file mode 100644 index 00000000000..14360470b6b --- /dev/null +++ b/vespalib/src/tests/util/static_string/CMakeLists.txt @@ -0,0 +1,9 @@ +# Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +vespa_add_executable(vespalib_static_string_test_app TEST + SOURCES + static_string_test.cpp + DEPENDS + vespalib + GTest::GTest +) +vespa_add_test(NAME vespalib_static_string_test_app COMMAND vespalib_static_string_test_app) diff --git a/vespalib/src/tests/util/static_string/static_string_test.cpp b/vespalib/src/tests/util/static_string/static_string_test.cpp new file mode 100644 index 00000000000..d91fb613f0a --- /dev/null +++ b/vespalib/src/tests/util/static_string/static_string_test.cpp @@ -0,0 +1,34 @@ +// Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +#include <vespa/vespalib/util/static_string.h> +#include <vespa/vespalib/gtest/gtest.h> + +using vespalib::StaticStringView; +using namespace vespalib::literals; + +TEST(StaticStringViewTest, simple_usage) { + auto value = "foo bar"_ssv; + vespalib::string expect("foo bar"); + std::string expect_std("foo bar"); + static_assert(std::same_as<decltype(value),StaticStringView>); + auto a_ref = value.ref(); + auto a_view = value.view(); + static_assert(std::same_as<decltype(a_ref),vespalib::stringref>); + static_assert(std::same_as<decltype(a_view),std::string_view>); + vespalib::stringref ref = value; + std::string_view view = value; + EXPECT_EQ(a_ref, expect); + EXPECT_EQ(a_view, expect_std); + EXPECT_EQ(ref, expect); + EXPECT_EQ(view, expect_std); + EXPECT_EQ(value.ref(), expect); + EXPECT_EQ(value.view(), expect_std); +} + +TEST(StaticStringViewTest, with_null_byte) { + auto value = "foo\0bar"_ssv; + std::string expect("foo\0bar", 7); + EXPECT_EQ(value.view(), expect); +} + +GTEST_MAIN_RUN_ALL_TESTS() diff --git a/vespalib/src/vespa/vespalib/util/static_string.h b/vespalib/src/vespa/vespalib/util/static_string.h new file mode 100644 index 00000000000..570c49a127b --- /dev/null +++ b/vespalib/src/vespa/vespalib/util/static_string.h @@ -0,0 +1,37 @@ +// Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +#pragma once + +#include <string_view> +#include <vespa/vespalib/stllike/string.h> + +namespace vespalib { + +class StaticStringView; +namespace literals { +constexpr StaticStringView operator "" _ssv(const char *literal, size_t size); +} // literals + +/** + * Contains the view of a literal string + **/ +class StaticStringView { +private: + std::string_view _view; + friend constexpr StaticStringView literals::operator "" _ssv(const char *, size_t); + constexpr StaticStringView(const char *literal, size_t size) noexcept + : _view(literal, size) {} +public: + constexpr std::string_view view() const noexcept { return _view; } + constexpr operator std::string_view() const noexcept { return _view; } + vespalib::stringref ref() const noexcept { return {_view.data(), _view.size()}; } + operator vespalib::stringref() const noexcept { return ref(); } +}; + +namespace literals { +constexpr StaticStringView operator "" _ssv(const char *literal, size_t size) { + return vespalib::StaticStringView(literal, size); +} +} // literals + +} // vespalib |