diff options
author | Henning Baldersheim <balder@yahoo-inc.com> | 2019-11-21 21:56:41 +0100 |
---|---|---|
committer | GitHub <noreply@github.com> | 2019-11-21 21:56:41 +0100 |
commit | bf04cdc3471570c4cfd1ffa57a66eaad1f4263ae (patch) | |
tree | 7b4cedc55993c45e3047525f79da601b8e20aa6e | |
parent | d1620d8c4503c3eca66e42d32364364e6fe2fb68 (diff) | |
parent | 75d5498f0ec6db8debf2b5e3adf54e8ea057979a (diff) |
Merge pull request #11380 from vespa-engine/havardpe/time-in-vespalib
Havardpe/time in vespalib
-rw-r--r-- | vespalib/CMakeLists.txt | 1 | ||||
-rw-r--r-- | vespalib/src/tests/time/CMakeLists.txt | 8 | ||||
-rw-r--r-- | vespalib/src/tests/time/time_test.cpp | 39 | ||||
-rw-r--r-- | vespalib/src/tests/time_tracker/.gitignore | 1 | ||||
-rw-r--r-- | vespalib/src/tests/time_tracker/CMakeLists.txt | 8 | ||||
-rw-r--r-- | vespalib/src/tests/time_tracker/time_tracker_test.cpp | 93 | ||||
-rw-r--r-- | vespalib/src/vespa/vespalib/util/CMakeLists.txt | 4 | ||||
-rw-r--r-- | vespalib/src/vespa/vespalib/util/time.cpp | 9 | ||||
-rw-r--r-- | vespalib/src/vespa/vespalib/util/time.h | 53 | ||||
-rw-r--r-- | vespalib/src/vespa/vespalib/util/time_tracker.cpp | 93 | ||||
-rw-r--r-- | vespalib/src/vespa/vespalib/util/time_tracker.h | 91 |
11 files changed, 111 insertions, 289 deletions
diff --git a/vespalib/CMakeLists.txt b/vespalib/CMakeLists.txt index 1a111ed49ef..14c14fe85ca 100644 --- a/vespalib/CMakeLists.txt +++ b/vespalib/CMakeLists.txt @@ -116,7 +116,6 @@ vespa_define_module( src/tests/thread src/tests/time src/tests/time_tracer - src/tests/time_tracker src/tests/trace src/tests/traits src/tests/true diff --git a/vespalib/src/tests/time/CMakeLists.txt b/vespalib/src/tests/time/CMakeLists.txt index 4fa8bad5eed..e43bd9097e5 100644 --- a/vespalib/src/tests/time/CMakeLists.txt +++ b/vespalib/src/tests/time/CMakeLists.txt @@ -6,3 +6,11 @@ vespa_add_executable(vespalib_time_box_test_app TEST vespalib ) vespa_add_test(NAME vespalib_time_box_test_app COMMAND vespalib_time_box_test_app) +vespa_add_executable(vespalib_time_test_app TEST + SOURCES + time_test.cpp + DEPENDS + vespalib + gtest +) +vespa_add_test(NAME vespalib_time_test_app COMMAND vespalib_time_test_app) diff --git a/vespalib/src/tests/time/time_test.cpp b/vespalib/src/tests/time/time_test.cpp new file mode 100644 index 00000000000..667511f6a94 --- /dev/null +++ b/vespalib/src/tests/time/time_test.cpp @@ -0,0 +1,39 @@ +// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +#include <vespa/vespalib/util/time.h> +#include <vespa/vespalib/gtest/gtest.h> +#include <thread> + +using namespace vespalib; + +TEST(TimeTest, steady_time_is_compatible_with_steady_clock) { + steady_time t = steady_clock::now(); + (void) t; +} + +TEST(TimeTest, system_time_is_compatible_with_system_clock) { + system_time t = system_clock::now(); + (void) t; +} + +TEST(TimeTest, timer_can_measure_elapsed_time) { + Timer timer; + std::this_thread::sleep_for(10ms); + auto elapsed = timer.elapsed(); + EXPECT_GE(elapsed, 10ms); + fprintf(stderr, "sleep(10ms) took %ld us\n", count_us(elapsed)); +} + +TEST(TimeTest, double_conversion_works_as_expected) { + EXPECT_EQ(to_s(10ms), 0.010); + EXPECT_EQ(10ms, from_s(0.010)); +} + +TEST(TimeTest, unit_counting_works_as_expected) { + auto d = 3ms + 5us + 7ns; + EXPECT_EQ(count_ns(d), 3005007); + EXPECT_EQ(count_us(d), 3005); + EXPECT_EQ(count_ms(d), 3); +} + +GTEST_MAIN_RUN_ALL_TESTS() diff --git a/vespalib/src/tests/time_tracker/.gitignore b/vespalib/src/tests/time_tracker/.gitignore deleted file mode 100644 index b6275ecd945..00000000000 --- a/vespalib/src/tests/time_tracker/.gitignore +++ /dev/null @@ -1 +0,0 @@ -vespalib_time_tracker_test_app diff --git a/vespalib/src/tests/time_tracker/CMakeLists.txt b/vespalib/src/tests/time_tracker/CMakeLists.txt deleted file mode 100644 index a4eae0c7aaf..00000000000 --- a/vespalib/src/tests/time_tracker/CMakeLists.txt +++ /dev/null @@ -1,8 +0,0 @@ -# Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. -vespa_add_executable(vespalib_time_tracker_test_app TEST - SOURCES - time_tracker_test.cpp - DEPENDS - vespalib -) -vespa_add_test(NAME vespalib_time_tracker_test_app COMMAND vespalib_time_tracker_test_app) diff --git a/vespalib/src/tests/time_tracker/time_tracker_test.cpp b/vespalib/src/tests/time_tracker/time_tracker_test.cpp deleted file mode 100644 index 653c47e8484..00000000000 --- a/vespalib/src/tests/time_tracker/time_tracker_test.cpp +++ /dev/null @@ -1,93 +0,0 @@ -// Copyright 2017 Yahoo Holdings. 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/util/time_tracker.h> -#include <vespa/vespalib/util/stringfmt.h> - -using namespace vespalib; - -size_t count(const std::string &token, const vespalib::string &str) { - size_t cnt = 0; - for (size_t pos = str.find(token); pos != str.npos; pos = str.find(token, pos + 1)) { - ++cnt; - } - return cnt; -} - -void do_stuff(size_t n) { - vespalib::string data; - for (size_t i = 0; i < n; ++i) { - data.append(make_string("%zu%zu", i, i)); - } -} - -TEST("require that thread aware time tracking works") { - TimeTracker outer_tt(2); - TimeTracker medio_tt(0); - TimeTracker inner_tt(3); - { - TIMED_THREAD(outer_tt); - TIMED("foo", do_stuff(100)); - TIMED("bar", do_stuff(200)); - TIMED("baz", do_stuff(300)); - { - TIMED_SCOPE("foo"); - do_stuff(100); - { - { - TIMED_THREAD(medio_tt); - TIMED("ignore", do_stuff(100)); // max_level == 0 - TIMED("ignore", do_stuff(200)); // max_level == 0 - TIMED("ignore", do_stuff(300)); // max_level == 0 - { - TIMED_THREAD(inner_tt); - TIMED("foo", do_stuff(100)); - TIMED("bar", do_stuff(200)); - TIMED("baz", do_stuff(300)); - { - TIMED_SCOPE("foo"); - do_stuff(100); - { - TIMED_SCOPE("bar"); - do_stuff(200); - { - TIMED_SCOPE("baz"); - do_stuff(300); - } - } - } - } - } - TIMED_SCOPE("bar"); - do_stuff(200); - { - TIMED_SCOPE("ignore"); // below max level - TIMED("ignore", do_stuff(100)); // below max level - TIMED("ignore", do_stuff(200)); // below max level - TIMED("ignore", do_stuff(300)); // below max level - } - } - } - } - TIMED("ignore", do_stuff(100)); // outside - TIMED("ignore", do_stuff(200)); // outside - TIMED("ignore", do_stuff(300)); // outside - fprintf(stderr, "outer stats: \n%s\n", outer_tt.get_stats().c_str()); - EXPECT_EQUAL(2u, count("foo:", outer_tt.get_stats())); - EXPECT_EQUAL(2u, count("bar:", outer_tt.get_stats())); - EXPECT_EQUAL(1u, count("baz:", outer_tt.get_stats())); - EXPECT_EQUAL(3u, count("foo", outer_tt.get_stats())); - EXPECT_EQUAL(2u, count("bar", outer_tt.get_stats())); - EXPECT_EQUAL(0u, count("ignore", outer_tt.get_stats())); - EXPECT_EQUAL(5u, count("\n", outer_tt.get_stats())); - EXPECT_EQUAL("", medio_tt.get_stats()); - fprintf(stderr, "inner stats: \n%s\n", inner_tt.get_stats().c_str()); - EXPECT_EQUAL(2u, count("foo:", inner_tt.get_stats())); - EXPECT_EQUAL(2u, count("bar:", inner_tt.get_stats())); - EXPECT_EQUAL(2u, count("baz:", inner_tt.get_stats())); - EXPECT_EQUAL(4u, count("foo", inner_tt.get_stats())); - EXPECT_EQUAL(3u, count("bar", inner_tt.get_stats())); - EXPECT_EQUAL(0u, count("ignore", inner_tt.get_stats())); - EXPECT_EQUAL(6u, count("\n", inner_tt.get_stats())); -} - -TEST_MAIN() { TEST_RUN_ALL(); } diff --git a/vespalib/src/vespa/vespalib/util/CMakeLists.txt b/vespalib/src/vespa/vespalib/util/CMakeLists.txt index 6bbe61170fb..da81556bb61 100644 --- a/vespalib/src/vespa/vespalib/util/CMakeLists.txt +++ b/vespalib/src/vespa/vespalib/util/CMakeLists.txt @@ -11,8 +11,8 @@ vespa_add_library(vespalib_vespalib_util OBJECT barrier.cpp benchmark_timer.cpp blockingthreadstackexecutor.cpp - bufferwriter.cpp box.cpp + bufferwriter.cpp classname.cpp closuretask.cpp compress.cpp @@ -52,7 +52,7 @@ vespa_add_library(vespalib_vespalib_util OBJECT thread_bundle.cpp threadstackexecutor.cpp threadstackexecutorbase.cpp - time_tracker.cpp + time.cpp valgrind.cpp zstdcompressor.cpp DEPENDS diff --git a/vespalib/src/vespa/vespalib/util/time.cpp b/vespalib/src/vespa/vespalib/util/time.cpp new file mode 100644 index 00000000000..d38e40a6d6a --- /dev/null +++ b/vespalib/src/vespa/vespalib/util/time.cpp @@ -0,0 +1,9 @@ +// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +#include "time.h" + +namespace vespalib { + +Timer::~Timer() = default; + +} diff --git a/vespalib/src/vespa/vespalib/util/time.h b/vespalib/src/vespa/vespalib/util/time.h new file mode 100644 index 00000000000..bab410f040d --- /dev/null +++ b/vespalib/src/vespa/vespalib/util/time.h @@ -0,0 +1,53 @@ +// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +#pragma once + +#include <chrono> + +using namespace std::literals::chrono_literals; + +namespace vespalib { + +using steady_clock = std::chrono::steady_clock; +using steady_time = std::chrono::steady_clock::time_point; + +using system_clock = std::chrono::system_clock; +using system_time = std::chrono::system_clock::time_point; + +using duration = std::chrono::nanoseconds; + +constexpr double to_s(duration d) { + return std::chrono::duration_cast<std::chrono::duration<double>>(d).count(); +} + +constexpr duration from_s(double seconds) { + return std::chrono::duration_cast<duration>(std::chrono::duration<double>(seconds)); +} + +constexpr int64_t count_ms(duration d) { + return std::chrono::duration_cast<std::chrono::milliseconds>(d).count(); +} + +constexpr int64_t count_us(duration d) { + return std::chrono::duration_cast<std::chrono::microseconds>(d).count(); +} + +constexpr int64_t count_ns(duration d) { + return std::chrono::duration_cast<std::chrono::nanoseconds>(d).count(); +} + +/** + * Simple utility class used to measure how much time has elapsed + * since it was constructed. + **/ +class Timer +{ +private: + steady_time _start; +public: + Timer() : _start(steady_clock::now()) {} + ~Timer(); + duration elapsed() const { return (steady_clock::now() - _start); } +}; + +} diff --git a/vespalib/src/vespa/vespalib/util/time_tracker.cpp b/vespalib/src/vespa/vespalib/util/time_tracker.cpp deleted file mode 100644 index 78ad6825117..00000000000 --- a/vespalib/src/vespa/vespalib/util/time_tracker.cpp +++ /dev/null @@ -1,93 +0,0 @@ -// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. - -#include "time_tracker.h" -#include "stringfmt.h" -#include <cassert> - -namespace vespalib { - -TimeTracker::Task::~Task() { } - -TimeTracker::TimeTracker(uint32_t max_level_in) - : _tasks(), - _current_level(0), - _max_level(max_level_in) -{ } - -TimeTracker::~TimeTracker() { - assert(_current_level == 0); -} - -void -TimeTracker::build_stats_string(const std::vector<Task> &tasks, uint32_t level, - vespalib::string level_name, vespalib::string &out) -{ - for (auto task: tasks) { - vespalib::string name = (level == 0) - ? task.name - : make_string("%s.%s", level_name.c_str(), task.name.c_str()); - out.append(make_string("%*s%s: %g ms\n", (level * 4), "", name.c_str(), task.ms())); - build_stats_string(task.sub_tasks, (level + 1), name, out); - } -} - -std::vector<TimeTracker::Task> & -TimeTracker::find_tasks(std::vector<Task> &tasks, uint32_t level) { - if (level == 0) { - return tasks; - } - assert(!tasks.empty()); - return find_tasks(tasks.back().sub_tasks, (level - 1)); -} - -void -TimeTracker::open_task(const char *name) -{ - if (++_current_level <= _max_level) { - std::vector<TimeTracker::Task> &tasks = find_tasks(_tasks, (_current_level - 1)); - tasks.emplace_back(name); - } -} - -void -TimeTracker::close_task() -{ - assert(_current_level > 0); - if (--_current_level < _max_level) { - std::vector<TimeTracker::Task> &tasks = find_tasks(_tasks, _current_level); - assert(!tasks.empty()); - tasks.back().close_task(); - } -} - -vespalib::string -TimeTracker::get_stats() -{ - vespalib::string out; - build_stats_string(_tasks, 0, "", out); - return out; -} - -namespace time_tracker { - -__thread ThreadBinder *ThreadBinder::tl_current_binder = nullptr; - -ThreadBinder::ThreadBinder(TimeTracker &tracker_in) - : tracker(tracker_in), - parent_binder(tl_current_binder) -{ - tl_current_binder = (tracker.max_level() > 0)? this : nullptr; -} - -ThreadBinder::~ThreadBinder() { - if (tracker.max_level() > 0) { - assert(tl_current_binder == this); - } else { - assert(tl_current_binder == nullptr); - } - tl_current_binder = parent_binder; -} - -} // namespace vespalib::time_tracker - -} // namespace vespalib diff --git a/vespalib/src/vespa/vespalib/util/time_tracker.h b/vespalib/src/vespa/vespalib/util/time_tracker.h deleted file mode 100644 index 95dc8feb325..00000000000 --- a/vespalib/src/vespa/vespalib/util/time_tracker.h +++ /dev/null @@ -1,91 +0,0 @@ -// Copyright 2017 Yahoo Holdings. 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 <vector> -#include <vespa/fastos/timestamp.h> - -namespace vespalib { - -//----------------------------------------------------------------------------- - -class TimeTracker -{ -private: - struct Task { - vespalib::string name; - fastos::StopWatch task_time; - fastos::TimeStamp elapsed; - std::vector<Task> sub_tasks; - Task(const char *name_in) : name(name_in), task_time(), elapsed() { } - ~Task(); - void close_task() { elapsed = task_time.elapsed(); } - double ms() const { return elapsed.sec()*1000.0; } - }; - - std::vector<Task> _tasks; - uint32_t _current_level; - uint32_t _max_level; - - static void build_stats_string(const std::vector<Task> &tasks, uint32_t level, - vespalib::string level_name, vespalib::string &out); - static std::vector<Task> &find_tasks(std::vector<Task> &tasks, uint32_t level); - -public: - explicit TimeTracker(uint32_t max_level_in); - ~TimeTracker(); - uint32_t level() const { return _current_level; } - uint32_t max_level() const { return _max_level; } - void open_task(const char *name); - void close_task(); - vespalib::string get_stats(); -}; - -//----------------------------------------------------------------------------- - -namespace time_tracker { - -struct ThreadBinder { - TimeTracker &tracker; - ThreadBinder *parent_binder; - static __thread ThreadBinder *tl_current_binder; - ThreadBinder(ThreadBinder &&) = delete; - ThreadBinder(const ThreadBinder &) = delete; - explicit ThreadBinder(TimeTracker &tracker_in); - ~ThreadBinder(); -}; - -void open_task(const char *name) { - if (__builtin_expect(ThreadBinder::tl_current_binder != nullptr, false)) { - ThreadBinder::tl_current_binder->tracker.open_task(name); - } -} - -void close_task() { - if (__builtin_expect(ThreadBinder::tl_current_binder != nullptr, false)) { - ThreadBinder::tl_current_binder->tracker.close_task(); - } -} - -struct Scope { - Scope(Scope &&) = delete; - Scope(const Scope &) = delete; - Scope(const char *name) { open_task(name); } - ~Scope() { close_task(); } -}; - -} // namespace vespalib::time_tracker - -//----------------------------------------------------------------------------- - -#define TIMED_CAT_IMPL(a, b) a ## b -#define TIMED_CAT(a, b) TIMED_CAT_IMPL(a, b) -#define TIMED_THREAD(tracer) ::vespalib::time_tracker::ThreadBinder TIMED_CAT(timed_thread_, __LINE__)(tracer) -#define TIMED_SCOPE(name) ::vespalib::time_tracker::Scope TIMED_CAT(timed_scope_, __LINE__)(name) -#define TIMED(name, code) do { ::vespalib::time_tracker::open_task(name); code; ::vespalib::time_tracker::close_task(); } while(false) - -//----------------------------------------------------------------------------- - -} // namespace vespalib - |