TLS time trace experiments

Note that this is without intrusive samples in the code

3 files changed, 140 insertions, 36 deletions

diff --git a/vespalib/src/tests/time_tracer/time_tracer_test.cpp b/vespalib/src/tests/time_tracer/time_tracer_test.cpp
index 835c3ffecbf..d7e2e0d579a 100644
--- a/vespalib/src/tests/time_tracer/time_tracer_test.cpp
+++ b/vespalib/src/tests/time_tracer/time_tracer_test.cpp
@@ -11,16 +11,15 @@ 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("require that tag ids are equal if and only if tag names are equal") {
+    TT_Tag tag1_too("tag1");
+    EXPECT_NOT_EQUAL(tag0.id(), tag1.id());
+    EXPECT_NOT_EQUAL(tag1.id(), tag2.id());
+    EXPECT_NOT_EQUAL(tag2.id(), tag0.id());
+    EXPECT_EQUAL(tag1_too.id(), tag1.id());
 }
 
 TEST_MT("require that threads are numbered by first sample", 3) {
@@ -38,14 +37,14 @@ TEST_MT("require that threads are numbered by first sample", 3) {
         { TT_Sample sample(tag2); }
     }
     TEST_BARRIER(); // # 3
-    auto list = TimeTracer::extract_all();
+    auto list = TimeTracer::extract().get();
     ASSERT_EQUAL(list.size(), 3u);
     EXPECT_EQUAL(list[0].thread_id, 0u);
-    EXPECT_EQUAL(list[0].tag_id, 0u);
+    EXPECT_EQUAL(list[0].tag_id, tag0.id());
     EXPECT_EQUAL(list[1].thread_id, 1u);
-    EXPECT_EQUAL(list[1].tag_id, 1u);
+    EXPECT_EQUAL(list[1].tag_id, tag1.id());
     EXPECT_EQUAL(list[2].thread_id, 2u);
-    EXPECT_EQUAL(list[2].tag_id, 2u);
+    EXPECT_EQUAL(list[2].tag_id, tag2.id());
 }
 
 TEST("require that records are extracted inversely ordered by end time per thread") {
@@ -53,11 +52,11 @@ TEST("require that records are extracted inversely ordered by end time per threa
     { TT_Sample s(my_tag); }
     { TT_Sample s(my_tag); }
     auto t = TimeTracer::now();
-    auto list = TimeTracer::extract_all();
+    auto list = TimeTracer::extract().get();
     EXPECT_EQUAL(list.size(), 6u);
     size_t cnt = 0;
     for (const auto &item: list) {
-        if (item.tag_id == 3) {
+        if (item.tag_id == my_tag.id()) {
             ++cnt;
             EXPECT_TRUE(item.start <= item.stop);
             EXPECT_TRUE(item.stop <= t);
@@ -73,7 +72,7 @@ TEST("benchmark time sampling") {
     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();
+    auto list = TimeTracer::extract().get();
     fprintf(stderr, "total samples after benchmarking: %zu\n", list.size());
     EXPECT_GREATER(list.size(), 6u);
 }
diff --git a/vespalib/src/vespa/vespalib/test/time_tracer.cpp b/vespalib/src/vespa/vespalib/test/time_tracer.cpp
index 49f554d1ad2..b0801413871 100644
--- a/vespalib/src/vespa/vespalib/test/time_tracer.cpp
+++ b/vespalib/src/vespa/vespalib/test/time_tracer.cpp
@@ -28,6 +28,64 @@ TimeTracer::Tag::~Tag() = default;
 
 //-----------------------------------------------------------------------------
 
+double
+TimeTracer::Record::ms_duration() const
+{
+    return std::chrono::duration<double, std::milli>(stop - start).count();
+}
+
+vespalib::string
+TimeTracer::Record::tag_name() const
+{
+    return master().get_tag_name(tag_id);
+}
+
+//-----------------------------------------------------------------------------
+
+bool
+TimeTracer::Extractor::keep(const Record &entry) const
+{
+    return ((!_by_thread || (entry.thread_id == _thread_id)) &&
+            (!_by_tag    || (entry.tag_id == _tag_id))       &&
+            (!_by_time   || (entry.stop > _a))               &&
+            (!_by_time   || (entry.start < _b)));
+}
+
+TimeTracer::Extractor &&
+TimeTracer::Extractor::by_thread(uint32_t thread_id) &&
+{
+    _by_thread = true;
+    _thread_id = thread_id;
+    return std::move(*this);
+}
+
+TimeTracer::Extractor &&
+TimeTracer::Extractor::by_tag(uint32_t tag_id) &&
+{
+    _by_tag = true;
+    _tag_id = tag_id;
+    return std::move(*this);
+}
+
+TimeTracer::Extractor &&
+TimeTracer::Extractor::by_time(time_point a, time_point b) &&
+{
+    _by_time = true;
+    _a = a;
+    _b = b;
+    return std::move(*this);
+}
+
+std::vector<TimeTracer::Record>
+TimeTracer::Extractor::get() const
+{
+    return master().extract_impl(*this);
+}
+
+TimeTracer::Extractor::~Extractor() = default;
+
+//-----------------------------------------------------------------------------
+
 void
 TimeTracer::init_thread_state() noexcept
 {
@@ -39,7 +97,8 @@ TimeTracer::init_thread_state() noexcept
 TimeTracer::TimeTracer()
     : _lock(),
       _state_list(),
-      _tags()
+      _tags(),
+      _tag_names()
 {
 }
 
@@ -53,26 +112,42 @@ TimeTracer::get_tag_id(const vespalib::string &tag_name)
     }
     uint32_t id = _tags.size();
     _tags[tag_name] = id;
+    _tag_names.push_back(tag_name);
     return id;
 }
 
+vespalib::string
+TimeTracer::get_tag_name(uint32_t tag_id)
+{
+    std::lock_guard guard(_lock);
+    if (tag_id < _tag_names.size()) {
+        return _tag_names[tag_id];
+    } else {
+        return "<undef>";
+    }
+}
+
 TimeTracer::ThreadState *
 TimeTracer::create_thread_state()
 {
     std::lock_guard guard(_lock);
-    _state_list.push_back(std::make_unique<ThreadState>());
+    uint32_t thread_id = _state_list.size();
+    _state_list.push_back(std::make_unique<ThreadState>(thread_id));
     return _state_list.back().get();
 }
 
 std::vector<TimeTracer::Record>
-TimeTracer::extract_all_impl()
+TimeTracer::extract_impl(const Extractor &extractor)
 {
     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();
+    for (const ThreadState::UP &state: _state_list) {
+        const LogEntry *entry = state->get_log_entries();
         while (entry != nullptr) {
-            list.emplace_back(thread_id, entry->tag_id, entry->start, entry->stop);
+            Record record(state->thread_id(), entry->tag_id, entry->start, entry->stop);
+            if (extractor.keep(record)) {
+                list.push_back(record);
+            }
             entry = entry->next;
         }
     }
@@ -83,12 +158,4 @@ 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
index 2a55e2134b3..c872ed84bbc 100644
--- a/vespalib/src/vespa/vespalib/test/time_tracer.h
+++ b/vespalib/src/vespa/vespalib/test/time_tracer.h
@@ -7,6 +7,7 @@
 #include <chrono>
 #include <mutex>
 #include <atomic>
+#include <thread>
 #include <map>
 
 namespace vespalib::test {
@@ -82,6 +83,26 @@ public:
                time_point start_in, time_point stop_in)
             : thread_id(thread_id_in), tag_id(tag_id_in),
               start(start_in), stop(stop_in) {}
+        double ms_duration() const;
+        vespalib::string tag_name() const;
+    };
+
+    class Extractor {
+    private:
+        bool       _by_thread;
+        uint32_t   _thread_id;
+        bool       _by_tag;
+        uint32_t   _tag_id;
+        bool       _by_time;
+        time_point _a;
+        time_point _b;
+    public:
+        bool keep(const Record &entry) const;
+        Extractor &&by_thread(uint32_t thread_id) &&;
+        Extractor &&by_tag(uint32_t tag_id) &&;
+        Extractor &&by_time(time_point a, time_point b) &&;
+        std::vector<Record> get() const;
+        ~Extractor();
     };
 
 private:
@@ -93,20 +114,35 @@ private:
         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) {}
     };
+
+    struct Guard {
+        std::atomic_flag &lock;
+        explicit Guard(std::atomic_flag &lock_in) noexcept : lock(lock_in) {
+            while (__builtin_expect(lock.test_and_set(std::memory_order_acquire), false)) {
+                std::this_thread::yield();
+            }
+        }
+        ~Guard() noexcept { lock.clear(std::memory_order_release); }
+    };
+
     class ThreadState {
     private:
+        uint32_t _thread_id;
+        mutable std::atomic_flag _lock;
         vespalib::Stash _stash;
-        std::atomic<const LogEntry *> _list;
+        const LogEntry * _list;
     public:
         using UP = std::unique_ptr<ThreadState>;
-        ThreadState() : _stash(64 * 1024), _list(nullptr) {}
+        ThreadState(uint32_t thread_id)
+            : _thread_id(thread_id), _lock{ATOMIC_FLAG_INIT}, _stash(64 * 1024), _list(nullptr) {}
+        uint32_t thread_id() const { return _thread_id; }
         const LogEntry *get_log_entries() const {
-            return _list.load(std::memory_order_acquire);
+            Guard guard(_lock);
+            return _list;
         }
         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);
+            Guard guard(_lock);
+            _list = &_stash.create<LogEntry>(tag_id, start, stop, _list);
         }
     };
     static TimeTracer &master();
@@ -123,15 +159,17 @@ private:
     std::mutex _lock;
     std::vector<ThreadState::UP> _state_list;
     std::map<vespalib::string, uint32_t> _tags;
+    std::vector<vespalib::string> _tag_names;
 
     TimeTracer();
     ~TimeTracer();
     uint32_t get_tag_id(const vespalib::string &tag_name);
+    vespalib::string get_tag_name(uint32_t tag_id);
     ThreadState *create_thread_state();
-    std::vector<Record> extract_all_impl();
+    std::vector<Record> extract_impl(const Extractor &extractor);
 
 public:
-    static std::vector<Record> extract_all();
+    static Extractor extract() { return Extractor(); }
 };
 
 } // namespace vespalib::test