diff --git a/llvm/include/llvm/Support/TimeProfiler.h b/llvm/include/llvm/Support/TimeProfiler.h --- a/llvm/include/llvm/Support/TimeProfiler.h +++ b/llvm/include/llvm/Support/TimeProfiler.h @@ -5,12 +5,82 @@ // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception // //===----------------------------------------------------------------------===// +// +// This provides lightweight and dependency-free machinery to trace execution +// time around arbitrary code. +// +// The primary interface uses an implicit per-thread scope of active +// time profiling 'entries': +// \code +// { +// TimeTraceScope scope("my_event_name"); +// ...my code... +// } +// \endcode +// +// It is also possible to manually create, begin and complete time profiling +// entries. This interface allows an entry to be created in one context, +// stored, then completed in another. The completing context need not be on +// the same thread as the creating context: +// \code +// auto entry = timeTraceProfilerBeginEntry("my_event_name"); +// ... +// // Possibly on a different thread +// entry.reset(); // optional, if the event start time should be decoupled +// // from entry creation +// ...my code... +// timeTraceProfilerEndEntry(std::move(entry)); +// \endcode +// +// Time profiling entries can be given an arbitrary name and, optionally, +// an arbitrary 'detail' string. The resulting trace will include 'Total' +// entries summing the time spent for each name. Thus, it's best to choose +// names to be fairly generic, and rely on the detail field to capture +// everything else of interest. +// +// To avoid lifetime issues name and detail strings are copied into the event +// entries at their time of creation. Thus, care should be taken to make string +// construction cheep to prevent 'Heisenperf' effects. The 'detail' argument +// may be a string-returning closure: +// \code +// int n; +// { +// TimeTraceScope scope("my_event_name", +// [n]() { return (Twine("x=") + Twine(n)).str(); }); +// ...my code... +// } +// \endcode +// (See Future Work below for a possible improvement to this API). +// +// Sub-threads should be wrapped in timeTraceProfilerInitialize and +// timeTraceProfilerFinishThread calls. The main process should +// be wrapped in timeTraceProfilerInitialize, timeTraceProfileWrite and +// timeTraceProfilerCleanup calls. +// +// Timestamps come from std::chrono::high_resolution_clock, so all threads +// see the same time at the highest available resolution. +// +// Currently, the best trace viewer is provided by the Google Perfetto +// project, a successor of Chrome's tracing, see http://ui.perfetto.dev. +// +// Future work: +// - Support akin to LLVM_DEBUG for runtime enable/disable of named tracing +// families for non-debug builds which wish to support optional tracing. +// - Evaluate the detail closures at profile write time to avoid +// stringification costs interfering with tracing... +// - ... or retire the detail closures in favor of std::string&& arguments +// to avoid double-copying constructed detail strings. +// +//===----------------------------------------------------------------------===// #ifndef LLVM_SUPPORT_TIMEPROFILER_H #define LLVM_SUPPORT_TIMEPROFILER_H -#include "llvm/Support/Error.h" #include "llvm/ADT/STLFunctionalExtras.h" +#include "llvm/ADT/StringRef.h" +#include "llvm/Support/Error.h" + +#include namespace llvm { @@ -53,13 +123,69 @@ /// Profiler copies the string data, so the pointers can be given into /// temporaries. Time sections can be hierarchical; every Begin must have a /// matching End pair but they can nest. -void timeTraceProfilerBegin(StringRef Name, StringRef Detail); +void timeTraceProfilerBegin(StringRef Name, StringRef Detail = {}); void timeTraceProfilerBegin(StringRef Name, llvm::function_ref Detail); /// Manually end the last time section. void timeTraceProfilerEnd(); +/// Represents an open or completed time section. +struct TimeProfilerEntry { + using ClockType = std::chrono::high_resolution_clock; + using TimePointType = std::chrono::time_point; + + TimePointType Start; + TimePointType End; + const std::string Name; + const std::string Detail; + + TimeProfilerEntry() = default; + + /// Constructs entry starting from now with Name and empty Detail. + explicit TimeProfilerEntry(std::string &&Name) + : Start(ClockType::now()), Name(std::move(Name)) {} + + /// Constructs entry starting from now with Name and Detail. + TimeProfilerEntry(std::string &&Name, std::string &&Detail) + : Start(ClockType::now()), Name(std::move(Name)), + Detail(std::move(Detail)) {} + + // Calculate timings for FlameGraph. Cast time points to microsecond precision + // rather than casting duration. This avoid truncation issues causing inner + // scopes overruning outer scopes. + std::chrono::steady_clock::rep + getFlameGraphStartUs(TimePointType StartTime) const { + return (std::chrono::time_point_cast(Start) - + std::chrono::time_point_cast(StartTime)) + .count(); + } + + std::chrono::steady_clock::rep getFlameGraphDurUs() const { + return (std::chrono::time_point_cast(End) - + std::chrono::time_point_cast(Start)) + .count(); + } + + /// Resets the starting time of the given entry to now. By default the entry + /// will take it's start time at the time of construction. + void reset() { Start = ClockType::now(); } +}; + +/// Returns an entry with starting time of now and Name and Detail. +/// The entry can later be added to the trace by timeTraceProfilerEndEntry +/// below when the tracked event has completed. +TimeProfilerEntry timeTraceProfilerBeginEntry(StringRef Name, + StringRef Detail = {}); +TimeProfilerEntry +timeTraceProfilerBeginEntry(StringRef Name, + llvm::function_ref Detail); + +/// Ends the Entry returned by timeTraceProfilerBeginEntry above. The entry is +/// recorded by the current thread, which need not be the same as the thread +/// which executed the original timeTraceProfilerBeginEntry call. +void timeTraceProfilerEndEntry(TimeProfilerEntry &&Entry); + /// The TimeTraceScope is a helper class to call the begin and end functions /// of the time trace profiler. When the object is constructed, it begins /// the section; and when it is destroyed, it stops it. If the time profiler @@ -72,11 +198,7 @@ TimeTraceScope(TimeTraceScope &&) = delete; TimeTraceScope &operator=(TimeTraceScope &&) = delete; - TimeTraceScope(StringRef Name) { - if (getTimeTraceProfilerInstance() != nullptr) - timeTraceProfilerBegin(Name, StringRef("")); - } - TimeTraceScope(StringRef Name, StringRef Detail) { + TimeTraceScope(StringRef Name, StringRef Detail = {}) { if (getTimeTraceProfilerInstance() != nullptr) timeTraceProfilerBegin(Name, Detail); } diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp --- a/llvm/lib/Support/TimeProfiler.cpp +++ b/llvm/lib/Support/TimeProfiler.cpp @@ -17,14 +17,12 @@ #include "llvm/Support/Path.h" #include "llvm/Support/Process.h" #include "llvm/Support/Threading.h" -#include #include #include #include #include #include -using namespace std::chrono; using namespace llvm; namespace { @@ -48,71 +46,47 @@ return TimeTraceProfilerInstance; } -typedef duration DurationType; -typedef time_point TimePointType; -typedef std::pair CountAndDurationType; -typedef std::pair - NameAndCountAndDurationType; - -namespace { -struct Entry { - const TimePointType Start; - TimePointType End; - const std::string Name; - const 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(); - } -}; -} // namespace +using ClockType = TimeProfilerEntry::ClockType; +using TimePointType = TimeProfilerEntry::TimePointType; +using DurationType = std::chrono::duration; +using CountAndDurationType = std::pair; +using NameAndCountAndDurationType = + std::pair; struct llvm::TimeTraceProfiler { TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "") - : BeginningOfTime(system_clock::now()), StartTime(steady_clock::now()), + : BeginningOfTime(ClockType::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 Detail) { - Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name), - Detail()); - } + void begin(TimeProfilerEntry &&Entry) { Stack.emplace_back(Entry); } void end() { assert(!Stack.empty() && "Must call begin() first"); - Entry &E = Stack.back(); - E.End = steady_clock::now(); + end(std::move(Stack.back())); + Stack.pop_back(); + } + + void end(TimeProfilerEntry &&Entry) { + Entry.End = ClockType::now(); // Check that end times monotonically increase. - assert((Entries.empty() || - (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >= - Entries.back().getFlameGraphStartUs(StartTime) + - Entries.back().getFlameGraphDurUs())) && + assert((Entries.empty() || (Entry.getFlameGraphStartUs(StartTime) + + Entry.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; + DurationType Duration = Entry.End - Entry.Start; // Only include sections longer or equal to TimeTraceGranularity msec. - if (duration_cast(Duration).count() >= TimeTraceGranularity) - Entries.emplace_back(E); + if (std::chrono::duration_cast(Duration) + .count() >= TimeTraceGranularity) + Entries.emplace_back(Entry); // 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 @@ -120,13 +94,13 @@ // 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 Entry &Val) { return Val.Name == E.Name; })) { - auto &CountAndTotal = CountAndTotalPerName[E.Name]; + [&](const TimeProfilerEntry &Val) { + return Val.Name == Entry.Name; + })) { + auto &CountAndTotal = CountAndTotalPerName[Entry.Name]; CountAndTotal.first++; CountAndTotal.second += Duration; } - - Stack.pop_back(); } // Write events from this TimeTraceProfilerInstance and @@ -163,10 +137,10 @@ } }); }; - for (const Entry &E : Entries) + for (const TimeProfilerEntry &E : Entries) writeEvent(E, this->Tid); for (const TimeTraceProfiler *TTP : Instances.List) - for (const Entry &E : TTP->Entries) + for (const TimeProfilerEntry &E : TTP->Entries) writeEvent(E, TTP->Tid); // Emit totals by section name as additional "thread" events, sorted from @@ -204,7 +178,9 @@ // Report totals on separate threads of tracing file. uint64_t TotalTid = MaxTid + 1; for (const NameAndCountAndDurationType &Total : SortedTotals) { - auto DurUs = duration_cast(Total.second.second).count(); + auto DurUs = std::chrono::duration_cast( + Total.second.second) + .count(); auto Count = AllCountAndTotalPerName[Total.first].first; J.object([&] { @@ -247,18 +223,19 @@ // 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(BeginningOfTime) - .time_since_epoch() - .count()); + J.attribute( + "beginningOfTime", + std::chrono::time_point_cast(BeginningOfTime) + .time_since_epoch() + .count()); J.objectEnd(); } - SmallVector Stack; - SmallVector Entries; + SmallVector Stack; + SmallVector Entries; StringMap CountAndTotalPerName; - const time_point BeginningOfTime; + const TimePointType BeginningOfTime; const TimePointType StartTime; const std::string ProcName; const sys::Process::Pid Pid; @@ -327,17 +304,32 @@ void llvm::timeTraceProfilerBegin(StringRef Name, StringRef Detail) { if (TimeTraceProfilerInstance != nullptr) - TimeTraceProfilerInstance->begin(std::string(Name), - [&]() { return std::string(Detail); }); + TimeTraceProfilerInstance->begin({std::string(Name), std::string(Detail)}); } void llvm::timeTraceProfilerBegin(StringRef Name, llvm::function_ref Detail) { if (TimeTraceProfilerInstance != nullptr) - TimeTraceProfilerInstance->begin(std::string(Name), Detail); + TimeTraceProfilerInstance->begin({std::string(Name), Detail()}); } void llvm::timeTraceProfilerEnd() { if (TimeTraceProfilerInstance != nullptr) TimeTraceProfilerInstance->end(); } + +TimeProfilerEntry llvm::timeTraceProfilerBeginEntry(StringRef Name, + StringRef Detail) { + return {std::string(Name), std::string(Detail)}; +} + +TimeProfilerEntry +llvm::timeTraceProfilerBeginEntry(StringRef Name, + llvm::function_ref Detail) { + return {std::string(Name), Detail()}; +} + +void llvm::timeTraceProfilerEndEntry(TimeProfilerEntry &&Entry) { + if (TimeTraceProfilerInstance != nullptr) + TimeTraceProfilerInstance->end(std::move(Entry)); +}