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,8 @@ friend class Timer; const char *m_name; std::atomic m_nanos; + std::atomic m_nanos_total; + 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,8 @@ 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_count.store(0, std::memory_order_release); Category *expected = g_categories; do { m_next = expected; @@ -93,6 +95,8 @@ // 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_count++; } void Timer::SetDisplayDepth(uint32_t depth) { g_display_depth = depth; } @@ -100,25 +104,38 @@ /* binary function predicate: * - returns whether a person is less than another person */ - -typedef std::pair TimerEntry; - -static bool CategoryMapIteratorSortCriterion(const TimerEntry &lhs, - const TimerEntry &rhs) { - return lhs.second > rhs.second; +namespace { +struct Stats { + const char *name; + uint64_t nanos; + uint64_t nanos_total; + uint64_t count; +}; +} // namespace + +static bool CategoryMapIteratorSortCriterion(const Stats &lhs, + const Stats &rhs) { + return lhs.nanos > rhs.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_count.store(0, std::memory_order_release); + } } void Timer::DumpCategoryTimes(Stream *s) { - std::vector sorted; + std::vector sorted; for (Category *i = g_categories; i; i = i->m_next) { uint64_t nanos = i->m_nanos.load(std::memory_order_acquire); - if (nanos) - sorted.push_back(std::make_pair(i->m_name, nanos)); + if (nanos) { + uint64_t nanos_total = i->m_nanos_total.load(std::memory_order_acquire); + uint64_t count = i->m_count.load(std::memory_order_acquire); + Stats stats{i->m_name, nanos, nanos_total, count}; + sorted.push_back(stats); + } } if (sorted.empty()) return; // Later code will break without any elements. @@ -126,6 +143,9 @@ // Sort by time llvm::sort(sorted.begin(), sorted.end(), CategoryMapIteratorSortCriterion); - for (const auto &timer : sorted) - s->Printf("%.9f sec for %s\n", timer.second / 1000000000., timer.first); + for (const auto &stats : sorted) + s->Printf("%.9f sec (total: %.3fs; child: %.3fs; count: %llu) for %s\n", + stats.nanos / 1000000000., stats.nanos_total / 1000000000., + (stats.nanos_total - stats.nanos) / 1000000000., stats.count, + stats.name); } 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,38 @@ 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.105202764 sec (total: 0.132s; child: 0.027s; count: 1) for CAT1 + // 0.026772798 sec (total: 0.027s; child: 0.000s; 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_NEAR(total1 - child1, seconds1, 0.002); + EXPECT_EQ(1, count1); + EXPECT_NEAR(child1, seconds2, 0.002); + EXPECT_EQ(2, count2); +}