2010-06-09 00:52:24 +08:00
|
|
|
//===-- Timer.cpp -----------------------------------------------*- C++ -*-===//
|
|
|
|
//
|
2019-01-19 16:50:56 +08:00
|
|
|
// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
|
|
|
|
// See https://llvm.org/LICENSE.txt for license information.
|
|
|
|
// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
|
2010-06-09 00:52:24 +08:00
|
|
|
//
|
|
|
|
//===----------------------------------------------------------------------===//
|
2017-06-29 22:32:17 +08:00
|
|
|
#include "lldb/Utility/Timer.h"
|
2017-03-07 02:34:25 +08:00
|
|
|
#include "lldb/Utility/Stream.h"
|
|
|
|
|
2016-05-18 09:59:10 +08:00
|
|
|
#include <algorithm>
|
2010-06-09 00:52:24 +08:00
|
|
|
#include <map>
|
2016-05-18 09:59:10 +08:00
|
|
|
#include <mutex>
|
2018-11-12 07:16:43 +08:00
|
|
|
#include <utility>
|
2010-06-09 00:52:24 +08:00
|
|
|
#include <vector>
|
|
|
|
|
2018-11-12 07:16:43 +08:00
|
|
|
#include <assert.h>
|
|
|
|
#include <stdarg.h>
|
2010-06-09 16:50:27 +08:00
|
|
|
#include <stdio.h>
|
|
|
|
|
2010-06-09 00:52:24 +08:00
|
|
|
using namespace lldb_private;
|
|
|
|
|
|
|
|
#define TIMER_INDENT_AMOUNT 2
|
2015-10-23 18:34:29 +08:00
|
|
|
|
2016-09-07 04:57:50 +08:00
|
|
|
namespace {
|
2016-11-03 17:14:09 +08:00
|
|
|
typedef std::vector<Timer *> TimerStack;
|
2017-05-15 21:02:37 +08:00
|
|
|
static std::atomic<Timer::Category *> g_categories;
|
2015-10-23 18:34:29 +08:00
|
|
|
} // end of anonymous namespace
|
|
|
|
|
2015-10-23 18:53:31 +08:00
|
|
|
std::atomic<bool> Timer::g_quiet(true);
|
|
|
|
std::atomic<unsigned> Timer::g_display_depth(0);
|
2016-09-07 04:57:50 +08:00
|
|
|
static std::mutex &GetFileMutex() {
|
2016-11-03 17:14:09 +08:00
|
|
|
static std::mutex *g_file_mutex_ptr = new std::mutex();
|
2016-09-07 04:57:50 +08:00
|
|
|
return *g_file_mutex_ptr;
|
2016-03-25 05:46:47 +08:00
|
|
|
}
|
2015-10-23 18:34:29 +08:00
|
|
|
|
2017-06-20 16:11:43 +08:00
|
|
|
static TimerStack &GetTimerStackForCurrentThread() {
|
|
|
|
static thread_local TimerStack g_stack;
|
|
|
|
return g_stack;
|
2010-06-09 00:52:24 +08:00
|
|
|
}
|
|
|
|
|
2017-05-15 21:02:37 +08:00
|
|
|
Timer::Category::Category(const char *cat) : m_name(cat) {
|
|
|
|
m_nanos.store(0, std::memory_order_release);
|
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
llvm-svn: 361987
2019-05-30 00:31:32 +08:00
|
|
|
m_nanos_total.store(0, std::memory_order_release);
|
|
|
|
m_count.store(0, std::memory_order_release);
|
2017-05-15 21:02:37 +08:00
|
|
|
Category *expected = g_categories;
|
|
|
|
do {
|
|
|
|
m_next = expected;
|
|
|
|
} while (!g_categories.compare_exchange_weak(expected, this));
|
|
|
|
}
|
|
|
|
|
2016-09-07 04:57:50 +08:00
|
|
|
void Timer::SetQuiet(bool value) { g_quiet = value; }
|
|
|
|
|
2017-05-15 21:02:37 +08:00
|
|
|
Timer::Timer(Timer::Category &category, const char *format, ...)
|
2016-11-03 17:14:09 +08:00
|
|
|
: m_category(category), m_total_start(std::chrono::steady_clock::now()) {
|
2017-06-20 16:11:43 +08:00
|
|
|
TimerStack &stack = GetTimerStackForCurrentThread();
|
2016-09-07 04:57:50 +08:00
|
|
|
|
2017-06-20 16:11:43 +08:00
|
|
|
stack.push_back(this);
|
|
|
|
if (g_quiet && stack.size() <= g_display_depth) {
|
2016-11-03 17:14:09 +08:00
|
|
|
std::lock_guard<std::mutex> lock(GetFileMutex());
|
|
|
|
|
|
|
|
// Indent
|
2017-06-20 16:11:43 +08:00
|
|
|
::fprintf(stdout, "%*s", int(stack.size() - 1) * TIMER_INDENT_AMOUNT, "");
|
2016-11-03 17:14:09 +08:00
|
|
|
// Print formatted string
|
|
|
|
va_list args;
|
|
|
|
va_start(args, format);
|
|
|
|
::vfprintf(stdout, format, args);
|
|
|
|
va_end(args);
|
|
|
|
|
|
|
|
// Newline
|
|
|
|
::fprintf(stdout, "\n");
|
2016-09-07 04:57:50 +08:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
Timer::~Timer() {
|
2016-11-03 17:14:09 +08:00
|
|
|
using namespace std::chrono;
|
|
|
|
|
|
|
|
auto stop_time = steady_clock::now();
|
|
|
|
auto total_dur = stop_time - m_total_start;
|
|
|
|
auto timer_dur = total_dur - m_child_duration;
|
2010-06-09 00:52:24 +08:00
|
|
|
|
2017-06-20 16:11:43 +08:00
|
|
|
TimerStack &stack = GetTimerStackForCurrentThread();
|
|
|
|
if (g_quiet && stack.size() <= g_display_depth) {
|
2016-11-03 17:14:09 +08:00
|
|
|
std::lock_guard<std::mutex> lock(GetFileMutex());
|
|
|
|
::fprintf(stdout, "%*s%.9f sec (%.9f sec)\n",
|
2017-06-20 16:11:43 +08:00
|
|
|
int(stack.size() - 1) * TIMER_INDENT_AMOUNT, "",
|
2016-11-03 17:14:09 +08:00
|
|
|
duration<double>(total_dur).count(),
|
|
|
|
duration<double>(timer_dur).count());
|
|
|
|
}
|
2010-06-09 00:52:24 +08:00
|
|
|
|
2017-06-20 16:11:43 +08:00
|
|
|
assert(stack.back() == this);
|
|
|
|
stack.pop_back();
|
|
|
|
if (!stack.empty())
|
|
|
|
stack.back()->ChildDuration(total_dur);
|
2010-06-09 00:52:24 +08:00
|
|
|
|
2016-11-03 17:14:09 +08:00
|
|
|
// Keep total results for each category so we can dump results.
|
2017-05-15 21:02:37 +08:00
|
|
|
m_category.m_nanos += std::chrono::nanoseconds(timer_dur).count();
|
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
llvm-svn: 361987
2019-05-30 00:31:32 +08:00
|
|
|
m_category.m_nanos_total += std::chrono::nanoseconds(total_dur).count();
|
|
|
|
m_category.m_count++;
|
2010-06-09 00:52:24 +08:00
|
|
|
}
|
|
|
|
|
2016-09-07 04:57:50 +08:00
|
|
|
void Timer::SetDisplayDepth(uint32_t depth) { g_display_depth = depth; }
|
2010-06-09 00:52:24 +08:00
|
|
|
|
|
|
|
/* binary function predicate:
|
|
|
|
* - returns whether a person is less than another person
|
|
|
|
*/
|
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
llvm-svn: 361987
2019-05-30 00:31:32 +08:00
|
|
|
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;
|
2016-09-07 04:57:50 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
void Timer::ResetCategoryTimes() {
|
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
llvm-svn: 361987
2019-05-30 00:31:32 +08:00
|
|
|
for (Category *i = g_categories; i; i = i->m_next) {
|
2017-05-15 21:02:37 +08:00
|
|
|
i->m_nanos.store(0, std::memory_order_release);
|
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
llvm-svn: 361987
2019-05-30 00:31:32 +08:00
|
|
|
i->m_nanos_total.store(0, std::memory_order_release);
|
|
|
|
i->m_count.store(0, std::memory_order_release);
|
|
|
|
}
|
2016-09-07 04:57:50 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
void Timer::DumpCategoryTimes(Stream *s) {
|
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
llvm-svn: 361987
2019-05-30 00:31:32 +08:00
|
|
|
std::vector<Stats> sorted;
|
2017-05-15 21:02:37 +08:00
|
|
|
for (Category *i = g_categories; i; i = i->m_next) {
|
|
|
|
uint64_t nanos = i->m_nanos.load(std::memory_order_acquire);
|
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
llvm-svn: 361987
2019-05-30 00:31:32 +08:00
|
|
|
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);
|
|
|
|
}
|
2016-09-07 04:57:50 +08:00
|
|
|
}
|
2017-05-15 21:02:37 +08:00
|
|
|
if (sorted.empty())
|
|
|
|
return; // Later code will break without any elements.
|
|
|
|
|
|
|
|
// Sort by time
|
2019-01-09 07:25:06 +08:00
|
|
|
llvm::sort(sorted.begin(), sorted.end(), CategoryMapIteratorSortCriterion);
|
2017-05-15 21:02:37 +08:00
|
|
|
|
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
llvm-svn: 361987
2019-05-30 00:31:32 +08:00
|
|
|
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);
|
2010-06-09 16:50:27 +08:00
|
|
|
}
|