Add a relative timestamp when tracing.

make it testable by allowing control of clock.

10 files changed, 132 insertions, 85 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) {