Merge branch 'master' into balder/milliseconds-in-config-rebased-1

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
-