aadsm created this revision.
aadsm added a reviewer: clayborg.
Herald added subscribers: lldb-commits, abidh, jfb, erik.pilkington, aprantl.
Herald added a project: LLDB.
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()
...
Repository:
rLLDB LLDB
https://reviews.llvm.org/D61235
Files:
lldb/include/lldb/Utility/Timer.h
lldb/source/Utility/Timer.cpp
Index: lldb/source/Utility/Timer.cpp
===================================================================
--- lldb/source/Utility/Timer.cpp
+++ 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<const char *, uint64_t> TimerEntry;
+struct Stats {
+ uint64_t nanos;
+ uint64_t nanos_total;
+ uint64_t nanos_child;
+ uint64_t count;
+};
+typedef std::pair<const char *, Stats> 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<TimerEntry> 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);
}
Index: lldb/include/lldb/Utility/Timer.h
===================================================================
--- lldb/include/lldb/Utility/Timer.h
+++ lldb/include/lldb/Utility/Timer.h
@@ -30,6 +30,9 @@
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_nanos_child;
+ std::atomic<uint64_t> m_count;
std::atomic<Category *> m_next;
DISALLOW_COPY_AND_ASSIGN(Category);
Index: lldb/source/Utility/Timer.cpp
===================================================================
--- lldb/source/Utility/Timer.cpp
+++ 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<const char *, uint64_t> TimerEntry;
+struct Stats {
+ uint64_t nanos;
+ uint64_t nanos_total;
+ uint64_t nanos_child;
+ uint64_t count;
+};
+typedef std::pair<const char *, Stats> 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<TimerEntry> 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);
}
Index: lldb/include/lldb/Utility/Timer.h
===================================================================
--- lldb/include/lldb/Utility/Timer.h
+++ lldb/include/lldb/Utility/Timer.h
@@ -30,6 +30,9 @@
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_nanos_child;
+ std::atomic<uint64_t> m_count;
std::atomic<Category *> m_next;
DISALLOW_COPY_AND_ASSIGN(Category);
_______________________________________________
lldb-commits mailing list
lldb-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-commits
