Use system_time in trace instead of int64_t count of milliseconds.

14 files changed, 78 insertions, 55 deletions

diff --git a/config/src/tests/trace/trace.cpp b/config/src/tests/trace/trace.cpp
index 33e25fa7ba2..fdb40d40893 100644
--- a/config/src/tests/trace/trace.cpp
+++ b/config/src/tests/trace/trace.cpp
@@ -2,7 +2,6 @@
 
 #include <vespa/vespalib/testkit/test_kit.h>
 #include <vespa/config/common/trace.h>
-#include <vespa/vespalib/trace/tracenode.h>
 
 
 using namespace config;
@@ -11,9 +10,9 @@ using namespace vespalib::slime;
 
 struct FixedClock : public Clock
 {
-    FixedClock() : currentTime(0) { }
-    int64_t currentTime;
-    int64_t currentTimeMillis() const override { return currentTime; }
+    FixedClock() : _currentTime(duration::zero()) { }
+    vespalib::system_time _currentTime;
+    vespalib::system_time currentTime() const override { return _currentTime; }
 };
 
 TEST("that trace can be serialized and deserialized") {
@@ -38,7 +37,7 @@ TEST("that trace can be serialized and deserialized") {
 }
 
 TEST_F("that trace level is taken into account", FixedClock) {
-    f1.currentTime = 3;
+    f1._currentTime = vespalib::system_time(3ms);
     Trace trace(4, f1);
     trace.trace(4, "foo");
     trace.trace(5, "bar");
@@ -58,11 +57,13 @@ TEST("that trace can be copied") {
     EXPECT_EQUAL(trace.toString(), trace2.toString());
 }
 
+constexpr vespalib::system_time epoch(duration::zero());
+
 TEST("ensure that system clock is used by default") {
     Trace trace(2);
     trace.trace(1, "foo");
     TraceNode child(trace.getRoot().getChild(0));
-    EXPECT_TRUE(child.getTimestamp() > 0);
+    EXPECT_TRUE(child.getTimestamp() > epoch);
 }
 
 TEST_MAIN() { TEST_RUN_ALL(); }
diff --git a/config/src/vespa/config/common/trace.cpp b/config/src/vespa/config/common/trace.cpp
index e6183a9fec1..d1bb154eda9 100644
--- a/config/src/vespa/config/common/trace.cpp
+++ b/config/src/vespa/config/common/trace.cpp
@@ -2,7 +2,6 @@
 #include "trace.h"
 #include <vespa/vespalib/trace/slime_trace_serializer.h>
 #include <vespa/vespalib/trace/slime_trace_deserializer.h>
-#include <vespa/fastos/timestamp.h>
 
 using namespace vespalib;
 using namespace vespalib::slime;
@@ -11,8 +10,8 @@ namespace config {
 
 struct SystemClock : public Clock
 {
-    int64_t currentTimeMillis() const override {
-        return fastos::ClockSystem::now().timeSinceEpoch().ms();
+    vespalib::system_time currentTime() const override {
+        return vespalib::system_clock::now();
     }
 };
 
@@ -73,7 +72,7 @@ void
 Trace::trace(uint32_t level, const vespalib::string & message)
 {
     if (shouldTrace(level)) {
-        _root.addChild(message, _clock.currentTimeMillis());
+        _root.addChild(message, _clock.currentTime());
     }
 }
 
diff --git a/config/src/vespa/config/common/trace.h b/config/src/vespa/config/common/trace.h
index 9cfd2b1f88e..772cdb6f31e 100644
--- a/config/src/vespa/config/common/trace.h
+++ b/config/src/vespa/config/common/trace.h
@@ -12,7 +12,7 @@ namespace config {
  * Clock interface for acquiring time.
  */
 struct Clock {
-    virtual int64_t currentTimeMillis() const = 0;
+    virtual vespalib::system_time currentTime() const = 0;
     virtual ~Clock() {}
 };
 
diff --git a/searchcore/src/vespa/searchcore/proton/common/attribute_updater.cpp b/searchcore/src/vespa/searchcore/proton/common/attribute_updater.cpp
index fcca1c2a737..eaf76ebdc8f 100644
--- a/searchcore/src/vespa/searchcore/proton/common/attribute_updater.cpp
+++ b/searchcore/src/vespa/searchcore/proton/common/attribute_updater.cpp
@@ -22,7 +22,6 @@
 #include <vespa/searchlib/attribute/changevector.hpp>
 #include <vespa/searchlib/attribute/predicate_attribute.h>
 #include <vespa/searchlib/attribute/reference_attribute.h>
-#include <vespa/searchlib/common/base.h>
 #include <vespa/searchlib/tensor/tensor_attribute.h>
 #include <vespa/vespalib/util/stringfmt.h>
 #include <sstream>
diff --git a/storage/src/tests/visiting/memory_bounded_trace_test.cpp b/storage/src/tests/visiting/memory_bounded_trace_test.cpp
index 0cfd3dad4c3..124730cf093 100644
--- a/storage/src/tests/visiting/memory_bounded_trace_test.cpp
+++ b/storage/src/tests/visiting/memory_bounded_trace_test.cpp
@@ -7,6 +7,8 @@ using namespace ::testing;
 
 namespace storage {
 
+constexpr vespalib::system_time epoch(vespalib::duration::zero());
+
 TEST(MemoryBoundedTraceTest, no_memory_reported_used_when_empty) {
     MemoryBoundedTrace trace(100);
     EXPECT_EQ(0, trace.getApproxMemoryUsed());
@@ -14,7 +16,7 @@ TEST(MemoryBoundedTraceTest, no_memory_reported_used_when_empty) {
 
 TEST(MemoryBoundedTraceTest, memory_used_is_string_length_for_leaf_node) {
     MemoryBoundedTrace trace(100);
-    EXPECT_TRUE(trace.add(mbus::TraceNode("hello world", 0)));
+    EXPECT_TRUE(trace.add(mbus::TraceNode("hello world", epoch)));
     EXPECT_EQ(11, trace.getApproxMemoryUsed());
 }
 
@@ -29,7 +31,7 @@ TEST(MemoryBoundedTraceTest, memory_used_is_accumulated_recursively_for_non_leaf
 
 TEST(MemoryBoundedTraceTest, trace_nodes_can_be_moved_and_implicitly_cleared) {
     MemoryBoundedTrace trace(100);
-    EXPECT_TRUE(trace.add(mbus::TraceNode("hello world", 0)));
+    EXPECT_TRUE(trace.add(mbus::TraceNode("hello world", epoch)));
     mbus::TraceNode target;
     trace.moveTraceTo(target);
     EXPECT_EQ(1, target.getNumChildren());
@@ -49,7 +51,7 @@ TEST(MemoryBoundedTraceTest, trace_nodes_can_be_moved_and_implicitly_cleared) {
  */
 TEST(MemoryBoundedTraceTest, moved_trace_tree_is_marked_as_strict) {
     MemoryBoundedTrace trace(100);
-    EXPECT_TRUE(trace.add(mbus::TraceNode("hello world", 0)));
+    EXPECT_TRUE(trace.add(mbus::TraceNode("hello world", epoch)));
     mbus::TraceNode target;
     trace.moveTraceTo(target);
     EXPECT_EQ(1, target.getNumChildren());
@@ -60,11 +62,11 @@ TEST(MemoryBoundedTraceTest, can_not_add_more_nodes_when_memory_used_exceeds_upp
     // Note: we allow one complete node tree to exceed the bounds, but as soon
     // as the bound is exceeded no further nodes can be added.
     MemoryBoundedTrace trace(10);
-    EXPECT_TRUE(trace.add(mbus::TraceNode("hello world", 0)));
+    EXPECT_TRUE(trace.add(mbus::TraceNode("hello world", epoch)));
     EXPECT_EQ(11, trace.getApproxMemoryUsed());
 
     EXPECT_FALSE(trace.add(mbus::TraceNode("the quick red fox runs across "
-                                           "the freeway", 0)));
+                                           "the freeway", epoch)));
     EXPECT_EQ(11, trace.getApproxMemoryUsed());
 
     mbus::TraceNode target;
@@ -77,8 +79,8 @@ TEST(MemoryBoundedTraceTest, can_not_add_more_nodes_when_memory_used_exceeds_upp
 
 TEST(MemoryBoundedTraceTest, moved_tree_includes_stats_node_when_nodes_omitted) {
     MemoryBoundedTrace trace(5);
-    EXPECT_TRUE(trace.add(mbus::TraceNode("abcdef", 0)));
-    EXPECT_FALSE(trace.add(mbus::TraceNode("ghijkjlmn", 0)));
+    EXPECT_TRUE(trace.add(mbus::TraceNode("abcdef", epoch)));
+    EXPECT_FALSE(trace.add(mbus::TraceNode("ghijkjlmn", epoch)));
 
     mbus::TraceNode target;
     trace.moveTraceTo(target);
diff --git a/vespalib/src/tests/trace/trace.cpp b/vespalib/src/tests/trace/trace.cpp
index f4ed0b15a27..3f2089450c9 100644
--- a/vespalib/src/tests/trace/trace.cpp
+++ b/vespalib/src/tests/trace/trace.cpp
@@ -1,10 +1,11 @@
 // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
-#include <vespa/log/log.h>
-LOG_SETUP("trace_test");
 #include <vespa/vespalib/testkit/testapp.h>
 #include <vespa/vespalib/trace/trace.h>
 #include <vespa/vespalib/trace/tracevisitor.h>
 
+#include <vespa/log/log.h>
+LOG_SETUP("trace_test");
+
 using namespace vespalib;
 
 class Test : public vespalib::TestApp {
@@ -383,27 +384,32 @@ Test::testVisiting()
     EXPECT_EQUAL(encoder.str, b1.encode());
 }
 
+constexpr system_time zero(duration::zero());
+constexpr system_time one234(std::chrono::milliseconds(1234));
+constexpr system_time one23(std::chrono::milliseconds(123));
+constexpr system_time one24(std::chrono::milliseconds(124));
+
 void
 Test::testTimestamp()
 {
     TraceNode root;
-    root.addChild("foo", 1234);
+    root.addChild("foo", one234);
     root.addChild("bar");
-    EXPECT_EQUAL(root.getTimestamp(), 0);
-    EXPECT_EQUAL(root.getChild(0).getTimestamp(), 1234);
-    EXPECT_EQUAL(root.getChild(1).getTimestamp(), 0);
+    EXPECT_EQUAL(root.getTimestamp(), zero);
+    EXPECT_EQUAL(root.getChild(0).getTimestamp(), one234);
+    EXPECT_EQUAL(root.getChild(1).getTimestamp(), zero);
 }
 
 void
 Test::testConstruct()
 {
-    TraceNode leaf1("foo", 123);
+    TraceNode leaf1("foo", one23);
     EXPECT_TRUE(leaf1.hasNote());
     EXPECT_EQUAL("foo", leaf1.getNote());
-    EXPECT_EQUAL(123, leaf1.getTimestamp());
+    EXPECT_EQUAL(one23, leaf1.getTimestamp());
 
-    TraceNode leaf2(124);
+    TraceNode leaf2(one24);
     EXPECT_FALSE(leaf2.hasNote());
     EXPECT_EQUAL("", leaf2.getNote());
-    EXPECT_EQUAL(124, leaf2.getTimestamp());
+    EXPECT_EQUAL(one24, leaf2.getTimestamp());
 }
diff --git a/vespalib/src/tests/trace/trace_serialization.cpp b/vespalib/src/tests/trace/trace_serialization.cpp
index c176ca9fcf9..077d123c142 100644
--- a/vespalib/src/tests/trace/trace_serialization.cpp
+++ b/vespalib/src/tests/trace/trace_serialization.cpp
@@ -1,11 +1,12 @@
 // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
-#include <vespa/log/log.h>
-LOG_SETUP("trace_test");
 #include <vespa/vespalib/testkit/test_kit.h>
 #include <vespa/vespalib/trace/tracenode.h>
 #include <vespa/vespalib/trace/slime_trace_serializer.h>
 #include <vespa/vespalib/trace/slime_trace_deserializer.h>
 
+#include <vespa/log/log.h>
+LOG_SETUP("trace_test");
+
 using namespace vespalib;
 using namespace vespalib::slime;
 
@@ -20,10 +21,15 @@ TEST("that a single trace node is serialized") {
     EXPECT_FALSE(i["payload"].valid());
 }
 
+constexpr system_time zero_system_time(duration::zero());
+constexpr system_time one234(std::chrono::milliseconds(1234));
+constexpr system_time one235(std::chrono::milliseconds(1235));
+constexpr system_time forty5(std::chrono::milliseconds(45));
+
 TEST("that a trace node with children is serialized") {
     TraceNode node;
-    node.addChild("foo", 1234);
-    node.addChild("bar", 1235);
+    node.addChild("foo", one234);
+    node.addChild("bar", one235);
     Slime slime;
     SlimeTraceSerializer serializer(slime.setObject());
     node.accept(serializer);
@@ -47,7 +53,7 @@ TEST("that an empty root trace node can be deserialized") {
     SlimeTraceDeserializer deserializer(root);
     TraceNode node(deserializer.deserialize());
     EXPECT_FALSE(node.hasNote());
-    EXPECT_EQUAL(0, node.getTimestamp());
+    EXPECT_EQUAL(zero_system_time, node.getTimestamp());
 }
 
 
@@ -58,7 +64,7 @@ TEST("that a single trace node can be deserialized") {
     root.setString("payload", "hello");
     SlimeTraceDeserializer deserializer(root);
     TraceNode node(deserializer.deserialize());
-    EXPECT_EQUAL(1234, node.getTimestamp());
+    EXPECT_EQUAL(one234, node.getTimestamp());
     EXPECT_TRUE(node.hasNote());
     EXPECT_EQUAL("hello", node.getNote());
 }
@@ -95,7 +101,7 @@ TEST("that a trace node with children can be deserialized") {
 
 TEST("test serialization and deserialization") {
     TraceNode root;
-    root.addChild("foo", 45);
+    root.addChild("foo", forty5);
     root.addChild("bar");
     root.addChild(TraceNode());
     Slime slime;
diff --git a/vespalib/src/vespa/vespalib/testkit/test_comparators.cpp b/vespalib/src/vespa/vespalib/testkit/test_comparators.cpp
index 92ec51268d2..fd424c8dbdc 100644
--- a/vespalib/src/vespa/vespalib/testkit/test_comparators.cpp
+++ b/vespalib/src/vespa/vespalib/testkit/test_comparators.cpp
@@ -2,6 +2,13 @@
 
 #include "test_comparators.h"
 
+namespace std::chrono {
+
+ostream & operator << (ostream & os, system_clock::time_point ts) {
+    return os << ts.time_since_epoch();
+}
+
+}
 namespace vespalib {
 
 } // namespace vespalib
diff --git a/vespalib/src/vespa/vespalib/testkit/test_comparators.h b/vespalib/src/vespa/vespalib/testkit/test_comparators.h
index 5119aaebea6..161c125757b 100644
--- a/vespalib/src/vespa/vespalib/testkit/test_comparators.h
+++ b/vespalib/src/vespa/vespalib/testkit/test_comparators.h
@@ -13,6 +13,9 @@ ostream & operator << (ostream & os, duration<rep, period> ts) {
     return os << ts.count();
 }
 
+ostream & operator << (ostream & os, system_clock::time_point ts);
+
+
 }
 
 namespace vespalib {
diff --git a/vespalib/src/vespa/vespalib/trace/slime_trace_deserializer.cpp b/vespalib/src/vespa/vespalib/trace/slime_trace_deserializer.cpp
index 44e79de5248..eea59f2164f 100644
--- a/vespalib/src/vespa/vespalib/trace/slime_trace_deserializer.cpp
+++ b/vespalib/src/vespa/vespalib/trace/slime_trace_deserializer.cpp
@@ -29,7 +29,7 @@ SlimeTraceDeserializer::deserialize(const Inspector & inspector)
 TraceNode
 SlimeTraceDeserializer::deserializeTraceNode(const Inspector & inspector)
 {
-    int64_t timestamp(decodeTimestamp(inspector));
+    system_time timestamp(std::chrono::milliseconds(decodeTimestamp(inspector)));
     if (hasPayload(inspector)) {
         std::string note(decodePayload(inspector));
         return TraceNode(note, timestamp);
diff --git a/vespalib/src/vespa/vespalib/trace/slime_trace_serializer.cpp b/vespalib/src/vespa/vespalib/trace/slime_trace_serializer.cpp
index cdc952464dd..ccf5d50517a 100644
--- a/vespalib/src/vespa/vespalib/trace/slime_trace_serializer.cpp
+++ b/vespalib/src/vespa/vespalib/trace/slime_trace_serializer.cpp
@@ -32,7 +32,7 @@ SlimeTraceSerializer::visit(const TraceNode & node)
 void
 SlimeTraceSerializer::addTimestamp(Cursor & current, const TraceNode & node)
 {
-    current.setLong(TIMESTAMP, node.getTimestamp());
+    current.setLong(TIMESTAMP, count_ms(node.getTimestamp().time_since_epoch()));
 }
 
 void
diff --git a/vespalib/src/vespa/vespalib/trace/slime_trace_serializer.h b/vespalib/src/vespa/vespalib/trace/slime_trace_serializer.h
index d2ca00ba81a..1d5b5638f48 100644
--- a/vespalib/src/vespa/vespalib/trace/slime_trace_serializer.h
+++ b/vespalib/src/vespa/vespalib/trace/slime_trace_serializer.h
@@ -22,8 +22,8 @@ public:
     static const Memory PAYLOAD;
     static const Memory CHILDREN;
 private:
-    void addTimestamp(slime::Cursor & current, const TraceNode & node);
-    void addPayload(slime::Cursor & current, const TraceNode & node);
+    static void addTimestamp(slime::Cursor & current, const TraceNode & node);
+    static void addPayload(slime::Cursor & current, const TraceNode & node);
     void addChildrenCursors(slime::Cursor & current, const TraceNode & node);
     void addChildrenCursorsToStack(slime::Cursor & childrenArray, const TraceNode & node);
     std::stack<slime::Cursor *> _cursors;
diff --git a/vespalib/src/vespa/vespalib/trace/tracenode.cpp b/vespalib/src/vespa/vespalib/trace/tracenode.cpp
index bce184312f4..d34b45025d3 100644
--- a/vespalib/src/vespa/vespalib/trace/tracenode.cpp
+++ b/vespalib/src/vespa/vespalib/trace/tracenode.cpp
@@ -46,7 +46,7 @@ TraceNode::TraceNode() :
     _hasNote(false),
     _note(""),
     _children(),
-    _timestamp(0)
+    _timestamp()
 { }
 
 TraceNode::TraceNode(const TraceNode &rhs) :
@@ -65,7 +65,7 @@ TraceNode & TraceNode::operator =(const TraceNode &) = default;
 
 TraceNode::~TraceNode() = default;
 
-TraceNode::TraceNode(const string &note, int64_t timestamp) :
+TraceNode::TraceNode(const string &note, system_time timestamp) :
     _parent(nullptr),
     _strict(true),
     _hasNote(true),
@@ -74,7 +74,7 @@ TraceNode::TraceNode(const string &note, int64_t timestamp) :
     _timestamp(timestamp)
 { }
 
-TraceNode::TraceNode(int64_t timestamp) :
+TraceNode::TraceNode(system_time timestamp) :
     _parent(nullptr),
     _strict(true),
     _hasNote(false),
@@ -109,7 +109,7 @@ TraceNode::clear()
     _hasNote = false;
     _note.clear();
     _children.clear();
-    _timestamp = 0;
+    _timestamp = system_time();
     return *this;
 }
 
@@ -177,11 +177,11 @@ TraceNode::normalize()
 TraceNode &
 TraceNode::addChild(const string &note)
 {
-    return addChild(TraceNode(note, 0));
+    return addChild(TraceNode(note, system_time()));
 }
 
 TraceNode &
-TraceNode::addChild(const string &note, int64_t timestamp)
+TraceNode::addChild(const string &note, system_time timestamp)
 {
     return addChild(TraceNode(note, timestamp));
 }
@@ -245,8 +245,7 @@ TraceNode::encode() const
     string ret = "";
     if (_hasNote) {
         ret.append("[");
-        for (uint32_t i = 0, len = _note.size(); i < len; ++i) {
-            char c = _note[i];
+        for (char c : _note) {
             if (c == '\\' || c == ']') {
                 ret.append("\\");
             }
@@ -296,7 +295,7 @@ TraceNode::decode(const string &str)
                 node = &node->_children.back();
                 node->setStrict(c == '(');
             } else if (c == ')' || c == '}') {
-                if (node == NULL) {
+                if (node == nullptr) {
                     LOG(warning, "Unexpected closing brace in trace '%s' at "
                                  "position %d.", str.c_str(), i);
                     return TraceNode();
diff --git a/vespalib/src/vespa/vespalib/trace/tracenode.h b/vespalib/src/vespa/vespalib/trace/tracenode.h
index b44881b99b4..63e7bcd6dc0 100644
--- a/vespalib/src/vespa/vespalib/trace/tracenode.h
+++ b/vespalib/src/vespa/vespalib/trace/tracenode.h
@@ -2,6 +2,7 @@
 #pragma once
 
 #include <vespa/vespalib/stllike/string.h>
+#include <vespa/vespalib/util/time.h>
 #include <vector>
 
 namespace vespalib {
@@ -27,7 +28,7 @@ private:
     bool                   _hasNote;
     string                 _note;
     std::vector<TraceNode> _children;
-    int64_t                _timestamp;
+    system_time            _timestamp;
 
 public:
     /**
@@ -40,13 +41,13 @@ public:
      * @param note The note for this node.
      * @param timestamp The timestamp to give to node.
      */
-    explicit TraceNode(const string &note, int64_t timestamp);
+    explicit TraceNode(const string &note, system_time timestamp);
 
     /**
      * Create a leaf node with no note and a time stamp.
      * @param timestamp The timestamp to give to node.
      */
-    explicit TraceNode(int64_t timestamp);
+    explicit TraceNode(system_time timestamp);
 
     TraceNode & operator =(const TraceNode &);
     TraceNode(TraceNode &&) noexcept;
@@ -104,7 +105,7 @@ public:
      *
      * @return True if this has no parent.
      */
-    bool isRoot() const { return _parent == NULL; }
+    bool isRoot() const { return _parent == nullptr; }
 
     /**
      * Check whether or not this is a leaf node.
@@ -155,7 +156,7 @@ public:
      *
      * @return The timestamp.
      */
-    int64_t getTimestamp() const { return _timestamp; }
+    system_time getTimestamp() const { return _timestamp; }
 
 
     /**
@@ -189,7 +190,7 @@ public:
      * @param timestamp The timestamp to give this child.
      * @return This, to allow chaining.
      */
-    TraceNode &addChild(const string &note, int64_t timestamp);
+    TraceNode &addChild(const string &note, system_time timestamp);
 
     /**
      * Adds a child node to this.