[support] Allow TimeProfiler tracing across threads

[mbs-modular]

Summary

*DRAFT*

The change to high_precision_clock to gain cross-thread consistency has not been tested on all platforms. Also need to measure slowdown on all platforms. Think we're going to use this change internally for a while before attempting to push upstream.

---

This change allows a TimeProfiler profiling entry to be created
on one thread and finished on another. This was triggered by a use
case where we needed to trace the scheduling delay for work items
ultimately handled by independent worker threads.

The clock is changed to std::chrono::high_resolution_clock, both for
its increased precision (our work items can be in the us range), but
also for its cross-thread consistency (all threads see the same clock).

As a pleasant side effect it is now possible to pay for the cost of
constructing a profiling entry with a possibly expensive detail string
outside of the critical section we wish to trace. I think we could do
better with shifting the cost of constructing detail strings to the final
trace writing phase, given the API already supports providing detail
strings via a callback. But I've not audited the code to check if
detail closures could have their lifetimes safely extended so dramatically.

Could not find unit tests, please let me know if I missed them.

[lattner]

Adding a few reviewers who have worked on this, Russell Gallop has worked on something directly related.

[russell.gallop]

Hi @mbs-modular ,

This looks interesting. Does this help with the case @mehdi_amini outlined here: https://reviews.llvm.org/D118550/new/#3323665 ? It would be great to be able to get the TimeProfile to trace anything multi-threaded in LLVM (anything using Thread Pool), rather than having to hook it into each use.

Regarding the patch, it looks like there are a number of non-functional changes here (e.g. move and rename Entry class, making Detail optional for TimeTraceScope, some style and formatting and a few others). Would it be possible to split those out to to a separate NFC patch so there is a patch focussed on the new functionality? I'm also trying to think whether the change to high_resolution_clock might have side-effects so could be a separate patch. I feel like it's the kind of thing that might trip up on one platform or another.

Could not find unit tests, please let me know if I missed them.

I'm not aware of any unit tests (though they sound like a good idea :-) ). There are some lit tests in clang/test/Driver and lld/test.

