Merge pull request #8350 from vespa-engine/havardpe/time-tracer

baseline time tracer code

6 files changed, 325 insertions, 0 deletions

diff --git a/vespalib/CMakeLists.txt b/vespalib/CMakeLists.txt
index a9d10954a6f..8306b55f73c 100644
--- a/vespalib/CMakeLists.txt
+++ b/vespalib/CMakeLists.txt
@@ -107,6 +107,7 @@ vespa_define_module(
     src/tests/text/utf8
     src/tests/thread
     src/tests/time
+    src/tests/time_tracer
     src/tests/time_tracker
     src/tests/trace
     src/tests/traits
diff --git a/vespalib/src/tests/time_tracer/CMakeLists.txt b/vespalib/src/tests/time_tracer/CMakeLists.txt
new file mode 100644
index 00000000000..00af1e12345
--- /dev/null
+++ b/vespalib/src/tests/time_tracer/CMakeLists.txt
@@ -0,0 +1,8 @@
+# Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+vespa_add_executable(vespalib_time_tracer_test_app TEST
+    SOURCES
+    time_tracer_test.cpp
+    DEPENDS
+    vespalib
+)
+vespa_add_test(NAME vespalib_time_tracer_test_app COMMAND vespalib_time_tracer_test_app)
diff --git a/vespalib/src/tests/time_tracer/time_tracer_test.cpp b/vespalib/src/tests/time_tracer/time_tracer_test.cpp
new file mode 100644
index 00000000000..835c3ffecbf
--- /dev/null
+++ b/vespalib/src/tests/time_tracer/time_tracer_test.cpp
@@ -0,0 +1,81 @@
+// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+
+#include <vespa/vespalib/testkit/test_kit.h>
+#include <vespa/vespalib/test/time_tracer.h>
+#include <vespa/vespalib/util/benchmark_timer.h>
+#include <vespa/vespalib/util/stringfmt.h>
+
+using namespace vespalib;
+using vespalib::test::TimeTracer;
+
+TT_Tag tag0("tag0");
+TT_Tag tag1("tag1");
+TT_Tag tag2("tag2");
+TT_Tag tag1_too("tag1");
+
+TT_Tag my_tag("my tag");
+
+TEST("require that tags are numbered by first creation time") {
+    EXPECT_EQUAL(tag0.id(), 0u);
+    EXPECT_EQUAL(tag1.id(), 1u);
+    EXPECT_EQUAL(tag2.id(), 2u);
+    EXPECT_EQUAL(tag1_too.id(), 1u);
+    EXPECT_EQUAL(my_tag.id(), 3u);
+}
+
+TEST_MT("require that threads are numbered by first sample", 3) {
+    if (thread_id == 0) {
+        { TT_Sample sample(tag0); }
+        TEST_BARRIER(); // # 1
+        TEST_BARRIER(); // # 2
+    } else if (thread_id == 1) {
+        TEST_BARRIER(); // # 1
+        { TT_Sample sample(tag1); }
+        TEST_BARRIER(); // # 2
+    } else {
+        TEST_BARRIER(); // # 1
+        TEST_BARRIER(); // # 2
+        { TT_Sample sample(tag2); }
+    }
+    TEST_BARRIER(); // # 3
+    auto list = TimeTracer::extract_all();
+    ASSERT_EQUAL(list.size(), 3u);
+    EXPECT_EQUAL(list[0].thread_id, 0u);
+    EXPECT_EQUAL(list[0].tag_id, 0u);
+    EXPECT_EQUAL(list[1].thread_id, 1u);
+    EXPECT_EQUAL(list[1].tag_id, 1u);
+    EXPECT_EQUAL(list[2].thread_id, 2u);
+    EXPECT_EQUAL(list[2].tag_id, 2u);
+}
+
+TEST("require that records are extracted inversely ordered by end time per thread") {
+    { TT_Sample s(my_tag); }
+    { TT_Sample s(my_tag); }
+    { TT_Sample s(my_tag); }
+    auto t = TimeTracer::now();
+    auto list = TimeTracer::extract_all();
+    EXPECT_EQUAL(list.size(), 6u);
+    size_t cnt = 0;
+    for (const auto &item: list) {
+        if (item.tag_id == 3) {
+            ++cnt;
+            EXPECT_TRUE(item.start <= item.stop);
+            EXPECT_TRUE(item.stop <= t);
+            t = item.stop;
+        }
+    }
+    EXPECT_EQUAL(cnt, 3u);
+}
+
+TEST("benchmark time sampling") {
+    double min_stamp_us = 1000000.0 * BenchmarkTimer::benchmark([](){ (void) TimeTracer::now(); }, 1.0);
+    double min_sample_us = 1000000.0 * BenchmarkTimer::benchmark([](){ TT_Sample my_sample(my_tag); }, 1.0);
+    fprintf(stderr, "min timestamp time: %g us\n", min_stamp_us);
+    fprintf(stderr, "min sample time: %g us\n", min_sample_us);
+    fprintf(stderr, "estimated non-clock overhead: %g us\n", (min_sample_us - (min_stamp_us * 2.0)));
+    auto list = TimeTracer::extract_all();
+    fprintf(stderr, "total samples after benchmarking: %zu\n", list.size());
+    EXPECT_GREATER(list.size(), 6u);
+}
+
+TEST_MAIN() { TEST_RUN_ALL(); }
diff --git a/vespalib/src/vespa/vespalib/test/CMakeLists.txt b/vespalib/src/vespa/vespalib/test/CMakeLists.txt
index 73d31208721..a42907dd72d 100644
--- a/vespalib/src/vespa/vespalib/test/CMakeLists.txt
+++ b/vespalib/src/vespa/vespalib/test/CMakeLists.txt
@@ -3,5 +3,6 @@ vespa_add_library(vespalib_vespalib_test OBJECT
     SOURCES
     make_tls_options_for_testing.cpp
     peer_policy_utils.cpp
+    time_tracer.cpp
     DEPENDS
 )
