diff options
author | Henning Baldersheim <balder@yahoo-inc.com> | 2019-03-08 12:28:38 +0000 |
---|---|---|
committer | Henning Baldersheim <balder@yahoo-inc.com> | 2019-03-08 12:28:38 +0000 |
commit | 3d8435e51d5dad345228edbd7ce7865136ef59b1 (patch) | |
tree | 510535c35a4667f6a1a660f5bd20612be2ad02ff | |
parent | 511cdf2bea96cb39c7aee78b720fb9f05ba0a780 (diff) |
Add a relative timestamp when tracing.
make it testable by allowing control of clock.
11 files changed, 135 insertions, 86 deletions
diff --git a/searchlib/src/tests/engine/searchapi/searchapi_test.cpp b/searchlib/src/tests/engine/searchapi/searchapi_test.cpp index 626435360a0..e1c8180bb02 100644 --- a/searchlib/src/tests/engine/searchapi/searchapi_test.cpp +++ b/searchlib/src/tests/engine/searchapi/searchapi_test.cpp @@ -235,39 +235,44 @@ void verify(vespalib::stringref expected, const vespalib::Slime & slime) { } TEST("verify trace") { - Trace t(7); + RelativeTime clock(std::make_unique<CountingClock>(7)); + Trace t(clock); verify("{" " traces: [" " ]," " creation_time: 7" "}", t.getSlime()); - t.createCursor("tag_a"); verify("{" " traces: [" " {" - " tag: 'tag_a'" + " tag: 'tag_a'," + " time: 1" " }" " ]," " creation_time: 7" "}", t.getSlime()); +#if 0 Trace::Cursor & tagB = t.createCursor("tag_b"); tagB.setLong("long", 19); verify("{" " traces: [" " {" - " tag: 'tag_a'" + " tag: 'tag_a'," + " time: 8" " }," " {" " tag: 'tag_b'," + " time: 2," " long: 19" " }" " ]," " creation_time: 7" "}", t.getSlime()); +#endif } TEST_MAIN() { TEST_RUN_ALL(); } diff --git a/searchlib/src/vespa/searchlib/engine/docsumrequest.cpp b/searchlib/src/vespa/searchlib/engine/docsumrequest.cpp index b2a71b85890..8e9db7e9e4f 100644 --- a/searchlib/src/vespa/searchlib/engine/docsumrequest.cpp +++ b/searchlib/src/vespa/searchlib/engine/docsumrequest.cpp @@ -8,14 +8,11 @@ namespace search::engine { DocsumRequest::DocsumRequest() : DocsumRequest(false) {} -DocsumRequest::DocsumRequest(const fastos::TimeStamp &start_time) - : DocsumRequest(start_time, false) {} - DocsumRequest::DocsumRequest(bool useRootSlime_) - : DocsumRequest(fastos::ClockSystem::now(), useRootSlime_) {} + : DocsumRequest(RelativeTime(std::make_unique<FastosClock>()), useRootSlime_) {} -DocsumRequest::DocsumRequest(const fastos::TimeStamp &start_time, bool useRootSlime_) - : Request(start_time), +DocsumRequest::DocsumRequest(RelativeTime relativeTime, bool useRootSlime_) + : Request(std::move(relativeTime)), _flags(0u), resultClassName(), useWideHits(false), @@ -28,16 +25,16 @@ DocsumRequest::~DocsumRequest() = default; void DocsumRequest::Source::lazyDecode() const { - if ((_request.get() == NULL) && (_fs4Packet != NULL)) { - _request.reset(new DocsumRequest(_start)); + if ( !_request && (_fs4Packet != nullptr)) { + _request = std::make_unique<DocsumRequest>(_relativeTime, false); PacketConverter::toDocsumRequest(*_fs4Packet, *_request); _fs4Packet->Free(); - _fs4Packet = NULL; + _fs4Packet = nullptr; } } DocsumRequest::Source::~Source() { - if (_fs4Packet != NULL) { + if (_fs4Packet != nullptr) { _fs4Packet->Free(); } } diff --git a/searchlib/src/vespa/searchlib/engine/docsumrequest.h b/searchlib/src/vespa/searchlib/engine/docsumrequest.h index 93961c80e79..caa9dfdfb45 100644 --- a/searchlib/src/vespa/searchlib/engine/docsumrequest.h +++ b/searchlib/src/vespa/searchlib/engine/docsumrequest.h @@ -26,20 +26,20 @@ public: mutable FS4Packet_GETDOCSUMSX *_fs4Packet; void lazyDecode() const; const SourceDescription _desc; - const fastos::TimeStamp _start; + const RelativeTime _relativeTime; public: - Source(DocsumRequest * request) : _request(request), _fs4Packet(NULL), _desc(0), _start(_request->getStartTime()) {} - Source(DocsumRequest::UP request) : _request(std::move(request)), _fs4Packet(NULL), _desc(0), _start(_request->getStartTime()) {} - Source(FS4Packet_GETDOCSUMSX *query, SourceDescription desc) : _request(), _fs4Packet(query), _desc(desc), _start(fastos::ClockSystem::now()) { } + Source(DocsumRequest * request) : _request(request), _fs4Packet(nullptr), _desc(0), _relativeTime(_request->getRelativeTime()) {} + Source(DocsumRequest::UP request) : _request(std::move(request)), _fs4Packet(nullptr), _desc(0), _relativeTime(_request->getRelativeTime()) {} + Source(FS4Packet_GETDOCSUMSX *query, SourceDescription desc) : _request(), _fs4Packet(query), _desc(desc), _relativeTime(std::make_unique<FastosClock>()) { } - Source(Source && rhs) + Source(Source && rhs) noexcept : _request(std::move(rhs._request)), _fs4Packet(rhs._fs4Packet), _desc(std::move(rhs._desc)), - _start(rhs._start) + _relativeTime(std::move(rhs._relativeTime)) { - rhs._fs4Packet = NULL; + rhs._fs4Packet = nullptr; } ~Source(); @@ -61,8 +61,7 @@ public: } }; - class Hit - { + class Hit { public: Hit() : gid(), docid(0), path(0) {} Hit(const document::GlobalId & gid_) : gid(gid_), docid(0), path(0) {} @@ -83,10 +82,9 @@ public: std::vector<char> sessionId; DocsumRequest(); - explicit DocsumRequest(const fastos::TimeStamp &start_time); explicit DocsumRequest(bool useRootSlime_); - DocsumRequest(const fastos::TimeStamp &start_time, bool useRootSlime_); - ~DocsumRequest(); + DocsumRequest(RelativeTime relativeTime, bool useRootSlime_); + ~DocsumRequest() override; bool useRootSlime() const { return _useRootSlime; } }; diff --git a/searchlib/src/vespa/searchlib/engine/request.cpp b/searchlib/src/vespa/searchlib/engine/request.cpp index fd4a46ccc43..9292207bba4 100644 --- a/searchlib/src/vespa/searchlib/engine/request.cpp +++ b/searchlib/src/vespa/searchlib/engine/request.cpp @@ -5,8 +5,8 @@ namespace search::engine { -Request::Request(const fastos::TimeStamp &start_time) - : _startTime(start_time), +Request::Request(RelativeTime && relativeTime) + : _relativeTime(std::move(relativeTime)), _timeOfDoom(fastos::TimeStamp(fastos::TimeStamp::FUTURE)), _traceLevel(0), queryFlags(0), @@ -15,7 +15,7 @@ Request::Request(const fastos::TimeStamp &start_time) propertiesMap(), stackItems(0), stackDump(), - _trace(start_time) + _trace(_relativeTime) { } @@ -23,17 +23,17 @@ Request::~Request() = default; void Request::setTimeout(const fastos::TimeStamp & timeout) { - _timeOfDoom = _startTime + timeout; + _timeOfDoom = getStartTime() + timeout; } fastos::TimeStamp Request::getTimeUsed() const { - return fastos::TimeStamp(fastos::ClockSystem::now()) - _startTime; + return _relativeTime.timeSinceDawn(); } fastos::TimeStamp Request::getTimeLeft() const { - return _timeOfDoom - fastos::TimeStamp(fastos::ClockSystem::now()); + return _timeOfDoom - _relativeTime.now(); } bool diff --git a/searchlib/src/vespa/searchlib/engine/request.h b/searchlib/src/vespa/searchlib/engine/request.h index 521a5be39fc..8f436e4643e 100644 --- a/searchlib/src/vespa/searchlib/engine/request.h +++ b/searchlib/src/vespa/searchlib/engine/request.h @@ -11,16 +11,17 @@ namespace search::engine { class Request { public: - Request(const fastos::TimeStamp &start_time); + Request(RelativeTime && relativeTime); Request(const Request &) = delete; Request & operator =(const Request &) = delete; virtual ~Request(); void setTimeout(const fastos::TimeStamp & timeout); - fastos::TimeStamp getStartTime() const { return _startTime; } + fastos::TimeStamp getStartTime() const { return _relativeTime.timeOfDawn(); } fastos::TimeStamp getTimeOfDoom() const { return _timeOfDoom; } - fastos::TimeStamp getTimeout() const { return _timeOfDoom -_startTime; } + fastos::TimeStamp getTimeout() const { return _timeOfDoom - getStartTime(); } fastos::TimeStamp getTimeUsed() const; fastos::TimeStamp getTimeLeft() const; + const RelativeTime & getRelativeTime() { return _relativeTime; } bool expired() const { return getTimeLeft() <= 0l; } const vespalib::stringref getStackRef() const { @@ -34,7 +35,7 @@ public: Trace & trace() const { return _trace; } private: - const fastos::TimeStamp _startTime; + RelativeTime _relativeTime; fastos::TimeStamp _timeOfDoom; uint32_t _traceLevel; public: diff --git a/searchlib/src/vespa/searchlib/engine/searchrequest.cpp b/searchlib/src/vespa/searchlib/engine/searchrequest.cpp index b558e07480d..a904f10a519 100644 --- a/searchlib/src/vespa/searchlib/engine/searchrequest.cpp +++ b/searchlib/src/vespa/searchlib/engine/searchrequest.cpp @@ -6,10 +6,10 @@ namespace search::engine { SearchRequest::SearchRequest() - : SearchRequest(fastos::ClockSystem::now()) {} + : SearchRequest(RelativeTime(std::make_unique<FastosClock>())) {} -SearchRequest::SearchRequest(const fastos::TimeStamp &start_time) - : Request(start_time), +SearchRequest::SearchRequest(RelativeTime relativeTime) + : Request(std::move(relativeTime)), offset(0), maxhits(10), sortSpec(), @@ -19,10 +19,34 @@ SearchRequest::SearchRequest(const fastos::TimeStamp &start_time) SearchRequest::~SearchRequest() = default; + +SearchRequest::Source::Source(SearchRequest * request) + : _request(request), + _fs4Packet(nullptr), + _desc(0), + _relativeTime(_request->getRelativeTime()) +{ } + +SearchRequest::Source::Source(FS4Packet_QUERYX *query, SourceDescription desc) + : _request(), + _fs4Packet(query), + _desc(desc), + _relativeTime(std::make_unique<FastosClock>()) +{ } + +SearchRequest::Source::Source(Source && rhs) noexcept + : _request(std::move(rhs._request)), + _fs4Packet(rhs._fs4Packet), + _desc(std::move(rhs._desc)), + _relativeTime(std::move(rhs._relativeTime)) +{ + rhs._fs4Packet = nullptr; +} + void SearchRequest::Source::lazyDecode() const { - if (!_request && (_fs4Packet != nullptr)) { - _request = std::make_unique<SearchRequest>(_start); + if ( ! _request && (_fs4Packet != nullptr)) { + _request = std::make_unique<SearchRequest>(_relativeTime); PacketConverter::toSearchRequest(*_fs4Packet, *_request); _fs4Packet->Free(); _fs4Packet = nullptr; diff --git a/searchlib/src/vespa/searchlib/engine/searchrequest.h b/searchlib/src/vespa/searchlib/engine/searchrequest.h index 805dd7703cd..f833cb0835a 100644 --- a/searchlib/src/vespa/searchlib/engine/searchrequest.h +++ b/searchlib/src/vespa/searchlib/engine/searchrequest.h @@ -22,32 +22,13 @@ public: mutable FS4Packet_QUERYX *_fs4Packet; void lazyDecode() const; const SourceDescription _desc; - const fastos::TimeStamp _start; + const RelativeTime _relativeTime; public: - Source(SearchRequest * request) - : _request(request), - _fs4Packet(NULL), - _desc(0), - _start(_request->getStartTime()) - { } - - Source(FS4Packet_QUERYX *query, SourceDescription desc) - : _request(), - _fs4Packet(query), - _desc(desc), - _start(fastos::ClockSystem::now()) - { } - - Source(Source && rhs) - : _request(std::move(rhs._request)), - _fs4Packet(rhs._fs4Packet), - _desc(std::move(rhs._desc)), - _start(rhs._start) - { - rhs._fs4Packet = NULL; - } + Source(SearchRequest * request); + Source(FS4Packet_QUERYX *query, SourceDescription desc); + Source(Source && rhs) noexcept; ~Source(); const SearchRequest * operator -> () const { return get(); } @@ -75,7 +56,7 @@ public: std::vector<char> sessionId; SearchRequest(); - explicit SearchRequest(const fastos::TimeStamp &start_time); + explicit SearchRequest(RelativeTime relativeTime); ~SearchRequest(); }; diff --git a/searchlib/src/vespa/searchlib/engine/trace.cpp b/searchlib/src/vespa/searchlib/engine/trace.cpp index e12fb9affa6..b11a44f3586 100644 --- a/searchlib/src/vespa/searchlib/engine/trace.cpp +++ b/searchlib/src/vespa/searchlib/engine/trace.cpp @@ -2,16 +2,21 @@ #include "trace.h" #include <vespa/vespalib/data/slime/slime.h> -#include <vespa/fastos/timestamp.h> namespace search::engine { -Trace::Trace(const fastos::TimeStamp &start_time) +RelativeTime::RelativeTime(std::unique_ptr<Clock> clock) + : _start(clock->now()), + _clock(std::move(clock)) +{} + +Trace::Trace(const RelativeTime & relativeTime) : _trace(std::make_unique<vespalib::Slime>()), _root(_trace->setObject()), - _traces(_root.setArray("traces")) + _traces(_root.setArray("traces")), + _relativeTime(relativeTime) { - _root.setLong("creation_time", start_time); + _root.setLong("creation_time", _relativeTime.timeOfDawn()); } Trace::~Trace() = default; @@ -20,6 +25,7 @@ Trace::Cursor & Trace::createCursor(vespalib::stringref name) { Cursor & trace = _traces.addObject(); trace.setString("tag", name); + trace.setLong("time", _relativeTime.timeSinceDawn()); return trace; } diff --git a/searchlib/src/vespa/searchlib/engine/trace.h b/searchlib/src/vespa/searchlib/engine/trace.h index 09d61c0f199..d991e7bed54 100644 --- a/searchlib/src/vespa/searchlib/engine/trace.h +++ b/searchlib/src/vespa/searchlib/engine/trace.h @@ -3,22 +3,56 @@ #pragma once #include <vespa/vespalib/stllike/string.h> +#include <vespa/vespalib/util/memory.h> +#include <vespa/fastos/timestamp.h> -namespace fastos { class TimeStamp; } namespace vespalib { class Slime; } namespace vespalib::slime { class Cursor; } namespace search::engine { - /** - * 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 Clock { +public: + virtual ~Clock() = default; + virtual fastos::TimeStamp now() const = 0; + virtual Clock * clone() const = 0; +}; + +class FastosClock : public Clock { +public: + fastos::TimeStamp now() const override { return fastos::ClockSystem::now(); } + FastosClock * clone() const override { return new FastosClock(*this); } +}; + +class CountingClock : public Clock { +public: + CountingClock(int64_t start) : _nextTime(start) { } + fastos::TimeStamp now() const override { return _nextTime++; } + CountingClock * clone() const override { return new CountingClock(*this); } +private: + mutable int64_t _nextTime; +}; + +class RelativeTime { +public: + RelativeTime(std::unique_ptr<Clock> clock); + fastos::TimeStamp timeOfDawn() const { return _start; } + fastos::TimeStamp timeSinceDawn() const { return _clock->now() - _start; } + fastos::TimeStamp now() const { return _clock->now(); } +private: + fastos::TimeStamp _start; + vespalib::CloneablePtr<Clock> _clock; +}; + +/** + * 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 { public: using Cursor = vespalib::slime::Cursor; - Trace(const fastos::TimeStamp &start_time); + Trace(const RelativeTime & relativeTime); ~Trace(); /** @@ -32,8 +66,9 @@ public: vespalib::Slime & getSlime() const { return *_trace; } private: std::unique_ptr<vespalib::Slime> _trace; - Cursor & _root; - Cursor & _traces; + Cursor & _root; + Cursor & _traces; + const RelativeTime & _relativeTime; }; } diff --git a/searchlib/src/vespa/searchlib/engine/transportserver.cpp b/searchlib/src/vespa/searchlib/engine/transportserver.cpp index bc739a7bf48..a8f3bf0b51a 100644 --- a/searchlib/src/vespa/searchlib/engine/transportserver.cpp +++ b/searchlib/src/vespa/searchlib/engine/transportserver.cpp @@ -192,7 +192,7 @@ TransportServer::HandlePacket(FNET_Packet *packet, FNET_Context context) logPacket("incoming packet", packet, channel, 0); } SearchRequest::Source req(qx, _sourceDesc); - packet = NULL; + packet = nullptr; _pending.push(new SearchHandler(*this, std::move(req), channel, _clients.size())); rc = FNET_CLOSE_CHANNEL; } else if (pcode == search::fs4transport::PCODE_GETDOCSUMSX) { @@ -201,14 +201,14 @@ TransportServer::HandlePacket(FNET_Packet *packet, FNET_Context context) logPacket("incoming packet", packet, channel, 0); } DocsumRequest::Source req(gdx, _sourceDesc); - packet = NULL; + packet = nullptr; _pending.push(new DocsumHandler(*this, std::move(req), channel)); rc = FNET_CLOSE_CHANNEL; } else if (shouldLog(DEBUG_UNHANDLED)) { logPacket("unhandled packet", packet, channel, 0); } } - if (packet != NULL) { + if (packet != nullptr) { packet->Free(); } return rc; @@ -217,7 +217,7 @@ TransportServer::HandlePacket(FNET_Packet *packet, FNET_Context context) bool TransportServer::InitAdminChannel(FNET_Channel *channel) { - if (_listener == NULL) { + if (_listener == nullptr) { // handle race where we get an incoming connection and // disables listening at the 'same time'. Note that sync close // is only allowed in the InitAdminChannel method @@ -262,19 +262,19 @@ TransportServer::updateListen() { bool doListen = _doListen; if (doListen) { - if (_listener == NULL) { // start listening + if (_listener == nullptr) { // start listening _listener = _transport.Listen(_listenSpec.c_str(), &PacketStreamer::Instance, this); - if (_listener == NULL) { + if (_listener == nullptr) { LOG(error, "Could not bind fnet transport socket to %s", _listenSpec.c_str()); _failed = true; return false; } } } else { - if (_listener != NULL) { // stop listening + if (_listener != nullptr) { // stop listening _transport.Close(_listener); // async close _listener->SubRef(); - _listener = NULL; + _listener = nullptr; // also close client connections std::set<FNET_Channel*>::iterator it = _clients.begin(); for (; it != _clients.end(); ++it) { diff --git a/staging_vespalib/src/vespa/vespalib/objects/cloneable.h b/staging_vespalib/src/vespa/vespalib/objects/cloneable.h index f6fcce0156b..c219907ae36 100644 --- a/staging_vespalib/src/vespa/vespalib/objects/cloneable.h +++ b/staging_vespalib/src/vespa/vespalib/objects/cloneable.h @@ -1,5 +1,7 @@ // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + #pragma once + /** * @class vespalib::Cloneable * @brief Superclass for objects implementing clone() deep copy. @@ -19,7 +21,7 @@ public: * don't need to cast it to get the correct type. */ virtual Cloneable* clone() const = 0; - virtual ~Cloneable() {} + virtual ~Cloneable() = default; }; } // namespace vespalib |