Likely unrelated but there is an outstanding bug on time-trace (https://github.com/llvm/llvm-project/issues/56554). Just noting it here in case anything here either fixes or desensitizes it.

Regards
Russ

[mbs-modular]

Thanks @russell.gallop.

Does this help with the case @mehdi_amini outlined here: https://reviews.llvm.org/D118550/new/#3323665 ?

If I'm reading correctly that is lamenting the need for each thread to establish and tear down it's own context as a consequence of relying on the TLS profiling context. That's not a concern for us, and the TLS approach seems inevitable given the current push/pop API. A global lock-free ring for all events is probably a better approach, but that's a new impl entirely I think.

Our use case is pretty simple:

// thread A
auto entry = timeTraceProfilerBeginEntry("e")
enqueuWorkItem([entry = std::move(entry)]() {
    // thread B
    timeTraceProfilerEndEntry(std::move(entry));
    ... do the work ...
})

The entries for "e" now measure scheduling latency.

Would it be possible to split those out to to a separate NFC patch

Sure thing.

I'm also trying to think whether the change to high_resolution_clock might have side-effects

Likewise a bit troubled by that. I think we should pessimistically assume there's a memory barrier in the high res clock, so must make sure to never ask for now() from it if tracing is disabled. I think I need an extra if (TimeTraceProfilerInstance) test in timeTraceProfilerBeginEntry, and will check elsewhere.

there is an outstanding bug on time-trace (https://github.com/llvm/llvm-project/issues/56554).

Yes, appears unrelated. I'm avoiding any caller changes.

[mbs-modular]

NFC (mostly!) changes in https://reviews.llvm.org/D133153, will bounce back here after that.

[mbs-modular]

[support] Allow TimeProfiler tracing across threads

This change allows a TimeProfiler profiling entry to be created on one thread and finished on another. This
was triggered by a use case where we needed to trace the scheduling delay for work items ultimately handled by
independent worker threads. The clock is changed to std::chrono::high_resolution_clock, both for its
increased precision (our work items can be in the us range), but also for its cross-thread consistency (all
threads see the same clock).

As a pleasant side effect it is now possible to pay for the cost of constructing a profiling entry with a
possibly expensive detail string outside of the critical section we wish to trace. I think we could do better
with shifting the cost of constructing detail strings to the final trace writing phase, given the API already
supports providing detail strings via a callback. But I've not audited the code to check if detail closures
could have their lifetimes safely extended so dramatically.

llvm/include/llvm/Support/TimeProfiler.h

 //===- llvm/Support/TimeProfiler.h - Hierarchical Time Profiler -*- C++ -*-===//
 //
 // 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 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:
 //
 // \code
 //   {
 //     TimeTraceScope scope("my_event_name");
 //     ...my code...
 //   }
 // \endcode
 //
 // If the code to be profiled does not have a natural lexical scope then
 // it is also possible to start and end events with respect to an implicit
 // per-thread stack of profiling entries:
 //
 // \code
 //   timeTraceProfilerBegin("my_event_name");
 //   ...my code...
 //   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
 // 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. Care should be taken to make string
 // construction cheap to prevent 'Heisenperf' effects. In particular, 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
 // 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.
 //  - http://ui.perfetto.dev is the replacement for the above, under active
 //    development by Google as part of the 'Perfetto' project.
 //  - https://www.speedscope.app/ has also been reported as an option.
 //
 // 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.
 //
 //===----------------------------------------------------------------------===//
 
 #ifndef LLVM_SUPPORT_TIMEPROFILER_H
 #define LLVM_SUPPORT_TIMEPROFILER_H
 
 #include "llvm/ADT/STLFunctionalExtras.h"
 #include "llvm/Support/Error.h"
 
+#include <chrono>
+
 namespace llvm {
 
 class raw_pwrite_stream;
 
 struct TimeTraceProfiler;
 TimeTraceProfiler *getTimeTraceProfilerInstance();
 
 /// Initialize the time trace profiler.

 /// matching End pair but they can nest.
 void timeTraceProfilerBegin(StringRef Name, StringRef Detail);
 void timeTraceProfilerBegin(StringRef Name,
                             llvm::function_ref<std::string()> Detail);
 
 /// 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<ClockType>;
+
+  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<std::chrono::microseconds>(Start) -
+            std::chrono::time_point_cast<std::chrono::microseconds>(StartTime))
+        .count();
+  }
+
+  ClockType::rep getFlameGraphDurUs() const {
+    return (std::chrono::time_point_cast<std::chrono::microseconds>(End) -
+            std::chrono::time_point_cast<std::chrono::microseconds>(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<std::string()> 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
 /// is not initialized, the overhead is a single branch.
 struct TimeTraceScope {
 
   TimeTraceScope() = delete;
   TimeTraceScope(const TimeTraceScope &) = delete;

llvm/lib/Support/TimeProfiler.cpp

 
 // 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 ClockType = TimeTraceProfilerEntry::ClockType;
+using TimePointType = TimeTraceProfilerEntry::TimePointType;
 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();
+    end(std::move(Stack.back()));
+    Stack.pop_back();
+  }
+
+  void end(TimeTraceProfilerEntry &&E) {
     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");
void end(TimeTraceProfilerEntry &&E) {
     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);
void llvm::timeTraceProfilerBegin(StringRef Name,
   if (TimeTraceProfilerInstance != nullptr)
     TimeTraceProfilerInstance->begin(std::string(Name), Detail);
 }
 
 void llvm::timeTraceProfilerEnd() {
   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<std::string()> 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));
+}

llvm/unittests/Support/TimeProfilerTest.cpp

 
 TEST(TimeProfiler, Begin_End_Disabled) {
   // Nothing should be observable here. The test is really just making sure
   // we've not got a stray nullptr deref.
   timeTraceProfilerBegin("event", "detail");
   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