diff options
author | Håvard Pettersen <havardpe@oath.com> | 2019-02-01 16:25:45 +0000 |
---|---|---|
committer | Håvard Pettersen <havardpe@oath.com> | 2019-02-01 16:56:34 +0000 |
commit | 3b684350f21b606ebbfe78beb51146e93673fa03 (patch) | |
tree | 5cd8ca23835f20f0da03e337a0de1385cece617b /vespalib | |
parent | 8c4bb624a2f36f3e4d6635abeaf474a1da2de9b1 (diff) |
baseline time tracer code
Diffstat (limited to 'vespalib')
-rw-r--r-- | vespalib/CMakeLists.txt | 1 | ||||
-rw-r--r-- | vespalib/src/tests/time_tracer/CMakeLists.txt | 8 | ||||
-rw-r--r-- | vespalib/src/tests/time_tracer/time_tracer_test.cpp | 81 | ||||
-rw-r--r-- | vespalib/src/vespa/vespalib/test/CMakeLists.txt | 1 | ||||
-rw-r--r-- | vespalib/src/vespa/vespalib/test/time_tracer.cpp | 94 | ||||
-rw-r--r-- | vespalib/src/vespa/vespalib/test/time_tracer.h | 140 |
6 files changed, 325 insertions, 0 deletions
diff --git a/vespalib/CMakeLists.txt b/vespalib/CMakeLists.txt index 24f7d6e9214..6f770a1863e 100644 --- a/vespalib/CMakeLists.txt +++ b/vespalib/CMakeLists.txt @@ -106,6 +106,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..3ea2dee411a --- /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) +{ + auto guard = std::lock_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() +{ + auto guard = std::lock_guard(_lock); + _state_list.push_back(std::make_unique<ThreadState>()); + return _state_list.back().get(); +} + +std::vector<TimeTracer::Record> +TimeTracer::extract_all_impl() +{ + auto guard = std::lock_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..73fdb774856 --- /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 font. 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; |