diff --git a/lldb/include/lldb/Utility/Timer.h b/lldb/include/lldb/Utility/Timer.h --- a/lldb/include/lldb/Utility/Timer.h +++ b/lldb/include/lldb/Utility/Timer.h @@ -30,6 +30,9 @@ friend class Timer; const char *m_name; std::atomic m_nanos; + std::atomic m_nanos_total; + std::atomic m_nanos_child; + std::atomic m_count; std::atomic m_next; DISALLOW_COPY_AND_ASSIGN(Category); diff --git a/lldb/source/Utility/Timer.cpp b/lldb/source/Utility/Timer.cpp --- a/lldb/source/Utility/Timer.cpp +++ b/lldb/source/Utility/Timer.cpp @@ -41,6 +41,9 @@ Timer::Category::Category(const char *cat) : m_name(cat) { m_nanos.store(0, std::memory_order_release); + m_nanos_total.store(0, std::memory_order_release); + m_nanos_child.store(0, std::memory_order_release); + m_count.store(0, std::memory_order_release); Category *expected = g_categories; do { m_next = expected; @@ -93,6 +96,10 @@ // Keep total results for each category so we can dump results. m_category.m_nanos += std::chrono::nanoseconds(timer_dur).count(); + m_category.m_nanos_total += std::chrono::nanoseconds(total_dur).count(); + m_category.m_nanos_child += + std::chrono::nanoseconds(m_child_duration).count(); + m_category.m_count++; } void Timer::SetDisplayDepth(uint32_t depth) { g_display_depth = depth; } @@ -101,24 +108,38 @@ * - returns whether a person is less than another person */ -typedef std::pair TimerEntry; +struct Stats { + uint64_t nanos; + uint64_t nanos_total; + uint64_t nanos_child; + uint64_t count; +}; +typedef std::pair TimerEntry; static bool CategoryMapIteratorSortCriterion(const TimerEntry &lhs, const TimerEntry &rhs) { - return lhs.second > rhs.second; + return lhs.second.nanos > rhs.second.nanos; } void Timer::ResetCategoryTimes() { - for (Category *i = g_categories; i; i = i->m_next) + for (Category *i = g_categories; i; i = i->m_next) { i->m_nanos.store(0, std::memory_order_release); + i->m_nanos_total.store(0, std::memory_order_release); + i->m_nanos_child.store(0, std::memory_order_release); + i->m_count.store(0, std::memory_order_release); + } } void Timer::DumpCategoryTimes(Stream *s) { std::vector sorted; for (Category *i = g_categories; i; i = i->m_next) { uint64_t nanos = i->m_nanos.load(std::memory_order_acquire); + uint64_t nanos_total = i->m_nanos_total.load(std::memory_order_acquire); + uint64_t nanos_child = i->m_nanos_child.load(std::memory_order_acquire); + uint64_t count = i->m_count.load(std::memory_order_acquire); + Stats stats{nanos, nanos_total, nanos_child, count}; if (nanos) - sorted.push_back(std::make_pair(i->m_name, nanos)); + sorted.push_back(std::make_pair(i->m_name, stats)); } if (sorted.empty()) return; // Later code will break without any elements. @@ -127,5 +148,9 @@ llvm::sort(sorted.begin(), sorted.end(), CategoryMapIteratorSortCriterion); for (const auto &timer : sorted) - s->Printf("%.9f sec for %s\n", timer.second / 1000000000., timer.first); + s->Printf("%.9f sec (total: %.3fs; child: %.3fs; count: %llu) for %s\n", + timer.second.nanos / 1000000000., + timer.second.nanos_total / 1000000000., + timer.second.nanos_child / 1000000000., timer.second.count, + timer.first); } diff --git a/lldb/unittests/Utility/TimerTest.cpp b/lldb/unittests/Utility/TimerTest.cpp --- a/lldb/unittests/Utility/TimerTest.cpp +++ b/lldb/unittests/Utility/TimerTest.cpp @@ -61,7 +61,9 @@ StreamString ss; Timer::DumpCategoryTimes(&ss); double seconds1, seconds2; - ASSERT_EQ(2, sscanf(ss.GetData(), "%lf sec for CAT1%*[\n ]%lf sec for CAT2", + ASSERT_EQ(2, sscanf(ss.GetData(), + "%lf sec (total: %*lfs; child: %*lfs; count: %*d) for " + "CAT1%*[\n ]%lf sec for CAT2", &seconds1, &seconds2)) << "String: " << ss.GetData(); EXPECT_LT(0.01, seconds1); @@ -69,3 +71,36 @@ EXPECT_LT(0.001, seconds2); EXPECT_GT(0.1, seconds2); } + +TEST(TimerTest, CategoryTimesStats) { + Timer::ResetCategoryTimes(); + { + static Timer::Category tcat1("CAT1"); + Timer t1(tcat1, "."); + std::this_thread::sleep_for(std::chrono::milliseconds(100)); + static Timer::Category tcat2("CAT2"); + Timer t2(tcat2, "."); + std::this_thread::sleep_for(std::chrono::milliseconds(10)); + Timer t3(tcat2, "."); + std::this_thread::sleep_for(std::chrono::milliseconds(10)); + } + // Example output: + // 0.102982273 sec (total: 0.126s; child: 0.023s; count: 1) for CAT1 + // 0.023058228 sec (total: 0.036s; child: 0.012s; count: 2) for CAT2 + StreamString ss; + Timer::DumpCategoryTimes(&ss); + double seconds1, total1, child1, seconds2; + int count1, count2; + ASSERT_EQ( + 6, sscanf(ss.GetData(), + "%lf sec (total: %lfs; child: %lfs; count: %d) for CAT1%*[\n " + "]%lf sec (total: %*lfs; child: %*lfs; count: %d) for CAT2", + &seconds1, &total1, &child1, &count1, &seconds2, &count2)) + << "String: " << ss.GetData(); + EXPECT_GT(total1 - child1, seconds1 - 0.001); + EXPECT_LT(total1 - child1, seconds1 + 0.001); + EXPECT_EQ(1, count1); + EXPECT_GT(child1, seconds2 - 0.001); + EXPECT_LT(child1, seconds2 + 0.001); + EXPECT_EQ(2, count2); +}