diff options
Diffstat (limited to 'llvm/lib/Support/TimeProfiler.cpp')
| -rw-r--r-- | llvm/lib/Support/TimeProfiler.cpp | 214 |
1 files changed, 159 insertions, 55 deletions
diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp index a7c85509064e..93bf6f57e348 100644 --- a/llvm/lib/Support/TimeProfiler.cpp +++ b/llvm/lib/Support/TimeProfiler.cpp @@ -11,20 +11,33 @@ //===----------------------------------------------------------------------===// #include "llvm/Support/TimeProfiler.h" +#include "llvm/ADT/STLExtras.h" #include "llvm/ADT/StringMap.h" #include "llvm/Support/CommandLine.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 std::chrono; +using namespace llvm; -namespace llvm { +static std::mutex Mu; +// List of all instances +static std::vector<TimeTraceProfiler *> + ThreadTimeTraceProfilerInstances; // GUARDED_BY(Mu) +// Per Thread instance +static LLVM_THREAD_LOCAL TimeTraceProfiler *TimeTraceProfilerInstance = nullptr; -TimeTraceProfiler *TimeTraceProfilerInstance = nullptr; +TimeTraceProfiler *llvm::getTimeTraceProfilerInstance() { + return TimeTraceProfilerInstance; +} typedef duration<steady_clock::rep, steady_clock::period> DurationType; typedef time_point<steady_clock> TimePointType; @@ -32,6 +45,7 @@ typedef std::pair<size_t, DurationType> CountAndDurationType; typedef std::pair<std::string, CountAndDurationType> NameAndCountAndDurationType; +namespace { struct Entry { const TimePointType Start; TimePointType End; @@ -57,11 +71,15 @@ struct Entry { .count(); } }; +} // namespace -struct TimeTraceProfiler { +struct llvm::TimeTraceProfiler { TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "") - : StartTime(steady_clock::now()), ProcName(ProcName), - TimeTraceGranularity(TimeTraceGranularity) {} + : BeginningOfTime(system_clock::now()), StartTime(steady_clock::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(steady_clock::now(), TimePointType(), std::move(Name), @@ -70,7 +88,7 @@ struct TimeTraceProfiler { void end() { assert(!Stack.empty() && "Must call begin() first"); - auto &E = Stack.back(); + Entry &E = Stack.back(); E.End = steady_clock::now(); // Check that end times monotonically increase. @@ -103,22 +121,30 @@ struct TimeTraceProfiler { Stack.pop_back(); } - void Write(raw_pwrite_stream &OS) { + // Write events from this TimeTraceProfilerInstance and + // ThreadTimeTraceProfilerInstances. + void write(raw_pwrite_stream &OS) { + // Acquire Mutex as reading ThreadTimeTraceProfilerInstances. + std::lock_guard<std::mutex> Lock(Mu); assert(Stack.empty() && - "All profiler sections should be ended when calling Write"); + "All profiler sections should be ended when calling write"); + assert(llvm::all_of(ThreadTimeTraceProfilerInstances, + [](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. - for (const auto &E : Entries) { + auto writeEvent = [&](const auto &E, uint64_t Tid) { auto StartUs = E.getFlameGraphStartUs(StartTime); auto DurUs = E.getFlameGraphDurUs(); - J.object([&]{ - J.attribute("pid", 1); - J.attribute("tid", 0); + J.object([&] { + J.attribute("pid", Pid); + J.attribute("tid", int64_t(Tid)); J.attribute("ph", "X"); J.attribute("ts", StartUs); J.attribute("dur", DurUs); @@ -127,100 +153,178 @@ struct TimeTraceProfiler { J.attributeObject("args", [&] { J.attribute("detail", E.Detail); }); } }); - } + }; + for (const Entry &E : Entries) + writeEvent(E, this->Tid); + for (const TimeTraceProfiler *TTP : ThreadTimeTraceProfilerInstances) + for (const Entry &E : TTP->Entries) + writeEvent(E, TTP->Tid); // Emit totals by section name as additional "thread" events, sorted from // longest one. - int Tid = 1; + // Find highest used thread id. + uint64_t MaxTid = this->Tid; + for (const TimeTraceProfiler *TTP : ThreadTimeTraceProfilerInstances) + 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 : ThreadTimeTraceProfilerInstances) + for (const auto &Stat : TTP->CountAndTotalPerName) + combineStat(Stat); + std::vector<NameAndCountAndDurationType> SortedTotals; - SortedTotals.reserve(CountAndTotalPerName.size()); - for (const auto &E : CountAndTotalPerName) - SortedTotals.emplace_back(E.getKey(), E.getValue()); - - llvm::sort(SortedTotals.begin(), SortedTotals.end(), - [](const NameAndCountAndDurationType &A, - const NameAndCountAndDurationType &B) { - return A.second.second > B.second.second; - }); - for (const auto &E : SortedTotals) { - auto DurUs = duration_cast<microseconds>(E.second.second).count(); - auto Count = CountAndTotalPerName[E.first].first; - - J.object([&]{ - J.attribute("pid", 1); - J.attribute("tid", Tid); + 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 " + E.first); + J.attribute("name", "Total " + Total.first); J.attributeObject("args", [&] { J.attribute("count", int64_t(Count)); J.attribute("avg ms", int64_t(DurUs / Count / 1000)); }); }); - ++Tid; + ++TotalTid; } - // Emit metadata event with process name. - J.object([&] { - J.attribute("cat", ""); - J.attribute("pid", 1); - J.attribute("tid", 0); - J.attribute("ts", 0); - J.attribute("ph", "M"); - J.attribute("name", "process_name"); - J.attributeObject("args", [&] { J.attribute("name", ProcName); }); - }); + 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 : ThreadTimeTraceProfilerInstances) + 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<Entry, 16> Stack; SmallVector<Entry, 128> Entries; StringMap<CountAndDurationType> CountAndTotalPerName; + const time_point<system_clock> BeginningOfTime; 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 timeTraceProfilerInitialize(unsigned TimeTraceGranularity, - StringRef ProcName) { +void llvm::timeTraceProfilerInitialize(unsigned TimeTraceGranularity, + StringRef ProcName) { assert(TimeTraceProfilerInstance == nullptr && "Profiler should not be initialized"); TimeTraceProfilerInstance = new TimeTraceProfiler( TimeTraceGranularity, llvm::sys::path::filename(ProcName)); } -void timeTraceProfilerCleanup() { +// Removes all TimeTraceProfilerInstances. +// Called from main thread. +void llvm::timeTraceProfilerCleanup() { delete TimeTraceProfilerInstance; + std::lock_guard<std::mutex> Lock(Mu); + for (auto TTP : ThreadTimeTraceProfilerInstances) + delete TTP; + ThreadTimeTraceProfilerInstances.clear(); +} + +// Finish TimeTraceProfilerInstance on a worker thread. +// This doesn't remove the instance, just moves the pointer to global vector. +void llvm::timeTraceProfilerFinishThread() { + std::lock_guard<std::mutex> Lock(Mu); + ThreadTimeTraceProfilerInstances.push_back(TimeTraceProfilerInstance); TimeTraceProfilerInstance = nullptr; } -void timeTraceProfilerWrite(raw_pwrite_stream &OS) { +void llvm::timeTraceProfilerWrite(raw_pwrite_stream &OS) { assert(TimeTraceProfilerInstance != nullptr && "Profiler object can't be null"); - TimeTraceProfilerInstance->Write(OS); + TimeTraceProfilerInstance->write(OS); } -void timeTraceProfilerBegin(StringRef Name, StringRef Detail) { +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_Text); + 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(Name, [&]() { return Detail; }); + TimeTraceProfilerInstance->begin(std::string(Name), + [&]() { return std::string(Detail); }); } -void timeTraceProfilerBegin(StringRef Name, - llvm::function_ref<std::string()> Detail) { +void llvm::timeTraceProfilerBegin(StringRef Name, + llvm::function_ref<std::string()> Detail) { if (TimeTraceProfilerInstance != nullptr) - TimeTraceProfilerInstance->begin(Name, Detail); + TimeTraceProfilerInstance->begin(std::string(Name), Detail); } -void timeTraceProfilerEnd() { +void llvm::timeTraceProfilerEnd() { if (TimeTraceProfilerInstance != nullptr) TimeTraceProfilerInstance->end(); } - -} // namespace llvm |