Index: lldb/trunk/include/lldb/Core/Timer.h =================================================================== --- lldb/trunk/include/lldb/Core/Timer.h +++ lldb/trunk/include/lldb/Core/Timer.h @@ -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 @@ 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 g_quiet; static std::atomic g_display_depth; private: - Timer(); DISALLOW_COPY_AND_ASSIGN(Timer); }; Index: lldb/trunk/source/Core/Timer.cpp =================================================================== --- lldb/trunk/source/Core/Timer.cpp +++ lldb/trunk/source/Core/Timer.cpp @@ -23,26 +23,14 @@ #define TIMER_INDENT_AMOUNT 2 namespace { -typedef std::map TimerCategoryMap; - -struct TimerStack { - TimerStack() : m_depth(0) {} - - uint32_t m_depth; - std::vector m_stack; -}; +typedef std::map TimerCategoryMap; +typedef std::vector TimerStack; } // end of anonymous namespace std::atomic Timer::g_quiet(true); std::atomic 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 @@ 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 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 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 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 lock(GetFileMutex()); + ::fprintf(stdout, "%*s%.9f sec (%.9f sec)\n", + int(stack->size() - 1) * TIMER_INDENT_AMOUNT, "", + duration(total_dur).count(), + duration(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 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 @@ 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(timer).count(), sorted_iterators[i]->first); } } Index: lldb/trunk/unittests/Core/CMakeLists.txt =================================================================== --- lldb/trunk/unittests/Core/CMakeLists.txt +++ lldb/trunk/unittests/Core/CMakeLists.txt @@ -4,4 +4,5 @@ DataExtractorTest.cpp ScalarTest.cpp StructuredDataTest.cpp + TimerTest.cpp ) Index: lldb/trunk/unittests/Core/TimerTest.cpp =================================================================== --- lldb/trunk/unittests/Core/TimerTest.cpp +++ lldb/trunk/unittests/Core/TimerTest.cpp @@ -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 +// when exceptions are disabled. +#include +#endif + +#include "lldb/Core/Timer.h" +#include "gtest/gtest.h" + +#include "lldb/Core/StreamString.h" +#include + +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); +}