Merge pull request #11509 from vespa-engine/balder/use-system-time-in-trace

Balder/use system time in trace

9 files changed, 69 insertions, 100 deletions

diff --git a/vespalib/src/tests/trace/trace.cpp b/vespalib/src/tests/trace/trace.cpp
index f4ed0b15a27..f2141fbf995 100644
--- a/vespalib/src/tests/trace/trace.cpp
+++ b/vespalib/src/tests/trace/trace.cpp
@@ -1,54 +1,14 @@
 // 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>
 
-using namespace vespalib;
-
-class Test : public vespalib::TestApp {
-private:
-    void testEncodeDecode();
-    void testReservedChars();
-    void testConstruct();
-    void testAdd();
-    void testSort();
-    void testStrict();
-    void testTraceLevel();
-    void testCompact();
-    void testNormalize();
-    void testTraceDump();
-    void testVisiting();
-    void testTimestamp();
-
-public:
-    int Main() override;
-};
-
-TEST_APPHOOK(Test);
+#include <vespa/log/log.h>
+LOG_SETUP("trace_test");
 
-int
-Test::Main()
-{
-    TEST_INIT("trace_test");
-    testEncodeDecode();
-    testReservedChars();
-    testAdd();
-    testConstruct();
-    testSort();
-    testStrict();
-    testTraceLevel();
-    testCompact();
-    testNormalize();
-    testTraceDump();
-    testVisiting();
-    testTimestamp();
-    TEST_DONE();
-}
+using namespace vespalib;
 
-void
-Test::testEncodeDecode()
+TEST("testEncodeDecode")
 {
     EXPECT_EQUAL("()", TraceNode::decode("").encode());
     EXPECT_EQUAL("()", TraceNode::decode("[xyz").encode());
@@ -134,8 +94,7 @@ Test::testEncodeDecode()
     }
 }
 
-void
-Test::testReservedChars()
+TEST("testReservedChars")
 {
     TraceNode t;
     t.addChild("abc(){}[]\\xyz");
@@ -154,8 +113,7 @@ Test::testReservedChars()
     }
 }
 
-void
-Test::testAdd()
+TEST("testAdd")
 {
     TraceNode t1 = TraceNode::decode("([x])");
     TraceNode t2 = TraceNode::decode("([y])");
@@ -175,16 +133,14 @@ Test::testAdd()
     EXPECT_EQUAL("([y]([y])([y]([y])))", t2.encode());
 }
 
-void
-Test::testStrict()
+TEST("testStrict")
 {
     EXPECT_EQUAL("{}", TraceNode::decode("()").setStrict(false).encode());
     EXPECT_EQUAL("{[x]}", TraceNode::decode("([x])").setStrict(false).encode());
     EXPECT_EQUAL("{[x][y]}", TraceNode::decode("([x][y])").setStrict(false).encode());
 }
 
-void
-Test::testTraceLevel()
+TEST("testTraceLevel")
 {
     Trace t;
     t.setLevel(4);
@@ -211,8 +167,7 @@ Test::testTraceLevel()
     EXPECT_EQUAL(5u, t.getRoot().getNumChildren());
 }
 
-void
-Test::testCompact()
+TEST("testCompact")
 {
     EXPECT_EQUAL("()", TraceNode::decode("()").compact().encode());
     EXPECT_EQUAL("()", TraceNode::decode("(())").compact().encode());
@@ -242,8 +197,7 @@ Test::testCompact()
     EXPECT_EQUAL("({[a][b][c][d][e][f]})", TraceNode::decode("({({[a][b]})({[c][d]})({[e][f]})})").compact().encode());
 }
 
-void
-Test::testSort()
+TEST("testSort")
 {
     EXPECT_EQUAL("([b][a][c])", TraceNode::decode("([b][a][c])").sort().encode());
     EXPECT_EQUAL("({[a][b][c]})", TraceNode::decode("({[b][a][c]})").sort().encode());
@@ -253,8 +207,7 @@ Test::testSort()
     EXPECT_EQUAL("({([b]){[a][c]}})", TraceNode::decode("({{[c][a]}([b])})").sort().encode());
 }
 
-void
-Test::testNormalize()
+TEST("testNormalize")
 {
     TraceNode t1 = TraceNode::decode("({([a][b]{[x][y]([p][q])})([c][d])([e][f])})");
     TraceNode t2 = TraceNode::decode("({([a][b]{[y][x]([p][q])})([c][d])([e][f])})");
@@ -295,8 +248,7 @@ Test::testNormalize()
     EXPECT_EQUAL("({([c][d])([e][f])([a][b]{[x][y]([p][q])})})", t1.normalize().encode());
 }
 
-void
-Test::testTraceDump()
+TEST("testTraceDump")
 {
     {
         Trace big;
@@ -363,8 +315,7 @@ struct EncoderVisitor : public TraceVisitor
     }
 };
 
-void
-Test::testVisiting()
+TEST("testVisiting")
 {
     TraceNode b1;
     TraceNode b2;
@@ -383,27 +334,30 @@ Test::testVisiting()
     EXPECT_EQUAL(encoder.str, b1.encode());
 }
 
-void
-Test::testTimestamp()
+constexpr system_time zero(duration::zero());
+constexpr system_time as_ms(long ms) { return system_time(std::chrono::milliseconds(ms)); }
+
+TEST("testTimestamp")
 {
     TraceNode root;
-    root.addChild("foo", 1234);
+    root.addChild("foo", as_ms(1234));
     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(), as_ms(1234));
+    EXPECT_EQUAL(root.getChild(1).getTimestamp(), zero);
 }
 
-void
-Test::testConstruct()
+TEST("testConstruct")
 {
-    TraceNode leaf1("foo", 123);
+    TraceNode leaf1("foo", as_ms(123));
     EXPECT_TRUE(leaf1.hasNote());
     EXPECT_EQUAL("foo", leaf1.getNote());
-    EXPECT_EQUAL(123, leaf1.getTimestamp());
+    EXPECT_EQUAL(as_ms(123), leaf1.getTimestamp());
 
-    TraceNode leaf2(124);
+    TraceNode leaf2(as_ms(124));
     EXPECT_FALSE(leaf2.hasNote());
     EXPECT_EQUAL("", leaf2.getNote());
-    EXPECT_EQUAL(124, leaf2.getTimestamp());
+    EXPECT_EQUAL(as_ms(124), leaf2.getTimestamp());
 }
+
+TEST_MAIN() { TEST_RUN_ALL(); }
diff --git a/vespalib/src/tests/trace/trace_serialization.cpp b/vespalib/src/tests/trace/trace_serialization.cpp
index c176ca9fcf9..9ba6cdb512b 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,14 @@ TEST("that a single trace node is serialized") {
     EXPECT_FALSE(i["payload"].valid());
 }
 
+constexpr system_time zero_system_time(duration::zero());
+constexpr system_time as_ms(long ms) { return system_time(std::chrono::milliseconds(ms)); }
+
+
 TEST("that a trace node with children is serialized") {
     TraceNode node;
-    node.addChild("foo", 1234);
-    node.addChild("bar", 1235);
+    node.addChild("foo", as_ms(1234));
+    node.addChild("bar", as_ms(1235));
     Slime slime;
     SlimeTraceSerializer serializer(slime.setObject());
     node.accept(serializer);
@@ -47,7 +52,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 +63,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(as_ms(1234), node.getTimestamp());
     EXPECT_TRUE(node.hasNote());
     EXPECT_EQUAL("hello", node.getNote());
 }
@@ -95,7 +100,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", as_ms(45));
     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..d00ad8d954c 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() << "ns";
+}
+
+}
 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.