blob: 4d625b3eb5b17092017c4501c72f81d9f6223789 [file] [log] [blame]
//===-- TimeProfiler.cpp - Hierarchical Time Profiler ---------------------===//
//
// 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
//
//===----------------------------------------------------------------------===//
//
// This file implements hierarchical time profiler.
//
//===----------------------------------------------------------------------===//
#include "llvm/Support/TimeProfiler.h"
#include "llvm/ADT/STLFunctionalExtras.h"
#include "llvm/ADT/StringMap.h"
#include "llvm/Support/JSON.h"
#include "llvm/Support/Path.h"
#include "llvm/Support/Process.h"
#include "llvm/Support/Threading.h"
#include <algorithm>
#include <cassert>
#include <chrono>
#include <mutex>
#include <string>
#include <vector>
using namespace llvm;
namespace {
using std::chrono::duration;
using std::chrono::duration_cast;
using std::chrono::microseconds;
using std::chrono::steady_clock;
using std::chrono::system_clock;
using std::chrono::time_point;
using std::chrono::time_point_cast;
struct TimeTraceProfilerInstances {
std::mutex Lock;
std::vector<TimeTraceProfiler *> List;
};
TimeTraceProfilerInstances &getTimeTraceProfilerInstances() {
static TimeTraceProfilerInstances Instances;
return Instances;
}
} // anonymous namespace
// Per Thread instance
static LLVM_THREAD_LOCAL TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
TimeTraceProfiler *llvm::getTimeTraceProfilerInstance() {
return TimeTraceProfilerInstance;
}
namespace {
using ClockType = steady_clock;
using TimePointType = time_point<ClockType>;
using DurationType = duration<ClockType::rep, ClockType::period>;
using CountAndDurationType = std::pair<size_t, DurationType>;
using NameAndCountAndDurationType =
std::pair<std::string, CountAndDurationType>;
/// Represents an open or completed time section entry to be captured.
struct TimeTraceProfilerEntry {
const TimePointType Start;
TimePointType End;
const std::string Name;
const std::string Detail;
TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
std::string &&Dt)
: Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
Detail(std::move(Dt)) {}
// Calculate timings for FlameGraph. Cast time points to microsecond precision
// rather than casting duration. This avoids truncation issues causing inner
// scopes overruning outer scopes.
ClockType::rep getFlameGraphStartUs(TimePointType StartTime) const {
return (time_point_cast<microseconds>(Start) -
time_point_cast<microseconds>(StartTime))
.count();
}
ClockType::rep getFlameGraphDurUs() const {
return (time_point_cast<microseconds>(End) -
time_point_cast<microseconds>(Start))
.count();
}
};
} // anonymous namespace
struct llvm::TimeTraceProfiler {
TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "")
: BeginningOfTime(system_clock::now()), StartTime(ClockType::now()),
ProcName(ProcName), Pid(sys::Process::getProcessId()),
Tid(llvm::get_threadid()), TimeTraceGranularity(TimeTraceGranularity) {
llvm::get_thread_name(ThreadName);
}
void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
Stack.emplace_back(ClockType::now(), TimePointType(), std::move(Name),
Detail());
}
void end() {
assert(!Stack.empty() && "Must call begin() first");
TimeTraceProfilerEntry &E = Stack.back();
E.End = ClockType::now();
// Check that end times monotonically increase.
assert((Entries.empty() ||
(E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >=
Entries.back().getFlameGraphStartUs(StartTime) +
Entries.back().getFlameGraphDurUs())) &&
"TimeProfiler scope ended earlier than previous scope");
// Calculate duration at full precision for overall counts.
DurationType Duration = E.End - E.Start;
// Only include sections longer or equal to TimeTraceGranularity msec.
if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity)
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 (llvm::none_of(llvm::drop_begin(llvm::reverse(Stack)),
[&](const TimeTraceProfilerEntry &Val) {
return Val.Name == E.Name;
})) {
auto &CountAndTotal = CountAndTotalPerName[E.Name];
CountAndTotal.first++;
CountAndTotal.second += Duration;
}
Stack.pop_back();
}
// Write events from this TimeTraceProfilerInstance and
// ThreadTimeTraceProfilerInstances.
void write(raw_pwrite_stream &OS) {
// Acquire Mutex as reading ThreadTimeTraceProfilerInstances.
auto &Instances = getTimeTraceProfilerInstances();
std::lock_guard<std::mutex> Lock(Instances.Lock);
assert(Stack.empty() &&
"All profiler sections should be ended when calling write");
assert(llvm::all_of(Instances.List,
[](const auto &TTP) { return TTP->Stack.empty(); }) &&
"All profiler sections should be ended when calling write");
json::OStream J(OS);
J.objectBegin();
J.attributeBegin("traceEvents");
J.arrayBegin();
// Emit all events for the main flame graph.
auto writeEvent = [&](const auto &E, uint64_t Tid) {
auto StartUs = E.getFlameGraphStartUs(StartTime);
auto DurUs = E.getFlameGraphDurUs();
J.object([&] {
J.attribute("pid", Pid);
J.attribute("tid", int64_t(Tid));
J.attribute("ph", "X");
J.attribute("ts", StartUs);
J.attribute("dur", DurUs);
J.attribute("name", E.Name);
if (!E.Detail.empty()) {
J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
}
});
};
for (const TimeTraceProfilerEntry &E : Entries)
writeEvent(E, this->Tid);
for (const TimeTraceProfiler *TTP : Instances.List)
for (const TimeTraceProfilerEntry &E : TTP->Entries)
writeEvent(E, TTP->Tid);
// Emit totals by section name as additional "thread" events, sorted from
// longest one.
// Find highest used thread id.
uint64_t MaxTid = this->Tid;
for (const TimeTraceProfiler *TTP : Instances.List)
MaxTid = std::max(MaxTid, TTP->Tid);
// Combine all CountAndTotalPerName from threads into one.
StringMap<CountAndDurationType> AllCountAndTotalPerName;
auto combineStat = [&](const auto &Stat) {
StringRef Key = Stat.getKey();
auto Value = Stat.getValue();
auto &CountAndTotal = AllCountAndTotalPerName[Key];
CountAndTotal.first += Value.first;
CountAndTotal.second += Value.second;
};
for (const auto &Stat : CountAndTotalPerName)
combineStat(Stat);
for (const TimeTraceProfiler *TTP : Instances.List)
for (const auto &Stat : TTP->CountAndTotalPerName)
combineStat(Stat);
std::vector<NameAndCountAndDurationType> SortedTotals;
SortedTotals.reserve(AllCountAndTotalPerName.size());
for (const auto &Total : AllCountAndTotalPerName)
SortedTotals.emplace_back(std::string(Total.getKey()), Total.getValue());
llvm::sort(SortedTotals, [](const NameAndCountAndDurationType &A,
const NameAndCountAndDurationType &B) {
return A.second.second > B.second.second;
});
// Report totals on separate threads of tracing file.
uint64_t TotalTid = MaxTid + 1;
for (const NameAndCountAndDurationType &Total : SortedTotals) {
auto DurUs = duration_cast<microseconds>(Total.second.second).count();
auto Count = AllCountAndTotalPerName[Total.first].first;
J.object([&] {
J.attribute("pid", Pid);
J.attribute("tid", int64_t(TotalTid));
J.attribute("ph", "X");
J.attribute("ts", 0);
J.attribute("dur", DurUs);
J.attribute("name", "Total " + Total.first);
J.attributeObject("args", [&] {
J.attribute("count", int64_t(Count));
J.attribute("avg ms", int64_t(DurUs / Count / 1000));
});
});
++TotalTid;
}
auto writeMetadataEvent = [&](const char *Name, uint64_t Tid,
StringRef arg) {
J.object([&] {
J.attribute("cat", "");
J.attribute("pid", Pid);
J.attribute("tid", int64_t(Tid));
J.attribute("ts", 0);
J.attribute("ph", "M");
J.attribute("name", Name);
J.attributeObject("args", [&] { J.attribute("name", arg); });
});
};
writeMetadataEvent("process_name", Tid, ProcName);
writeMetadataEvent("thread_name", Tid, ThreadName);
for (const TimeTraceProfiler *TTP : Instances.List)
writeMetadataEvent("thread_name", TTP->Tid, TTP->ThreadName);
J.arrayEnd();
J.attributeEnd();
// Emit the absolute time when this TimeProfiler started.
// This can be used to combine the profiling data from
// multiple processes and preserve actual time intervals.
J.attribute("beginningOfTime",
time_point_cast<microseconds>(BeginningOfTime)
.time_since_epoch()
.count());
J.objectEnd();
}
SmallVector<TimeTraceProfilerEntry, 16> Stack;
SmallVector<TimeTraceProfilerEntry, 128> Entries;
StringMap<CountAndDurationType> CountAndTotalPerName;
// System clock time when the session was begun.
const time_point<system_clock> BeginningOfTime;
// Profiling clock time when the session was begun.
const TimePointType StartTime;
const std::string ProcName;
const sys::Process::Pid Pid;
SmallString<0> ThreadName;
const uint64_t Tid;
// Minimum time granularity (in microseconds)
const unsigned TimeTraceGranularity;
};
void llvm::timeTraceProfilerInitialize(unsigned TimeTraceGranularity,
StringRef ProcName) {
assert(TimeTraceProfilerInstance == nullptr &&
"Profiler should not be initialized");
TimeTraceProfilerInstance = new TimeTraceProfiler(
TimeTraceGranularity, llvm::sys::path::filename(ProcName));
}
// Removes all TimeTraceProfilerInstances.
// Called from main thread.
void llvm::timeTraceProfilerCleanup() {
delete TimeTraceProfilerInstance;
TimeTraceProfilerInstance = nullptr;
auto &Instances = getTimeTraceProfilerInstances();
std::lock_guard<std::mutex> Lock(Instances.Lock);
for (auto *TTP : Instances.List)
delete TTP;
Instances.List.clear();
}
// Finish TimeTraceProfilerInstance on a worker thread.
// This doesn't remove the instance, just moves the pointer to global vector.
void llvm::timeTraceProfilerFinishThread() {
auto &Instances = getTimeTraceProfilerInstances();
std::lock_guard<std::mutex> Lock(Instances.Lock);
Instances.List.push_back(TimeTraceProfilerInstance);
TimeTraceProfilerInstance = nullptr;
}
void llvm::timeTraceProfilerWrite(raw_pwrite_stream &OS) {
assert(TimeTraceProfilerInstance != nullptr &&
"Profiler object can't be null");
TimeTraceProfilerInstance->write(OS);
}
Error llvm::timeTraceProfilerWrite(StringRef PreferredFileName,
StringRef FallbackFileName) {
assert(TimeTraceProfilerInstance != nullptr &&
"Profiler object can't be null");
std::string Path = PreferredFileName.str();
if (Path.empty()) {
Path = FallbackFileName == "-" ? "out" : FallbackFileName.str();
Path += ".time-trace";
}
std::error_code EC;
raw_fd_ostream OS(Path, EC, sys::fs::OF_TextWithCRLF);
if (EC)
return createStringError(EC, "Could not open " + Path);
timeTraceProfilerWrite(OS);
return Error::success();
}
void llvm::timeTraceProfilerBegin(StringRef Name, StringRef Detail) {
if (TimeTraceProfilerInstance != nullptr)
TimeTraceProfilerInstance->begin(std::string(Name),
[&]() { return std::string(Detail); });
}
void llvm::timeTraceProfilerBegin(StringRef Name,
llvm::function_ref<std::string()> Detail) {
if (TimeTraceProfilerInstance != nullptr)
TimeTraceProfilerInstance->begin(std::string(Name), Detail);
}
void llvm::timeTraceProfilerEnd() {
if (TimeTraceProfilerInstance != nullptr)
TimeTraceProfilerInstance->end();
}