2019-03-30 16:42:48 +08:00
|
|
|
//===-- TimeProfiler.cpp - Hierarchical Time Profiler ---------------------===//
|
|
|
|
//
|
2019-04-16 05:02:47 +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
|
2019-03-30 16:42:48 +08:00
|
|
|
//
|
|
|
|
//===----------------------------------------------------------------------===//
|
|
|
|
//
|
2019-04-16 05:02:47 +08:00
|
|
|
// This file implements hierarchical time profiler.
|
2019-03-30 16:42:48 +08:00
|
|
|
//
|
|
|
|
//===----------------------------------------------------------------------===//
|
|
|
|
|
|
|
|
#include "llvm/Support/TimeProfiler.h"
|
2019-04-09 20:18:44 +08:00
|
|
|
#include "llvm/ADT/StringMap.h"
|
2019-04-16 05:02:47 +08:00
|
|
|
#include "llvm/Support/CommandLine.h"
|
2019-03-30 16:42:48 +08:00
|
|
|
#include "llvm/Support/FileSystem.h"
|
2019-04-16 14:35:07 +08:00
|
|
|
#include "llvm/Support/JSON.h"
|
2019-03-30 16:42:48 +08:00
|
|
|
#include <cassert>
|
|
|
|
#include <chrono>
|
|
|
|
#include <string>
|
|
|
|
#include <vector>
|
|
|
|
|
|
|
|
using namespace std::chrono;
|
|
|
|
|
|
|
|
namespace llvm {
|
|
|
|
|
2019-04-16 05:02:47 +08:00
|
|
|
static cl::opt<unsigned> TimeTraceGranularity(
|
|
|
|
"time-trace-granularity",
|
|
|
|
cl::desc(
|
|
|
|
"Minimum time granularity (in microseconds) traced by time profiler"),
|
|
|
|
cl::init(500));
|
|
|
|
|
2019-03-30 16:42:48 +08:00
|
|
|
TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
|
|
|
|
|
|
|
|
typedef duration<steady_clock::rep, steady_clock::period> DurationType;
|
2019-04-09 20:18:44 +08:00
|
|
|
typedef std::pair<size_t, DurationType> CountAndDurationType;
|
|
|
|
typedef std::pair<std::string, CountAndDurationType>
|
|
|
|
NameAndCountAndDurationType;
|
2019-03-30 16:42:48 +08:00
|
|
|
|
|
|
|
struct Entry {
|
|
|
|
time_point<steady_clock> Start;
|
|
|
|
DurationType Duration;
|
|
|
|
std::string Name;
|
|
|
|
std::string Detail;
|
2019-04-16 05:02:47 +08:00
|
|
|
|
|
|
|
Entry(time_point<steady_clock> &&S, DurationType &&D, std::string &&N,
|
|
|
|
std::string &&Dt)
|
|
|
|
: Start(std::move(S)), Duration(std::move(D)), Name(std::move(N)),
|
|
|
|
Detail(std::move(Dt)){};
|
2019-03-30 16:42:48 +08:00
|
|
|
};
|
|
|
|
|
|
|
|
struct TimeTraceProfiler {
|
|
|
|
TimeTraceProfiler() {
|
|
|
|
StartTime = steady_clock::now();
|
|
|
|
}
|
|
|
|
|
|
|
|
void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
|
2019-04-16 05:02:47 +08:00
|
|
|
Stack.emplace_back(steady_clock::now(), DurationType{}, std::move(Name),
|
|
|
|
Detail());
|
2019-03-30 16:42:48 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
void end() {
|
|
|
|
assert(!Stack.empty() && "Must call begin() first");
|
|
|
|
auto &E = Stack.back();
|
|
|
|
E.Duration = steady_clock::now() - E.Start;
|
|
|
|
|
2019-04-16 05:02:47 +08:00
|
|
|
// Only include sections longer than TimeTraceGranularity msec.
|
|
|
|
if (duration_cast<microseconds>(E.Duration).count() > TimeTraceGranularity)
|
2019-03-30 16:42:48 +08:00
|
|
|
Entries.emplace_back(E);
|
|
|
|
|
|
|
|
// Track total time taken by each "name", but only the topmost levels of
|
|
|
|
// them; e.g. if there's a template instantiation that instantiates other
|
|
|
|
// templates from within, we only want to add the topmost one. "topmost"
|
|
|
|
// happens to be the ones that don't have any currently open entries above
|
|
|
|
// itself.
|
|
|
|
if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) {
|
|
|
|
return Val.Name == E.Name;
|
|
|
|
}) == Stack.rend()) {
|
2019-04-09 20:18:44 +08:00
|
|
|
auto &CountAndTotal = CountAndTotalPerName[E.Name];
|
|
|
|
CountAndTotal.first++;
|
|
|
|
CountAndTotal.second += E.Duration;
|
2019-03-30 16:42:48 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
Stack.pop_back();
|
|
|
|
}
|
|
|
|
|
2019-04-16 05:02:47 +08:00
|
|
|
void Write(raw_pwrite_stream &OS) {
|
2019-03-30 16:42:48 +08:00
|
|
|
assert(Stack.empty() &&
|
|
|
|
"All profiler sections should be ended when calling Write");
|
|
|
|
|
2019-04-16 14:35:07 +08:00
|
|
|
json::Array Events;
|
2019-04-17 04:36:56 +08:00
|
|
|
const size_t ExpectedEntryCount =
|
|
|
|
Entries.size() + CountAndTotalPerName.size() + 1;
|
|
|
|
Events.reserve(ExpectedEntryCount);
|
2019-03-30 16:42:48 +08:00
|
|
|
|
|
|
|
// Emit all events for the main flame graph.
|
|
|
|
for (const auto &E : Entries) {
|
|
|
|
auto StartUs = duration_cast<microseconds>(E.Start - StartTime).count();
|
|
|
|
auto DurUs = duration_cast<microseconds>(E.Duration).count();
|
2019-04-16 14:35:07 +08:00
|
|
|
|
|
|
|
Events.emplace_back(json::Object{
|
|
|
|
{"pid", 1},
|
|
|
|
{"tid", 0},
|
|
|
|
{"ph", "X"},
|
|
|
|
{"ts", StartUs},
|
|
|
|
{"dur", DurUs},
|
|
|
|
{"name", E.Name},
|
|
|
|
{"args", json::Object{{"detail", E.Detail}}},
|
|
|
|
});
|
2019-03-30 16:42:48 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
// Emit totals by section name as additional "thread" events, sorted from
|
|
|
|
// longest one.
|
|
|
|
int Tid = 1;
|
2019-04-09 20:18:44 +08:00
|
|
|
std::vector<NameAndCountAndDurationType> SortedTotals;
|
|
|
|
SortedTotals.reserve(CountAndTotalPerName.size());
|
2019-04-16 05:02:47 +08:00
|
|
|
for (const auto &E : CountAndTotalPerName)
|
2019-04-09 20:18:44 +08:00
|
|
|
SortedTotals.emplace_back(E.getKey(), E.getValue());
|
2019-04-16 05:02:47 +08:00
|
|
|
|
|
|
|
llvm::sort(SortedTotals.begin(), SortedTotals.end(),
|
|
|
|
[](const NameAndCountAndDurationType &A,
|
|
|
|
const NameAndCountAndDurationType &B) {
|
|
|
|
return A.second.second > B.second.second;
|
|
|
|
});
|
2019-03-30 16:42:48 +08:00
|
|
|
for (const auto &E : SortedTotals) {
|
2019-04-09 20:18:44 +08:00
|
|
|
auto DurUs = duration_cast<microseconds>(E.second.second).count();
|
|
|
|
auto Count = CountAndTotalPerName[E.first].first;
|
2019-04-16 14:35:07 +08:00
|
|
|
|
|
|
|
Events.emplace_back(json::Object{
|
|
|
|
{"pid", 1},
|
|
|
|
{"tid", Tid},
|
|
|
|
{"ph", "X"},
|
|
|
|
{"ts", 0},
|
|
|
|
{"dur", DurUs},
|
|
|
|
{"name", "Total " + E.first},
|
|
|
|
{"args", json::Object{{"count", static_cast<int64_t>(Count)},
|
|
|
|
{"avg ms",
|
|
|
|
static_cast<int64_t>(DurUs / Count / 1000)}}},
|
|
|
|
});
|
|
|
|
|
2019-03-30 16:42:48 +08:00
|
|
|
++Tid;
|
|
|
|
}
|
|
|
|
|
|
|
|
// Emit metadata event with process name.
|
2019-04-16 14:35:07 +08:00
|
|
|
Events.emplace_back(json::Object{
|
|
|
|
{"cat", ""},
|
|
|
|
{"pid", 1},
|
|
|
|
{"tid", 0},
|
|
|
|
{"ts", 0},
|
|
|
|
{"ph", "M"},
|
|
|
|
{"name", "process_name"},
|
|
|
|
{"args", json::Object{{"name", "clang"}}},
|
|
|
|
});
|
|
|
|
|
2019-04-17 04:36:56 +08:00
|
|
|
assert(Events.size() == ExpectedEntryCount && "Size prediction failed!");
|
|
|
|
|
2019-04-16 14:35:07 +08:00
|
|
|
OS << formatv("{0:2}", json::Value(json::Object(
|
|
|
|
{{"traceEvents", std::move(Events)}})));
|
2019-03-30 16:42:48 +08:00
|
|
|
}
|
|
|
|
|
2019-04-16 05:02:47 +08:00
|
|
|
SmallVector<Entry, 16> Stack;
|
|
|
|
SmallVector<Entry, 128> Entries;
|
2019-04-09 20:18:44 +08:00
|
|
|
StringMap<CountAndDurationType> CountAndTotalPerName;
|
2019-03-30 16:42:48 +08:00
|
|
|
time_point<steady_clock> StartTime;
|
|
|
|
};
|
|
|
|
|
|
|
|
void timeTraceProfilerInitialize() {
|
|
|
|
assert(TimeTraceProfilerInstance == nullptr &&
|
|
|
|
"Profiler should not be initialized");
|
|
|
|
TimeTraceProfilerInstance = new TimeTraceProfiler();
|
|
|
|
}
|
|
|
|
|
|
|
|
void timeTraceProfilerCleanup() {
|
|
|
|
delete TimeTraceProfilerInstance;
|
|
|
|
TimeTraceProfilerInstance = nullptr;
|
|
|
|
}
|
|
|
|
|
2019-04-16 05:02:47 +08:00
|
|
|
void timeTraceProfilerWrite(raw_pwrite_stream &OS) {
|
2019-03-30 16:42:48 +08:00
|
|
|
assert(TimeTraceProfilerInstance != nullptr &&
|
|
|
|
"Profiler object can't be null");
|
|
|
|
TimeTraceProfilerInstance->Write(OS);
|
|
|
|
}
|
|
|
|
|
|
|
|
void timeTraceProfilerBegin(StringRef Name, StringRef Detail) {
|
|
|
|
if (TimeTraceProfilerInstance != nullptr)
|
|
|
|
TimeTraceProfilerInstance->begin(Name, [&]() { return Detail; });
|
|
|
|
}
|
|
|
|
|
|
|
|
void timeTraceProfilerBegin(StringRef Name,
|
|
|
|
llvm::function_ref<std::string()> Detail) {
|
|
|
|
if (TimeTraceProfilerInstance != nullptr)
|
|
|
|
TimeTraceProfilerInstance->begin(Name, Detail);
|
|
|
|
}
|
|
|
|
|
|
|
|
void timeTraceProfilerEnd() {
|
|
|
|
if (TimeTraceProfilerInstance != nullptr)
|
|
|
|
TimeTraceProfilerInstance->end();
|
|
|
|
}
|
|
|
|
|
|
|
|
} // namespace llvm
|