diff options
author | Henning Baldersheim <balder@yahoo-inc.com> | 2019-12-05 01:10:26 +0000 |
---|---|---|
committer | Henning Baldersheim <balder@yahoo-inc.com> | 2019-12-05 01:10:26 +0000 |
commit | 673d9aa646a4e99320cbeaa717e9362555fd9e8e (patch) | |
tree | 02e3d11543e76dd102a340d2ffd2a7e436f4c159 | |
parent | eb814155171b9d46eaa213ed3000a874aa250fa4 (diff) |
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 ¬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. |