[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.
+//
+// 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 <chrono>
 
 namespace llvm {
 
 class raw_pwrite_stream;
 
 struct TimeTraceProfiler;
 TimeTraceProfiler *getTimeTraceProfilerInstance();
 

 /// unable to open the file for writing.
 Error timeTraceProfilerWrite(StringRef PreferredFileName,
                              StringRef FallbackFileName);
 
 /// Manually begin a time section, with the given \p Name and \p Detail.
 /// 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<std::string()> 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<ClockType>;
+
+  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<std::chrono::microseconds>(Start) -
+            std::chrono::time_point_cast<std::chrono::microseconds>(StartTime))
+        .count();
+  }
+
+  std::chrono::steady_clock::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 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<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.
+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
 /// is not initialized, the overhead is a single branch.
 struct TimeTraceScope {
 
   TimeTraceScope() = delete;
   TimeTraceScope(const TimeTraceScope &) = delete;
   TimeTraceScope &operator=(const TimeTraceScope &) = delete;
   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);
   }
   TimeTraceScope(StringRef Name, llvm::function_ref<std::string()> Detail) {
     if (getTimeTraceProfilerInstance() != nullptr)
       timeTraceProfilerBegin(Name, Detail);
   }
   ~TimeTraceScope() {
     if (getTimeTraceProfilerInstance() != nullptr)
       timeTraceProfilerEnd();
   }
 };
 
 } // end namespace llvm
 
 #endif

llvm/lib/Support/TimeProfiler.cpp

 
 #include "llvm/Support/TimeProfiler.h"
 #include "llvm/ADT/STLFunctionalExtras.h"
 #include "llvm/ADT/StringMap.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 {
 
 struct TimeTraceProfilerInstances {
   std::mutex Lock;
   std::vector<TimeTraceProfiler *> List;
 };
 
 TimeTraceProfilerInstances &getTimeTraceProfilerInstances() {
   static TimeTraceProfilerInstances Instances;
   return Instances;
 }
 
 } // anonymous namespace
 
 // Per Thread instance
 static LLVM_THREAD_LOCAL TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
 
 TimeTraceProfiler *llvm::getTimeTraceProfilerInstance() {
   return TimeTraceProfilerInstance;
 }
 
-typedef duration<steady_clock::rep, steady_clock::period> DurationType;
-typedef time_point<steady_clock> TimePointType;
-typedef std::pair<size_t, DurationType> CountAndDurationType;
-typedef std::pair<std::string, CountAndDurationType>
-    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<microseconds>(Start) -
-            time_point_cast<microseconds>(StartTime))
-        .count();
-  }
-
-  steady_clock::rep getFlameGraphDurUs() const {
-    return (time_point_cast<microseconds>(End) -
-            time_point_cast<microseconds>(Start))
-        .count();
-  }
-};
-} // namespace
+using ClockType = TimeProfilerEntry::ClockType;
+using TimePointType = TimeProfilerEntry::TimePointType;
+using DurationType = std::chrono::duration<std::chrono::steady_clock::rep,
+                                           std::chrono::steady_clock::period>;
+using CountAndDurationType = std::pair<size_t, DurationType>;
+using NameAndCountAndDurationType =
+    std::pair<std::string, CountAndDurationType>;
 
 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<std::string()> 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() >=
+    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<microseconds>(Duration).count() >= TimeTraceGranularity)
-      Entries.emplace_back(E);
+    if (std::chrono::duration_cast<std::chrono::microseconds>(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
     // 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 (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
   // ThreadTimeTraceProfilerInstances.
   void write(raw_pwrite_stream &OS) {
     // Acquire Mutex as reading ThreadTimeTraceProfilerInstances.
     auto &Instances = getTimeTraceProfilerInstances();
     std::lock_guard<std::mutex> Lock(Instances.Lock);
auto writeEvent = [&](const auto &E, uint64_t Tid) {
         J.attribute("ts", StartUs);
         J.attribute("dur", DurUs);
         J.attribute("name", E.Name);
         if (!E.Detail.empty()) {
           J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
         }
       });
     };
-    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
     // longest one.
     // Find highest used thread id.
     uint64_t MaxTid = this->Tid;
     for (const TimeTraceProfiler *TTP : Instances.List)
       MaxTid = std::max(MaxTid, TTP->Tid);
void write(raw_pwrite_stream &OS) {
     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 DurUs = std::chrono::duration_cast<std::chrono::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);
for (const TimeTraceProfiler *TTP : Instances.List)
       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.attribute(
+        "beginningOfTime",
+        std::chrono::time_point_cast<std::chrono::microseconds>(BeginningOfTime)
 
     J.objectEnd();
   }
 
-  SmallVector<Entry, 16> Stack;
-  SmallVector<Entry, 128> Entries;
+  SmallVector<TimeProfilerEntry, 16> Stack;
+  SmallVector<TimeProfilerEntry, 128> Entries;
   StringMap<CountAndDurationType> CountAndTotalPerName;
-  const time_point<system_clock> BeginningOfTime;
+  const TimePointType 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;
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(std::string(Name),
-                                     [&]() { return std::string(Detail); });
+    TimeTraceProfilerInstance->begin({std::string(Name), std::string(Detail)});
 }
 
 void llvm::timeTraceProfilerBegin(StringRef Name,
                                   llvm::function_ref<std::string()> 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<std::string()> Detail) {
+  return {std::string(Name), Detail()};
+}
+
+void llvm::timeTraceProfilerEndEntry(TimeProfilerEntry &&Entry) {
+  if (TimeTraceProfilerInstance != nullptr)
+    TimeTraceProfilerInstance->end(std::move(Entry));
+}