//===-- 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/StringMap.h" #include "llvm/Support/CommandLine.h" #include "llvm/Support/FileSystem.h" #include "llvm/Support/JSON.h" #include #include #include #include using namespace std::chrono; namespace llvm { TimeTraceProfiler *TimeTraceProfilerInstance = nullptr; typedef duration DurationType; typedef time_point TimePointType; typedef std::pair CountAndDurationType; typedef std::pair NameAndCountAndDurationType; struct Entry { TimePointType Start; TimePointType End; std::string Name; std::string Detail; Entry(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 avoid truncation issues causing inner // scopes overruning outer scopes. steady_clock::rep getFlameGraphStartUs(TimePointType StartTime) const { return (time_point_cast(Start) - time_point_cast(StartTime)) .count(); } steady_clock::rep getFlameGraphDurUs() const { return (time_point_cast(End) - time_point_cast(Start)) .count(); } }; struct TimeTraceProfiler { TimeTraceProfiler() { StartTime = steady_clock::now(); } void begin(std::string Name, llvm::function_ref Detail) { Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name), Detail()); } void end() { assert(!Stack.empty() && "Must call begin() first"); auto &E = Stack.back(); E.End = steady_clock::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(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 (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) { return Val.Name == E.Name; }) == Stack.rend()) { auto &CountAndTotal = CountAndTotalPerName[E.Name]; CountAndTotal.first++; CountAndTotal.second += Duration; } Stack.pop_back(); } void Write(raw_pwrite_stream &OS) { assert(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 StartUs = E.getFlameGraphStartUs(StartTime); auto DurUs = E.getFlameGraphDurUs(); J.object([&]{ J.attribute("pid", 1); J.attribute("tid", 0); J.attribute("ph", "X"); J.attribute("ts", StartUs); J.attribute("dur", DurUs); J.attribute("name", E.Name); J.attributeObject("args", [&] { J.attribute("detail", E.Detail); }); }); } // Emit totals by section name as additional "thread" events, sorted from // longest one. int Tid = 1; std::vector 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(E.second.second).count(); auto Count = CountAndTotalPerName[E.first].first; J.object([&]{ J.attribute("pid", 1); J.attribute("tid", Tid); J.attribute("ph", "X"); J.attribute("ts", 0); J.attribute("dur", DurUs); J.attribute("name", "Total " + E.first); J.attributeObject("args", [&] { J.attribute("count", int64_t(Count)); J.attribute("avg ms", int64_t(DurUs / Count / 1000)); }); }); ++Tid; } // 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", "clang"); }); }); J.arrayEnd(); J.attributeEnd(); J.objectEnd(); } SmallVector Stack; SmallVector Entries; StringMap CountAndTotalPerName; TimePointType StartTime; // Minimum time granularity (in microseconds) unsigned TimeTraceGranularity; }; void timeTraceProfilerInitialize(unsigned TimeTraceGranularity) { assert(TimeTraceProfilerInstance == nullptr && "Profiler should not be initialized"); TimeTraceProfilerInstance = new TimeTraceProfiler(); TimeTraceProfilerInstance->TimeTraceGranularity = TimeTraceGranularity; } void timeTraceProfilerCleanup() { delete TimeTraceProfilerInstance; TimeTraceProfilerInstance = nullptr; } void timeTraceProfilerWrite(raw_pwrite_stream &OS) { 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 Detail) { if (TimeTraceProfilerInstance != nullptr) TimeTraceProfilerInstance->begin(Name, Detail); } void timeTraceProfilerEnd() { if (TimeTraceProfilerInstance != nullptr) TimeTraceProfilerInstance->end(); } } // namespace llvm