[Lldb-commits] [lldb] r285890 - Refactor Timer class
Pavel Labath via lldb-commits
lldb-commits at lists.llvm.org
Thu Nov 3 02:14:10 PDT 2016
Author: labath
Date: Thu Nov 3 04:14:09 2016
New Revision: 285890
URL: http://llvm.org/viewvc/llvm-project?rev=285890&view=rev
Log:
Refactor Timer class
Summary:
While removing TimeValue from this class I noticed a lot of room for small
simplifications here. Main are:
- instead of complicated start-stop dances to compute own time, each Timer
just starts the timer once, and keeps track of the durations of child
timers. Then the own time can be computed at the end by subtracting the two
values.
- remove double accounting in TimerStack - the stack object already knows the
number of timers.
The interface does not lend itself well to unit testing, but I have added a
couple of tests which can (and did) catch any obvious errors.
Reviewers: tberghammer, clayborg
Subscribers: mgorny, lldb-commits
Differential Revision: https://reviews.llvm.org/D26243
Added:
lldb/trunk/unittests/Core/TimerTest.cpp
Modified:
lldb/trunk/include/lldb/Core/Timer.h
lldb/trunk/source/Core/Timer.cpp
lldb/trunk/unittests/Core/CMakeLists.txt
Modified: lldb/trunk/include/lldb/Core/Timer.h
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/include/lldb/Core/Timer.h?rev=285890&r1=285889&r2=285890&view=diff
==============================================================================
--- lldb/trunk/include/lldb/Core/Timer.h (original)
+++ lldb/trunk/include/lldb/Core/Timer.h Thu Nov 3 04:14:09 2016
@@ -20,8 +20,8 @@
// Other libraries and framework includes
// Project includes
-#include "lldb/Host/TimeValue.h"
#include "lldb/lldb-private.h"
+#include "llvm/Support/Chrono.h"
namespace lldb_private {
@@ -61,27 +61,17 @@ public:
static void ResetCategoryTimes();
protected:
- void ChildStarted(const TimeValue &time);
-
- void ChildStopped(const TimeValue &time);
-
- uint64_t GetTotalElapsedNanoSeconds();
-
- uint64_t GetTimerElapsedNanoSeconds();
+ using TimePoint = std::chrono::steady_clock::time_point;
+ void ChildDuration(TimePoint::duration dur) { m_child_duration += dur; }
const char *m_category;
- TimeValue m_total_start;
- TimeValue m_timer_start;
- uint64_t m_total_ticks; // Total running time for this timer including when
- // other timers below this are running
- uint64_t m_timer_ticks; // Ticks for this timer that do not include when other
- // timers below this one are running
+ TimePoint m_total_start;
+ TimePoint::duration m_child_duration{0};
static std::atomic<bool> g_quiet;
static std::atomic<unsigned> g_display_depth;
private:
- Timer();
DISALLOW_COPY_AND_ASSIGN(Timer);
};
Modified: lldb/trunk/source/Core/Timer.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/source/Core/Timer.cpp?rev=285890&r1=285889&r2=285890&view=diff
==============================================================================
--- lldb/trunk/source/Core/Timer.cpp (original)
+++ lldb/trunk/source/Core/Timer.cpp Thu Nov 3 04:14:09 2016
@@ -23,26 +23,14 @@ using namespace lldb_private;
#define TIMER_INDENT_AMOUNT 2
namespace {
-typedef std::map<const char *, uint64_t> TimerCategoryMap;
-
-struct TimerStack {
- TimerStack() : m_depth(0) {}
-
- uint32_t m_depth;
- std::vector<Timer *> m_stack;
-};
+typedef std::map<const char *, std::chrono::nanoseconds> TimerCategoryMap;
+typedef std::vector<Timer *> TimerStack;
} // end of anonymous namespace
std::atomic<bool> Timer::g_quiet(true);
std::atomic<unsigned> Timer::g_display_depth(0);
static std::mutex &GetFileMutex() {
- static std::mutex *g_file_mutex_ptr = nullptr;
- static std::once_flag g_once_flag;
- std::call_once(g_once_flag, []() {
- // leaked on purpose to ensure this mutex works after main thread has run
- // global C++ destructor chain
- g_file_mutex_ptr = new std::mutex();
- });
+ static std::mutex *g_file_mutex_ptr = new std::mutex();
return *g_file_mutex_ptr;
}
@@ -75,111 +63,58 @@ static TimerStack *GetTimerStackForCurre
void Timer::SetQuiet(bool value) { g_quiet = value; }
Timer::Timer(const char *category, const char *format, ...)
- : m_category(category), m_total_start(), m_timer_start(), m_total_ticks(0),
- m_timer_ticks(0) {
+ : m_category(category), m_total_start(std::chrono::steady_clock::now()) {
TimerStack *stack = GetTimerStackForCurrentThread();
if (!stack)
return;
- if (stack->m_depth++ < g_display_depth) {
- if (g_quiet == false) {
- std::lock_guard<std::mutex> lock(GetFileMutex());
-
- // Indent
- ::fprintf(stdout, "%*s", stack->m_depth * TIMER_INDENT_AMOUNT, "");
- // Print formatted string
- va_list args;
- va_start(args, format);
- ::vfprintf(stdout, format, args);
- va_end(args);
-
- // Newline
- ::fprintf(stdout, "\n");
- }
- TimeValue start_time(TimeValue::Now());
- m_total_start = start_time;
- m_timer_start = start_time;
-
- if (!stack->m_stack.empty())
- stack->m_stack.back()->ChildStarted(start_time);
- stack->m_stack.push_back(this);
+ stack->push_back(this);
+ if (g_quiet && stack->size() <= g_display_depth) {
+ std::lock_guard<std::mutex> lock(GetFileMutex());
+
+ // Indent
+ ::fprintf(stdout, "%*s", int(stack->size() - 1) * TIMER_INDENT_AMOUNT, "");
+ // Print formatted string
+ va_list args;
+ va_start(args, format);
+ ::vfprintf(stdout, format, args);
+ va_end(args);
+
+ // Newline
+ ::fprintf(stdout, "\n");
}
}
Timer::~Timer() {
+ using namespace std::chrono;
+
TimerStack *stack = GetTimerStackForCurrentThread();
if (!stack)
return;
- if (m_total_start.IsValid()) {
- TimeValue stop_time = TimeValue::Now();
- if (m_total_start.IsValid()) {
- m_total_ticks += (stop_time - m_total_start);
- m_total_start.Clear();
- }
- if (m_timer_start.IsValid()) {
- m_timer_ticks += (stop_time - m_timer_start);
- m_timer_start.Clear();
- }
-
- assert(stack->m_stack.back() == this);
- stack->m_stack.pop_back();
- if (stack->m_stack.empty() == false)
- stack->m_stack.back()->ChildStopped(stop_time);
-
- const uint64_t total_nsec_uint = GetTotalElapsedNanoSeconds();
- const uint64_t timer_nsec_uint = GetTimerElapsedNanoSeconds();
- const double total_nsec = total_nsec_uint;
- const double timer_nsec = timer_nsec_uint;
-
- if (g_quiet == false) {
- std::lock_guard<std::mutex> lock(GetFileMutex());
- ::fprintf(stdout, "%*s%.9f sec (%.9f sec)\n",
- (stack->m_depth - 1) * TIMER_INDENT_AMOUNT, "",
- total_nsec / 1000000000.0, timer_nsec / 1000000000.0);
- }
+ auto stop_time = steady_clock::now();
+ auto total_dur = stop_time - m_total_start;
+ auto timer_dur = total_dur - m_child_duration;
+
+ if (g_quiet && stack->size() <= g_display_depth) {
+ std::lock_guard<std::mutex> lock(GetFileMutex());
+ ::fprintf(stdout, "%*s%.9f sec (%.9f sec)\n",
+ int(stack->size() - 1) * TIMER_INDENT_AMOUNT, "",
+ duration<double>(total_dur).count(),
+ duration<double>(timer_dur).count());
+ }
+
+ assert(stack->back() == this);
+ stack->pop_back();
+ if (!stack->empty())
+ stack->back()->ChildDuration(total_dur);
- // Keep total results for each category so we can dump results.
+ // Keep total results for each category so we can dump results.
+ {
std::lock_guard<std::mutex> guard(GetCategoryMutex());
TimerCategoryMap &category_map = GetCategoryMap();
- category_map[m_category] += timer_nsec_uint;
+ category_map[m_category] += timer_dur;
}
- if (stack->m_depth > 0)
- --stack->m_depth;
-}
-
-uint64_t Timer::GetTotalElapsedNanoSeconds() {
- uint64_t total_ticks = m_total_ticks;
-
- // If we are currently running, we need to add the current
- // elapsed time of the running timer...
- if (m_total_start.IsValid())
- total_ticks += (TimeValue::Now() - m_total_start);
-
- return total_ticks;
-}
-
-uint64_t Timer::GetTimerElapsedNanoSeconds() {
- uint64_t timer_ticks = m_timer_ticks;
-
- // If we are currently running, we need to add the current
- // elapsed time of the running timer...
- if (m_timer_start.IsValid())
- timer_ticks += (TimeValue::Now() - m_timer_start);
-
- return timer_ticks;
-}
-
-void Timer::ChildStarted(const TimeValue &start_time) {
- if (m_timer_start.IsValid()) {
- m_timer_ticks += (start_time - m_timer_start);
- m_timer_start.Clear();
- }
-}
-
-void Timer::ChildStopped(const TimeValue &stop_time) {
- if (!m_timer_start.IsValid())
- m_timer_start = stop_time;
}
void Timer::SetDisplayDepth(uint32_t depth) { g_display_depth = depth; }
@@ -212,8 +147,8 @@ void Timer::DumpCategoryTimes(Stream *s)
const size_t count = sorted_iterators.size();
for (size_t i = 0; i < count; ++i) {
- const double timer_nsec = sorted_iterators[i]->second;
- s->Printf("%.9f sec for %s\n", timer_nsec / 1000000000.0,
+ const auto timer = sorted_iterators[i]->second;
+ s->Printf("%.9f sec for %s\n", std::chrono::duration<double>(timer).count(),
sorted_iterators[i]->first);
}
}
Modified: lldb/trunk/unittests/Core/CMakeLists.txt
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/unittests/Core/CMakeLists.txt?rev=285890&r1=285889&r2=285890&view=diff
==============================================================================
--- lldb/trunk/unittests/Core/CMakeLists.txt (original)
+++ lldb/trunk/unittests/Core/CMakeLists.txt Thu Nov 3 04:14:09 2016
@@ -4,4 +4,5 @@ add_lldb_unittest(LLDBCoreTests
DataExtractorTest.cpp
ScalarTest.cpp
StructuredDataTest.cpp
+ TimerTest.cpp
)
Added: lldb/trunk/unittests/Core/TimerTest.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/unittests/Core/TimerTest.cpp?rev=285890&view=auto
==============================================================================
--- lldb/trunk/unittests/Core/TimerTest.cpp (added)
+++ lldb/trunk/unittests/Core/TimerTest.cpp Thu Nov 3 04:14:09 2016
@@ -0,0 +1,75 @@
+//===-- TimerTest.cpp -------------------------------------------*- C++ -*-===//
+//
+// The LLVM Compiler Infrastructure
+//
+// This file is distributed under the University of Illinois Open Source
+// License. See LICENSE.TXT for details.
+//
+//===----------------------------------------------------------------------===//
+
+#if defined(_MSC_VER) && (_HAS_EXCEPTIONS == 0)
+// Workaround for MSVC standard library bug, which fails to include <thread>
+// when exceptions are disabled.
+#include <eh.h>
+#endif
+
+#include "lldb/Core/Timer.h"
+#include "gtest/gtest.h"
+
+#include "lldb/Core/StreamString.h"
+#include <thread>
+
+using namespace lldb_private;
+
+TEST(TimerTest, CategoryTimes) {
+ Timer::ResetCategoryTimes();
+ {
+ Timer t("CAT1", "");
+ std::this_thread::sleep_for(std::chrono::milliseconds(10));
+ }
+ StreamString ss;
+ Timer::DumpCategoryTimes(&ss);
+ double seconds;
+ ASSERT_EQ(1, sscanf(ss.GetData(), "%lf sec for CAT1", &seconds));
+ EXPECT_LT(0.001, seconds);
+ EXPECT_GT(0.1, seconds);
+}
+
+TEST(TimerTest, CategoryTimesNested) {
+ Timer::ResetCategoryTimes();
+ {
+ Timer t1("CAT1", "");
+ std::this_thread::sleep_for(std::chrono::milliseconds(10));
+ {
+ Timer t2("CAT1", "");
+ std::this_thread::sleep_for(std::chrono::milliseconds(10));
+ }
+ }
+ StreamString ss;
+ Timer::DumpCategoryTimes(&ss);
+ double seconds;
+ ASSERT_EQ(1, sscanf(ss.GetData(), "%lf sec for CAT1", &seconds));
+ EXPECT_LT(0.002, seconds);
+ EXPECT_GT(0.2, seconds);
+}
+
+TEST(TimerTest, CategoryTimes2) {
+ Timer::ResetCategoryTimes();
+ {
+ Timer t1("CAT1", "");
+ std::this_thread::sleep_for(std::chrono::milliseconds(10));
+ {
+ Timer t2("CAT2", "");
+ std::this_thread::sleep_for(std::chrono::milliseconds(10));
+ }
+ }
+ StreamString ss;
+ Timer::DumpCategoryTimes(&ss);
+ double seconds1, seconds2;
+ ASSERT_EQ(2, sscanf(ss.GetData(), "%lf sec for CAT1%*[\n ]%lf sec for CAT2",
+ &seconds1, &seconds2));
+ EXPECT_LT(0.001, seconds1);
+ EXPECT_GT(0.1, seconds1);
+ EXPECT_LT(0.001, seconds2);
+ EXPECT_GT(0.1, seconds2);
+}
More information about the lldb-commits
mailing list