[Lldb-commits] [lldb] r361987 - Add more information to the log timer dump
Antonio Afonso via lldb-commits
lldb-commits at lists.llvm.org
Wed May 29 09:31:32 PDT 2019
Author: aadsm
Date: Wed May 29 09:31:32 2019
New Revision: 361987
URL: http://llvm.org/viewvc/llvm-project?rev=361987&view=rev
Log:
Add more information to the log timer dump
Summary:
The `log timer dump` is showing the time of the function itself minus any function that is called from this one that also happens to be timed. However, this is really not obvious and it also makes it hard to understand the time spent in total and also which children are actually taking the time.
To get a better reading of the timer dump I added the total, children (which I named child) and also the hit count. I used these timers to figure out a performance issue and only after adding this things were more clear to me.
It looks like this:
```
(lldb) log timer dump
35.447713617 sec (total: 35.449s; child: 0.001s; count: 1374) for void SymbolFileDWARF::Index()
29.717921481 sec (total: 29.718s; child: 0.000s; count: 8230500) for const lldb_private::ConstString &lldb_private::Mangled::GetDemangledName(lldb::LanguageType) const
21.049508865 sec (total: 24.683s; child: 3.633s; count: 1399) for void lldb_private::Symtab::InitNameIndexes()
...
```
Reviewers: clayborg, teemperor, labath, espindola, xiaobai
Reviewed By: labath, xiaobai
Subscribers: emaste, mgorny, arichardson, eraman, MaskRay, jdoerfert, labath, davide, teemperor, aprantl, erik.pilkington, jfb, abidh, lldb-commits
Tags: #lldb
Differential Revision: https://reviews.llvm.org/D61235
Modified:
lldb/trunk/include/lldb/Utility/Timer.h
lldb/trunk/source/Utility/Timer.cpp
lldb/trunk/unittests/Utility/TimerTest.cpp
Modified: lldb/trunk/include/lldb/Utility/Timer.h
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/include/lldb/Utility/Timer.h?rev=361987&r1=361986&r2=361987&view=diff
==============================================================================
--- lldb/trunk/include/lldb/Utility/Timer.h (original)
+++ lldb/trunk/include/lldb/Utility/Timer.h Wed May 29 09:31:32 2019
@@ -30,6 +30,8 @@ public:
friend class Timer;
const char *m_name;
std::atomic<uint64_t> m_nanos;
+ std::atomic<uint64_t> m_nanos_total;
+ std::atomic<uint64_t> m_count;
std::atomic<Category *> m_next;
DISALLOW_COPY_AND_ASSIGN(Category);
Modified: lldb/trunk/source/Utility/Timer.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/source/Utility/Timer.cpp?rev=361987&r1=361986&r2=361987&view=diff
==============================================================================
--- lldb/trunk/source/Utility/Timer.cpp (original)
+++ lldb/trunk/source/Utility/Timer.cpp Wed May 29 09:31:32 2019
@@ -41,6 +41,8 @@ static TimerStack &GetTimerStackForCurre
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 @@ Timer::~Timer() {
// 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 @@ void Timer::SetDisplayDepth(uint32_t dep
/* binary function predicate:
* - returns whether a person is less than another person
*/
-
-typedef std::pair<const char *, uint64_t> 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<TimerEntry> sorted;
+ std::vector<Stats> 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 @@ void Timer::DumpCategoryTimes(Stream *s)
// 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);
}
Modified: lldb/trunk/unittests/Utility/TimerTest.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/unittests/Utility/TimerTest.cpp?rev=361987&r1=361986&r2=361987&view=diff
==============================================================================
--- lldb/trunk/unittests/Utility/TimerTest.cpp (original)
+++ lldb/trunk/unittests/Utility/TimerTest.cpp Wed May 29 09:31:32 2019
@@ -61,7 +61,9 @@ TEST(TimerTest, CategoryTimes2) {
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 @@ TEST(TimerTest, CategoryTimes2) {
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);
+}
More information about the lldb-commits
mailing list