diff options
author | Henning Baldersheim <balder@yahoo-inc.com> | 2019-12-05 06:28:38 -0800 |
---|---|---|
committer | GitHub <noreply@github.com> | 2019-12-05 06:28:38 -0800 |
commit | fa9c3e1bdd88b6919eaff9fba12e693262031581 (patch) | |
tree | 9d828d7a5d61b8a637f10285a85385a316915686 /vespalib | |
parent | f3335bc568a4ba16d05d6f8e3bf9ce26e12022e5 (diff) | |
parent | 516e1e2f28180c8055ccfdd640ea2b6051e4e648 (diff) |
Merge pull request #11509 from vespa-engine/balder/use-system-time-in-trace
Balder/use system time in trace
Diffstat (limited to 'vespalib')
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 ¬e, int64_t timestamp) : +TraceNode::TraceNode(const string ¬e, system_time timestamp) : _parent(nullptr), _strict(true), _hasNote(true), @@ -74,7 +74,7 @@ TraceNode::TraceNode(const string ¬e, 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 ¬e) { - return addChild(TraceNode(note, 0)); + return addChild(TraceNode(note, system_time())); } TraceNode & -TraceNode::addChild(const string ¬e, int64_t timestamp) +TraceNode::addChild(const string ¬e, 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 ¬e, int64_t timestamp); + explicit TraceNode(const string ¬e, 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 ¬e, int64_t timestamp); + TraceNode &addChild(const string ¬e, system_time timestamp); /** * Adds a child node to this. |