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 @@ -7,7 +7,7 @@ //===----------------------------------------------------------------------===// // // This provides lightweight and dependency-free machinery to trace execution -// time around arbitrary code. Two API flavors are available. +// time around arbitrary code. Three API flavors are available. // // The primary API uses a RAII object to trigger tracing: // @@ -28,6 +28,21 @@ // timeTraceProfilerEnd(); // must be called on all control flow paths // \endcode // +// Finally, it is also possible to manually create, begin and complete time +// profiling entries. This API 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.begin(); // 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 @@ -50,14 +65,25 @@ // The closure will not be called if tracing is disabled. Otherwise, the // resulting string will be directly moved into the entry. // +// If string construction is a significant cost it is possible to construct +// the entry outside of the critical section: +// +// \code +// auto entry = timeTraceProfilerBeginEntry("my_event_name", +// [=]() { ... expensive ... }); +// ...non critical code... +// entry.begin(); +// ...my critical code... +// timeTraceProfilerEndEntry(std::move(entry)); +// \endcode +// // The main process should begin with a timeTraceProfilerInitialize, and // finish with timeTraceProfileWrite and timeTraceProfilerCleanup calls. // Each new thread should begin with a timeTraceProfilerInitialize, and // finish with a timeTraceProfilerFinishThread call. // -// Timestamps come from std::chrono::stable_clock. Note that threads need -// not see the same time from that clock, and the resolution may not be -// the best available. +// Timestamps come from std::chrono::high_resolution_clock, so all threads +// see the same time at the highest available resolution. // // Currently, there are a number of compatible viewers: // - chrome://tracing is the original chromium trace viewer. @@ -79,6 +105,8 @@ #include "llvm/ADT/STLFunctionalExtras.h" #include "llvm/Support/Error.h" +#include + namespace llvm { class raw_pwrite_stream; @@ -127,6 +155,74 @@ /// Manually end the last time section. void timeTraceProfilerEnd(); +/// Represents an open or completed time section entry to be captured. +struct TimeTraceProfilerEntry { + // We use the high_resolution_clock for maximum precision. + // It may not be steady (ClockType::is_steady may be false), which means + // it is possible for profiles to yield invalid durations during leap + // second transitions or other system clock adjustments. This rare glitch + // seems worthwhile in exchange for the precision. + // Under linux glibc++ the high_resolution_clock is consistent across threads + // which is necessary for building cross-thread entries. + // It is unknown whether that's the case under Windows, and the C++ standard + // does not appear to impose any thread consistency on any of the clocks. + + 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; + + TimeTraceProfilerEntry() : Start(TimePointType()), End(TimePointType()) {} + + 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 (std::chrono::time_point_cast(Start) - + std::chrono::time_point_cast(StartTime)) + .count(); + } + + ClockType::rep getFlameGraphDurUs() const { + return (std::chrono::time_point_cast(End) - + std::chrono::time_point_cast(Start)) + .count(); + } + + /// Resets the starting time of this entry to now. By default the entry + /// will have taken its start time to be the time of entry construction. + /// But if the entry has been constructed early so as to keep detail string + /// construction out of the measured section then this method can be called + /// to signal measurement should begin. If the time profiler is not + /// initialized, the overhead is a single branch. + void begin(); +}; + +/// 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. If the time profiler is not +/// initialized, the overhead is constructing an empty entry without any +/// use of the global clock. +TimeTraceProfilerEntry timeTraceProfilerBeginEntry(StringRef Name, + StringRef Detail = {}); +TimeTraceProfilerEntry +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. If the time +/// profiler is not initialized, the overhead is a single branch. +void timeTraceProfilerEndEntry(TimeTraceProfilerEntry &&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 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 @@ -55,45 +55,13 @@ return TimeTraceProfilerInstance; } -namespace { - -using ClockType = steady_clock; -using TimePointType = time_point; +using ClockType = TimeTraceProfilerEntry::ClockType; +using TimePointType = TimeTraceProfilerEntry::TimePointType; using DurationType = duration; using CountAndDurationType = std::pair; using NameAndCountAndDurationType = std::pair; -/// 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(Start) - - time_point_cast(StartTime)) - .count(); - } - - ClockType::rep getFlameGraphDurUs() const { - return (time_point_cast(End) - - time_point_cast(Start)) - .count(); - } -}; - -} // anonymous namespace - struct llvm::TimeTraceProfiler { TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "") : BeginningOfTime(system_clock::now()), StartTime(ClockType::now()), @@ -109,7 +77,11 @@ void end() { assert(!Stack.empty() && "Must call begin() first"); - TimeTraceProfilerEntry &E = Stack.back(); + end(std::move(Stack.back())); + Stack.pop_back(); + } + + void end(TimeTraceProfilerEntry &&E) { E.End = ClockType::now(); // Check that end times monotonically increase. @@ -139,8 +111,6 @@ CountAndTotal.first++; CountAndTotal.second += Duration; } - - Stack.pop_back(); } // Write events from this TimeTraceProfilerInstance and @@ -357,3 +327,31 @@ if (TimeTraceProfilerInstance != nullptr) TimeTraceProfilerInstance->end(); } + +void llvm::TimeTraceProfilerEntry::begin() { + if (TimeTraceProfilerInstance != nullptr) + Start = ClockType::now(); +} + +TimeTraceProfilerEntry llvm::timeTraceProfilerBeginEntry(StringRef Name, + StringRef Detail) { + if (TimeTraceProfilerInstance != nullptr) + return {ClockType::now(), TimePointType(), std::string(Name), + std::string(Detail)}; + // The default constructor does not invoke now(). + return {}; +} + +TimeTraceProfilerEntry +llvm::timeTraceProfilerBeginEntry(StringRef Name, + llvm::function_ref Detail) { + if (TimeTraceProfilerInstance != nullptr) + return {ClockType::now(), TimePointType(), std::string(Name), Detail()}; + // The default constructor does not invoke now(). + return {}; +} + +void llvm::timeTraceProfilerEndEntry(TimeTraceProfilerEntry &&Entry) { + if (TimeTraceProfilerInstance != nullptr) + TimeTraceProfilerInstance->end(std::move(Entry)); +} diff --git a/llvm/unittests/Support/TimeProfilerTest.cpp b/llvm/unittests/Support/TimeProfilerTest.cpp --- a/llvm/unittests/Support/TimeProfilerTest.cpp +++ b/llvm/unittests/Support/TimeProfilerTest.cpp @@ -61,4 +61,15 @@ timeTraceProfilerEnd(); } +TEST(TimeProfiler, Entry_Disabled) { + // Only get the default entry if tracing is not setup. + auto entry = timeTraceProfilerBeginEntry("event", "detail"); + entry.begin(); + ASSERT_TRUE(entry.Name.empty()); + ASSERT_TRUE(entry.Detail.empty()); + ASSERT_EQ(entry.Start, TimeTraceProfilerEntry::TimePointType()); + ASSERT_EQ(entry.End, TimeTraceProfilerEntry::TimePointType()); + timeTraceProfilerEndEntry(std::move(entry)); +} + } // namespace