diff --git a/vespalib/src/vespa/vespalib/test/time_tracer.cpp b/vespalib/src/vespa/vespalib/test/time_tracer.cpp
new file mode 100644
index 00000000000..49f554d1ad2
--- /dev/null
+++ b/vespalib/src/vespa/vespalib/test/time_tracer.cpp
@@ -0,0 +1,94 @@
+// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+
+#include "time_tracer.h"
+
+namespace vespalib::test {
+
+//-----------------------------------------------------------------------------
+
+TimeTracer &
+TimeTracer::master()
+{
+    static TimeTracer instance;
+    return instance;
+}
+
+//-----------------------------------------------------------------------------
+
+thread_local TimeTracer::ThreadState *TimeTracer::_thread_state = nullptr;
+
+//-----------------------------------------------------------------------------
+
+TimeTracer::Tag::Tag(const vespalib::string &name)
+    : _id(master().get_tag_id(name))
+{
+}
+
+TimeTracer::Tag::~Tag() = default;
+
+//-----------------------------------------------------------------------------
+
+void
+TimeTracer::init_thread_state() noexcept
+{
+    _thread_state = master().create_thread_state();
+}
+
+//-----------------------------------------------------------------------------
+
+TimeTracer::TimeTracer()
+    : _lock(),
+      _state_list(),
+      _tags()
+{
+}
+
+uint32_t
+TimeTracer::get_tag_id(const vespalib::string &tag_name)
+{
+    std::lock_guard guard(_lock);
+    auto pos = _tags.find(tag_name);
+    if (pos != _tags.end()) {
+        return pos->second;
+    }
+    uint32_t id = _tags.size();
+    _tags[tag_name] = id;
+    return id;
+}
+
+TimeTracer::ThreadState *
+TimeTracer::create_thread_state()
+{
+    std::lock_guard guard(_lock);
+    _state_list.push_back(std::make_unique<ThreadState>());
+    return _state_list.back().get();
+}
+
+std::vector<TimeTracer::Record>
+TimeTracer::extract_all_impl()
+{
+    std::lock_guard guard(_lock);
+    std::vector<Record> list;
+    for (size_t thread_id = 0; thread_id < _state_list.size(); ++thread_id) {
+        const LogEntry *entry = _state_list[thread_id]->get_log_entries();
+        while (entry != nullptr) {
+            list.emplace_back(thread_id, entry->tag_id, entry->start, entry->stop);
+            entry = entry->next;
+        }
+    }
+    return list;
+}
+
+TimeTracer::~TimeTracer() = default;
+
+//-----------------------------------------------------------------------------
+
+std::vector<TimeTracer::Record>
+TimeTracer::extract_all()
+{
+    return master().extract_all_impl();
+}
+
+//-----------------------------------------------------------------------------
+
+} // namespace vespalib::test
diff --git a/vespalib/src/vespa/vespalib/test/time_tracer.h b/vespalib/src/vespa/vespalib/test/time_tracer.h
new file mode 100644
index 00000000000..2a55e2134b3
--- /dev/null
+++ b/vespalib/src/vespa/vespalib/test/time_tracer.h
@@ -0,0 +1,140 @@
+// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+
+#pragma once
+
+#include <vespa/vespalib/stllike/string.h>
+#include <vespa/vespalib/util/stash.h>
+#include <chrono>
+#include <mutex>
+#include <atomic>
+#include <map>
+
+namespace vespalib::test {
+
+/**
+ * Keep track of when and for how long different things happen across
+ * different threads. Note that this is intended for testing purposes
+ * only, since collected data is never released.
+ *
+ * Typically, timing information is collected while a unit test is
+ * running. Sampling can be performed in the test code itself to
+ * identify which parts take more time. For more advanced analysis,
+ * critical parts of the code being tested can also be modified to
+ * collect time samples (this is similar to the ancient fprintf
+ * debugging technique).
+ *
+ * In order to collect timing information, the client code uses the
+ * TT_Tag and TT_Sample classes. The TT_Tag class represents a thing
+ * that can happen. It should always be constructed up front. The
+ * TT_Sample class represents the fact that the thing represented by a
+ * TT_Tag is happening for as long as the TT_Sample object is
+ * alive. In other words; if the TT_Tag is an event, the TT_Sample
+ * will bind an instance of that event to the current scope.
+ *
+ * <pre>
+ * How to integrate into code:
+ *
+ * #include <vespa/vespalib/test/time_tracer.h>
+ *
+ * TT_Tag my_tag("my task");
+ *
+ * void do_stuff() {
+ *     TT_Sample my_sample(my_tag);
+ *     ... perform 'my task'
+ * }
+ * </pre>
+ *
+ * Data collection is designed to be high-capacity/low-overhead. This
+ * means that collected time samples cannot be inspected directly in a
+ * global structure but will need to be extracted before they can be
+ * analyzed.
+ **/
+class TimeTracer
+{
+public:
+    using time_point = std::chrono::steady_clock::time_point;
+    static time_point now() { return std::chrono::steady_clock::now(); }
+
+    class Tag {
+    private:
+        uint32_t _id;
+    public:
+        Tag(const vespalib::string &name_in);
+        ~Tag();
+        uint32_t id() const { return _id; }
+    };
+
+    class Sample {
+    private:
+        uint32_t _tag_id;
+        time_point _start;
+    public:
+        Sample(const Tag &tag) noexcept : _tag_id(tag.id()), _start(now()) {}
+        ~Sample() noexcept { thread_state().add_log_entry(_tag_id, _start, now()); }
+    };
+
+    struct Record {
+        uint32_t thread_id;
+        uint32_t tag_id;
+        time_point start;
+        time_point stop;
+        Record(uint32_t thread_id_in, uint32_t tag_id_in,
+               time_point start_in, time_point stop_in)
+            : thread_id(thread_id_in), tag_id(tag_id_in),
+              start(start_in), stop(stop_in) {}
+    };
+
+private:
+    struct LogEntry {
+        uint32_t tag_id;
+        time_point start;
+        time_point stop;
+        const LogEntry *next;
+        LogEntry(uint32_t tag_id_in, time_point start_in, time_point stop_in, const LogEntry *next_in)
+            : tag_id(tag_id_in), start(start_in), stop(stop_in), next(next_in) {}
+    };
+    class ThreadState {
+    private:
+        vespalib::Stash _stash;
+        std::atomic<const LogEntry *> _list;
+    public:
+        using UP = std::unique_ptr<ThreadState>;
+        ThreadState() : _stash(64 * 1024), _list(nullptr) {}
+        const LogEntry *get_log_entries() const {
+            return _list.load(std::memory_order_acquire);
+        }
+        void add_log_entry(uint32_t tag_id, time_point start, time_point stop) {
+            const LogEntry *old_list = _list.load(std::memory_order_relaxed);
+            _list.store(&_stash.create<LogEntry>(tag_id, start, stop, old_list),
+                        std::memory_order_release);
+        }
+    };
+    static TimeTracer &master();
+    static thread_local ThreadState *_thread_state;
+
+    static void init_thread_state() noexcept;
+    static ThreadState &thread_state() noexcept {
+        if (__builtin_expect((_thread_state == nullptr), false)) {
+            init_thread_state();
+        }
+        return *_thread_state;
+    }
+
+    std::mutex _lock;
+    std::vector<ThreadState::UP> _state_list;
+    std::map<vespalib::string, uint32_t> _tags;
+
+    TimeTracer();
+    ~TimeTracer();
+    uint32_t get_tag_id(const vespalib::string &tag_name);
+    ThreadState *create_thread_state();
+    std::vector<Record> extract_all_impl();
+
+public:
+    static std::vector<Record> extract_all();
+};
+
+} // namespace vespalib::test
+
+using TT_Tag = vespalib::test::TimeTracer::Tag;
+using TT_Sample = vespalib::test::TimeTracer::Sample;