diff options
8 files changed, 73 insertions, 35 deletions
diff --git a/searchcore/src/tests/proton/matching/match_phase_limiter/match_phase_limiter_test.cpp b/searchcore/src/tests/proton/matching/match_phase_limiter/match_phase_limiter_test.cpp index be4bc159b1b..d05abac203e 100644 --- a/searchcore/src/tests/proton/matching/match_phase_limiter/match_phase_limiter_test.cpp +++ b/searchcore/src/tests/proton/matching/match_phase_limiter/match_phase_limiter_test.cpp @@ -291,6 +291,7 @@ TEST("require that the match phase limiter is able to pre-limit the query") { EXPECT_EQUAL(12u, limiter.sample_hits_per_thread(10)); RelativeTime clock(std::make_unique<CountingClock>(fastos::TimeStamp::fromSec(1500000000), 1700000L)); Trace trace(clock, 7); + trace.start(4); SearchIterator::UP search = limiter.maybe_limit(prepare(new MockSearch("search")), 0.1, 100000, trace.maybeCreateCursor(7, "limit")); limiter.updateDocIdSpaceEstimate(1000, 9000); EXPECT_EQUAL(1680u, limiter.getDocIdSpaceEstimate()); @@ -331,7 +332,7 @@ TEST("require that the match phase limiter is able to pre-limit the query") { " }" " ]," " duration_ms: 3.4" - "}", trace.getSlime()); + "}", *trace.getSlime()); } TEST("require that the match phase limiter is able to post-limit the query") { diff --git a/searchcore/src/vespa/searchcore/proton/matchengine/matchengine.cpp b/searchcore/src/vespa/searchcore/proton/matchengine/matchengine.cpp index c7016d711cb..f887b5069cb 100644 --- a/searchcore/src/vespa/searchcore/proton/matchengine/matchengine.cpp +++ b/searchcore/src/vespa/searchcore/proton/matchengine/matchengine.cpp @@ -141,11 +141,11 @@ MatchEngine::performSearch(search::engine::SearchRequest::Source req, ret->request = req.release(); ret->setDistributionKey(_distributionKey); if (ret->request->trace().getLevel() > 0) { - ret->request->trace().getRoot().setLong("distribution-key", _distributionKey); + ret->request->trace().getRoot()->setLong("distribution-key", _distributionKey); ret->request->trace().done(); search::fef::Properties & trace = ret->propertiesMap.lookupCreate("trace"); vespalib::SmartBuffer output(4096); - vespalib::slime::BinaryFormat::encode(ret->request->trace().getSlime(), output); + vespalib::slime::BinaryFormat::encode(*ret->request->trace().getSlime(), output); trace.add("slime", output.obtain().make_stringref()); } client.searchDone(std::move(ret)); diff --git a/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp b/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp index 7dd06038707..ed8900e0cac 100644 --- a/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp +++ b/searchcore/src/vespa/searchcore/proton/matching/match_master.cpp @@ -99,8 +99,8 @@ MatchMaster::match(search::engine::Trace & trace, 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); - if (inserter) { - vespalib::slime::inject(matchThread.getTrace().getRoot(), *inserter); + if (inserter && matchThread.getTrace().getRoot()) { + vespalib::slime::inject(*matchThread.getTrace().getRoot(), *inserter); } } _stats.queryLatency(query_time_s); diff --git a/searchlib/src/tests/engine/searchapi/searchapi_test.cpp b/searchlib/src/tests/engine/searchapi/searchapi_test.cpp index 2f2cf4f22e5..28c90dd18ca 100644 --- a/searchlib/src/tests/engine/searchapi/searchapi_test.cpp +++ b/searchlib/src/tests/engine/searchapi/searchapi_test.cpp @@ -228,36 +228,37 @@ TEST("convertFromReply") { } } -void verify(vespalib::stringref expected, const vespalib::Slime & slime) { +void verify(vespalib::stringref expected, const vespalib::Slime * slime) { vespalib::Slime expectedSlime; vespalib::slime::JsonFormat::decode(expected, expectedSlime); - EXPECT_EQUAL(expectedSlime, slime); + if (slime) { + EXPECT_EQUAL(expectedSlime, *slime); + } else { + EXPECT_TRUE(expected.empty()); + } } TEST("verify trace") { RelativeTime clock(std::make_unique<CountingClock>(fastos::TimeStamp::fromSec(1500000000), 1700000L)); Trace t(clock); - verify("{" - " traces: [" - " ]," - " start_time_utc: '2017-07-14 02:40:00.000 UTC'" - "}", - t.getSlime()); + verify("", t.getSlime()); + t.start(0); t.createCursor("tag_a"); verify("{" + " start_time_utc: '2017-07-14 02:40:00.000 UTC'," " traces: [" " {" " tag: 'tag_a'," " timestamp_ms: 1.7" " }" - " ]," - " start_time_utc: '2017-07-14 02:40:00.000 UTC'" + " ]" "}", t.getSlime()); Trace::Cursor & tagB = t.createCursor("tag_b"); tagB.setLong("long", 19); t.done(); verify("{" + " start_time_utc: '2017-07-14 02:40:00.000 UTC'," " traces: [" " {" " tag: 'tag_a'," @@ -269,7 +270,6 @@ TEST("verify trace") { " long: 19" " }" " ]," - " start_time_utc: '2017-07-14 02:40:00.000 UTC'," " duration_ms: 5.1" "}", t.getSlime()); diff --git a/searchlib/src/vespa/searchlib/engine/packetconverter.cpp b/searchlib/src/vespa/searchlib/engine/packetconverter.cpp index c35ce9ded05..b7ebab79e47 100644 --- a/searchlib/src/vespa/searchlib/engine/packetconverter.cpp +++ b/searchlib/src/vespa/searchlib/engine/packetconverter.cpp @@ -74,7 +74,8 @@ PacketConverter::toSearchRequest(const QUERYX &packet, SearchRequest &request) request.location = packet._location; request.stackItems = packet._numStackItems; request.stackDump.assign( packet._stackDump.begin(), packet._stackDump.end()); - request.setTraceLevel(search::fef::indexproperties::trace::Level::lookup(request.propertiesMap.modelOverrides())); + // 3 is the minimum level required for backend tracing. + request.setTraceLevel(search::fef::indexproperties::trace::Level::lookup(request.propertiesMap.modelOverrides()), 3); } void diff --git a/searchlib/src/vespa/searchlib/engine/request.h b/searchlib/src/vespa/searchlib/engine/request.h index 733043b0e4e..05f6901d2e4 100644 --- a/searchlib/src/vespa/searchlib/engine/request.h +++ b/searchlib/src/vespa/searchlib/engine/request.h @@ -30,7 +30,11 @@ public: bool should_drop_sort_data() const; - Request & setTraceLevel(uint32_t level) { _trace.setLevel(level); return *this; } + Request & setTraceLevel(uint32_t level, uint32_t minLevel) { + _trace.setLevel(level); + _trace.start(minLevel); + return *this; + } Trace & trace() const { return _trace; } private: diff --git a/searchlib/src/vespa/searchlib/engine/trace.cpp b/searchlib/src/vespa/searchlib/engine/trace.cpp index ba92902d2fd..c9e3a39daa4 100644 --- a/searchlib/src/vespa/searchlib/engine/trace.cpp +++ b/searchlib/src/vespa/searchlib/engine/trace.cpp @@ -10,30 +10,49 @@ RelativeTime::RelativeTime(std::unique_ptr<Clock> clock) _clock(std::move(clock)) {} -namespace { +void +Trace::constructObject() { + _trace = std::make_unique<vespalib::Slime>(); + _root = & _trace->setObject(); +} -Trace::Cursor & -createRoot(vespalib::Slime & slime, const RelativeTime & relativeTime) { - Trace::Cursor & root = slime.setObject(); - root.setString("start_time_utc", relativeTime.timeOfDawn().toString()); - return root; +void +Trace::constructTraces() { + _traces = &_root->setArray("traces"); } +void +Trace::lazyConstruct(uint32_t level) { + if (shouldTrace(level) && !_trace) { + constructObject(); + constructTraces(); + } } + Trace::Trace(const RelativeTime & relativeTime, uint32_t level) - : _trace(std::make_unique<vespalib::Slime>()), - _root(createRoot(*_trace, relativeTime)), - _traces(_root.setArray("traces")), + : _trace(), + _root(nullptr), + _traces(nullptr), _relativeTime(relativeTime), _level(level) { } +void +Trace::start(int level) { + if (shouldTrace(level) && !_trace) { + constructObject(); + _root->setString("start_time_utc", _relativeTime.timeOfDawn().toString()); + constructTraces(); + } +} + Trace::~Trace() = default; Trace::Cursor & Trace::createCursor(vespalib::stringref name) { - Cursor & trace = _traces.addObject(); + lazyConstruct(_level); + Cursor & trace = _traces->addObject(); addTimeStamp(trace); trace.setString("tag", name); return trace; @@ -41,6 +60,7 @@ Trace::createCursor(vespalib::stringref name) { Trace::Cursor * Trace::maybeCreateCursor(uint32_t level, vespalib::stringref name) { + lazyConstruct(level); return shouldTrace(level) ? & createCursor(name) : nullptr; } @@ -48,7 +68,8 @@ void Trace::addEvent(uint32_t level, vespalib::stringref event) { if (!shouldTrace(level)) { return; } - Cursor & trace = _traces.addObject(); + lazyConstruct(level); + Cursor & trace = _traces->addObject(); addTimeStamp(trace); trace.setString("event", event); } @@ -59,12 +80,14 @@ Trace::addTimeStamp(Cursor & trace) { } void Trace::done() { - _root.setDouble("duration_ms", _relativeTime.timeSinceDawn()/1000000.0); + if (!_root) { return; } + + _root->setDouble("duration_ms", _relativeTime.timeSinceDawn()/1000000.0); } vespalib::string Trace::toString() const { - return _trace->toString(); + return _trace ? _trace->toString() : ""; } } diff --git a/searchlib/src/vespa/searchlib/engine/trace.h b/searchlib/src/vespa/searchlib/engine/trace.h index 41f2c608615..78832733f71 100644 --- a/searchlib/src/vespa/searchlib/engine/trace.h +++ b/searchlib/src/vespa/searchlib/engine/trace.h @@ -57,6 +57,12 @@ public: ~Trace(); /** + * Will add start timestamp if level is high enough + * @param level + */ + void start(int level); + + /** * Will give you a trace entry. It will also add a timestamp relative to the creation of the trace. * @param name * @return a Cursor to use for further tracing. @@ -76,17 +82,20 @@ public: void done(); vespalib::string toString() const; - Cursor & getRoot() const { return _root; } - vespalib::Slime & getSlime() const { return *_trace; } + Cursor * getRoot() const { return _root; } + vespalib::Slime * getSlime() const { return _trace.get(); } bool shouldTrace(uint32_t level) const { return level <= _level; } uint32_t getLevel() const { return _level; } Trace & setLevel(uint32_t level) { _level = level; return *this; } const RelativeTime & getRelativeTime() const { return _relativeTime; } private: + void constructObject(); + void constructTraces(); + void lazyConstruct(uint32_t level); void addTimeStamp(Cursor & trace); std::unique_ptr<vespalib::Slime> _trace; - Cursor & _root; - Cursor & _traces; + Cursor * _root; + Cursor * _traces; const RelativeTime & _relativeTime; uint32_t _level; }; |