Use timeTraceAsyncProfilerBegin for Source span #83961

atetubou · 2024-03-05T05:41:23Z

This fixes incorrect trace for #56554.

This shows trace like
https://ui.perfetto.dev/#!/?s=aa809778dc50f2b155b062317fa18bbe2bb2fb9175e6282add8121c7c178214e
for the case shown in #83236.

#83778 is preparing PR.

Fix #56554

llvmbot · 2024-03-06T05:54:14Z

@llvm/pr-subscribers-clang

@llvm/pr-subscribers-llvm-support

Author: Takuto Ikuta (atetubou)

Changes

This fixes incorrect trace for #56554.

This shows trace like
https://ui.perfetto.dev/#!/?s=aa809778dc50f2b155b062317fa18bbe2bb2fb9175e6282add8121c7c178214e
for the case shown in #83236.

#83778 is preparing PR.

Fix #56554

Full diff: https://github.com/llvm/llvm-project/pull/83961.diff

4 Files Affected:

(modified) clang/lib/Sema/Sema.cpp (+6-4)
(modified) llvm/include/llvm/Support/TimeProfiler.h (+25-9)
(modified) llvm/lib/Support/TimeProfiler.cpp (+71-30)
(modified) llvm/unittests/Support/TimeProfilerTest.cpp (+11)

diff --git a/clang/lib/Sema/Sema.cpp b/clang/lib/Sema/Sema.cpp
index cfb653e665ea03..2fb12e327c304d 100644
--- a/clang/lib/Sema/Sema.cpp
+++ b/clang/lib/Sema/Sema.cpp
@@ -135,6 +135,7 @@ namespace sema {
 class SemaPPCallbacks : public PPCallbacks {
   Sema *S = nullptr;
   llvm::SmallVector<SourceLocation, 8> IncludeStack;
+  llvm::SmallVector<llvm::TimeTraceProfilerEntry *, 8> ProfilerStack;
 
 public:
   void set(Sema &S) { this->S = &S; }
@@ -153,8 +154,8 @@ class SemaPPCallbacks : public PPCallbacks {
       if (IncludeLoc.isValid()) {
         if (llvm::timeTraceProfilerEnabled()) {
           OptionalFileEntryRef FE = SM.getFileEntryRefForID(SM.getFileID(Loc));
-          llvm::timeTraceProfilerBegin("Source", FE ? FE->getName()
-                                                    : StringRef("<unknown>"));
+          ProfilerStack.push_back(llvm::timeTraceAsyncProfilerBegin(
+              "Source", FE ? FE->getName() : StringRef("<unknown>")));
         }
 
         IncludeStack.push_back(IncludeLoc);
@@ -166,8 +167,9 @@ class SemaPPCallbacks : public PPCallbacks {
     }
     case ExitFile:
       if (!IncludeStack.empty()) {
-        if (llvm::timeTraceProfilerEnabled())
-          llvm::timeTraceProfilerEnd();
+        if (llvm::timeTraceProfilerEnabled()) {
+          llvm::timeTraceProfilerEnd(ProfilerStack.pop_back_val());
+        }
 
         S->DiagnoseNonDefaultPragmaAlignPack(
             Sema::PragmaAlignPackDiagnoseKind::ChangedStateAtExit,
diff --git a/llvm/include/llvm/Support/TimeProfiler.h b/llvm/include/llvm/Support/TimeProfiler.h
index 454a65f70231f4..31f7df10916db9 100644
--- a/llvm/include/llvm/Support/TimeProfiler.h
+++ b/llvm/include/llvm/Support/TimeProfiler.h
@@ -86,6 +86,8 @@ class raw_pwrite_stream;
 struct TimeTraceProfiler;
 TimeTraceProfiler *getTimeTraceProfilerInstance();
 
+struct TimeTraceProfilerEntry;
+
 /// Initialize the time trace profiler.
 /// This sets up the global \p TimeTraceProfilerInstance
 /// variable to be the profiler instance.
@@ -120,19 +122,30 @@ Error timeTraceProfilerWrite(StringRef PreferredFileName,
 /// 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,
-                            llvm::function_ref<std::string()> Detail);
+TimeTraceProfilerEntry *timeTraceProfilerBegin(StringRef Name,
+                                               StringRef Detail);
+TimeTraceProfilerEntry *
+timeTraceProfilerBegin(StringRef Name,
+                       llvm::function_ref<std::string()> Detail);
+
+/// Manually begin a time section, with the given \p Name and \p Detail.
+/// This starts Async Events having \p Name as a category which is shown
+/// separately from other traces. See
+/// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.jh64i9l3vwa1
+/// for more details.
+TimeTraceProfilerEntry *timeTraceAsyncProfilerBegin(StringRef Name,
+                                                    StringRef Detail);
 
 /// Manually end the last time section.
 void timeTraceProfilerEnd();
+void timeTraceProfilerEnd(TimeTraceProfilerEntry *E);
 
 /// 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 {
-
+class TimeTraceScope {
+public:
   TimeTraceScope() = delete;
   TimeTraceScope(const TimeTraceScope &) = delete;
   TimeTraceScope &operator=(const TimeTraceScope &) = delete;
@@ -141,20 +154,23 @@ struct TimeTraceScope {
 
   TimeTraceScope(StringRef Name) {
     if (getTimeTraceProfilerInstance() != nullptr)
-      timeTraceProfilerBegin(Name, StringRef(""));
+      Entry = timeTraceProfilerBegin(Name, StringRef(""));
   }
   TimeTraceScope(StringRef Name, StringRef Detail) {
     if (getTimeTraceProfilerInstance() != nullptr)
-      timeTraceProfilerBegin(Name, Detail);
+      Entry = timeTraceProfilerBegin(Name, Detail);
   }
   TimeTraceScope(StringRef Name, llvm::function_ref<std::string()> Detail) {
     if (getTimeTraceProfilerInstance() != nullptr)
-      timeTraceProfilerBegin(Name, Detail);
+      Entry = timeTraceProfilerBegin(Name, Detail);
   }
   ~TimeTraceScope() {
     if (getTimeTraceProfilerInstance() != nullptr)
-      timeTraceProfilerEnd();
+      timeTraceProfilerEnd(Entry);
   }
+
+private:
+  TimeTraceProfilerEntry *Entry = nullptr;
 };
 
 } // end namespace llvm
diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp
index 4d625b3eb5b170..3114f8e7ded598 100644
--- a/llvm/lib/Support/TimeProfiler.cpp
+++ b/llvm/lib/Support/TimeProfiler.cpp
@@ -11,6 +11,7 @@
 //===----------------------------------------------------------------------===//
 
 #include "llvm/Support/TimeProfiler.h"
+#include "llvm/ADT/STLExtras.h"
 #include "llvm/ADT/STLFunctionalExtras.h"
 #include "llvm/ADT/StringMap.h"
 #include "llvm/Support/JSON.h"
@@ -20,6 +21,7 @@
 #include <algorithm>
 #include <cassert>
 #include <chrono>
+#include <memory>
 #include <mutex>
 #include <string>
 #include <vector>
@@ -64,17 +66,19 @@ using CountAndDurationType = std::pair<size_t, DurationType>;
 using NameAndCountAndDurationType =
     std::pair<std::string, CountAndDurationType>;
 
+} // anonymous namespace
+
 /// Represents an open or completed time section entry to be captured.
-struct TimeTraceProfilerEntry {
+struct llvm::TimeTraceProfilerEntry {
   const TimePointType Start;
   TimePointType End;
   const std::string Name;
   const std::string Detail;
-
+  const bool AsyncEvent = false;
   TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
-                         std::string &&Dt)
+                         std::string &&Dt, bool Ae)
       : Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
-        Detail(std::move(Dt)) {}
+        Detail(std::move(Dt)), AsyncEvent(Ae) {}
 
   // Calculate timings for FlameGraph. Cast time points to microsecond precision
   // rather than casting duration. This avoids truncation issues causing inner
@@ -92,8 +96,6 @@ struct TimeTraceProfilerEntry {
   }
 };
 
-} // anonymous namespace
-
 struct llvm::TimeTraceProfiler {
   TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "")
       : BeginningOfTime(system_clock::now()), StartTime(ClockType::now()),
@@ -102,23 +104,24 @@ struct llvm::TimeTraceProfiler {
     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());
+  TimeTraceProfilerEntry *begin(std::string Name,
+                                llvm::function_ref<std::string()> Detail,
+                                bool AsyncEvent = false) {
+    Stack.emplace_back(std::make_unique<TimeTraceProfilerEntry>(
+        ClockType::now(), TimePointType(), std::move(Name), Detail(),
+        AsyncEvent));
+    return Stack.back().get();
   }
 
   void end() {
+    TimeTraceProfilerEntry *E = Stack.back().get();
+    end(*E);
+  }
+
+  void end(TimeTraceProfilerEntry &E) {
     assert(!Stack.empty() && "Must call begin() first");
-    TimeTraceProfilerEntry &E = Stack.back();
     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");
-
     // Calculate duration at full precision for overall counts.
     DurationType Duration = E.End - E.Start;
 
@@ -132,15 +135,18 @@ struct llvm::TimeTraceProfiler {
     // 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 TimeTraceProfilerEntry &Val) {
-                        return Val.Name == E.Name;
+                      [&](const std::unique_ptr<TimeTraceProfilerEntry> &Val) {
+                        return Val->Name == E.Name;
                       })) {
       auto &CountAndTotal = CountAndTotalPerName[E.Name];
       CountAndTotal.first++;
       CountAndTotal.second += Duration;
-    }
+    };
 
-    Stack.pop_back();
+    llvm::erase_if(Stack,
+                   [&](const std::unique_ptr<TimeTraceProfilerEntry> &Val) {
+                     return Val.get() == &E;
+                   });
   }
 
   // Write events from this TimeTraceProfilerInstance and
@@ -168,14 +174,32 @@ struct llvm::TimeTraceProfiler {
       J.object([&] {
         J.attribute("pid", Pid);
         J.attribute("tid", int64_t(Tid));
-        J.attribute("ph", "X");
         J.attribute("ts", StartUs);
-        J.attribute("dur", DurUs);
+        if (E.AsyncEvent) {
+          J.attribute("cat", E.Name);
+          J.attribute("ph", "b");
+          J.attribute("id", 0);
+        } else {
+          J.attribute("ph", "X");
+          J.attribute("dur", DurUs);
+        }
         J.attribute("name", E.Name);
         if (!E.Detail.empty()) {
           J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
         }
       });
+
+      if (E.AsyncEvent) {
+        J.object([&] {
+          J.attribute("pid", Pid);
+          J.attribute("tid", int64_t(Tid));
+          J.attribute("ts", StartUs + DurUs);
+          J.attribute("cat", E.Name);
+          J.attribute("ph", "e");
+          J.attribute("id", 0);
+          J.attribute("name", E.Name);
+        });
+      }
     };
     for (const TimeTraceProfilerEntry &E : Entries)
       writeEvent(E, this->Tid);
@@ -269,7 +293,7 @@ struct llvm::TimeTraceProfiler {
     J.objectEnd();
   }
 
-  SmallVector<TimeTraceProfilerEntry, 16> Stack;
+  SmallVector<std::unique_ptr<TimeTraceProfilerEntry>, 16> Stack;
   SmallVector<TimeTraceProfilerEntry, 128> Entries;
   StringMap<CountAndDurationType> CountAndTotalPerName;
   // System clock time when the session was begun.
@@ -341,19 +365,36 @@ Error llvm::timeTraceProfilerWrite(StringRef PreferredFileName,
   return Error::success();
 }
 
-void llvm::timeTraceProfilerBegin(StringRef Name, StringRef Detail) {
+TimeTraceProfilerEntry *llvm::timeTraceProfilerBegin(StringRef Name,
+                                                     StringRef Detail) {
+  if (TimeTraceProfilerInstance != nullptr)
+    return TimeTraceProfilerInstance->begin(
+        std::string(Name), [&]() { return std::string(Detail); }, false);
+  return nullptr;
+}
+
+TimeTraceProfilerEntry *
+llvm::timeTraceProfilerBegin(StringRef Name,
+                             llvm::function_ref<std::string()> Detail) {
   if (TimeTraceProfilerInstance != nullptr)
-    TimeTraceProfilerInstance->begin(std::string(Name),
-                                     [&]() { return std::string(Detail); });
+    return TimeTraceProfilerInstance->begin(std::string(Name), Detail, false);
+  return nullptr;
 }
 
-void llvm::timeTraceProfilerBegin(StringRef Name,
-                                  llvm::function_ref<std::string()> Detail) {
+TimeTraceProfilerEntry *llvm::timeTraceAsyncProfilerBegin(StringRef Name,
+                                                          StringRef Detail) {
   if (TimeTraceProfilerInstance != nullptr)
-    TimeTraceProfilerInstance->begin(std::string(Name), Detail);
+    return TimeTraceProfilerInstance->begin(
+        std::string(Name), [&]() { return std::string(Detail); }, true);
+  return nullptr;
 }
 
 void llvm::timeTraceProfilerEnd() {
   if (TimeTraceProfilerInstance != nullptr)
     TimeTraceProfilerInstance->end();
 }
+
+void llvm::timeTraceProfilerEnd(TimeTraceProfilerEntry *E) {
+  if (TimeTraceProfilerInstance != nullptr)
+    TimeTraceProfilerInstance->end(*E);
+}
diff --git a/llvm/unittests/Support/TimeProfilerTest.cpp b/llvm/unittests/Support/TimeProfilerTest.cpp
index 6be716bae6b3fb..bb820ec99a393e 100644
--- a/llvm/unittests/Support/TimeProfilerTest.cpp
+++ b/llvm/unittests/Support/TimeProfilerTest.cpp
@@ -54,6 +54,17 @@ TEST(TimeProfiler, Begin_End_Smoke) {
   ASSERT_TRUE(json.find(R"("detail":"detail")") != std::string::npos);
 }
 
+TEST(TimeProfiler, Async_Begin_End_Smoke) {
+  setupProfiler();
+
+  auto *Profiler = timeTraceAsyncProfilerBegin("event", "detail");
+  timeTraceProfilerEnd(Profiler);
+
+  std::string json = teardownProfiler();
+  ASSERT_TRUE(json.find(R"("name":"event")") != std::string::npos);
+  ASSERT_TRUE(json.find(R"("detail":"detail")") != std::string::npos);
+}
+
 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.

atetubou · 2024-03-11T01:35:53Z

@ZequanWu could you take a look this?

ZequanWu

IIUC, the approach you choose here is to let SemaPPCallbacks control the "entered file stack" and allow it to remove element (which is file) from middle of the internal stack in TimeTraceProfiler, but this creates async event which is not designed for this purpose.

Can we let SemaPPCallbacks track the last push file into the stack and when exit file, pop all the elements from the stack until we popped the last pushed file?

llvm/lib/Support/TimeProfiler.cpp

atetubou · 2024-03-12T06:53:22Z

IIUC, the approach you choose here is to let SemaPPCallbacks control the "entered file stack" and allow it to remove element (which is file) from middle of the internal stack in TimeTraceProfiler, but this creates async event which is not designed for this purpose.

Can we let SemaPPCallbacks track the last push file into the stack and when exit file, pop all the elements from the stack until we popped the last pushed file?

As I wrote in #56554 (comment), file level span and syntax tree level span should be handled asynchronously. So using such implementation produces incorrect trace in other edge cases.

ZequanWu · 2024-03-12T15:44:04Z

IIUC, the approach you choose here is to let SemaPPCallbacks control the "entered file stack" and allow it to remove element (which is file) from middle of the internal stack in TimeTraceProfiler, but this creates async event which is not designed for this purpose.
Can we let SemaPPCallbacks track the last push file into the stack and when exit file, pop all the elements from the stack until we popped the last pushed file?

As I wrote in #56554 (comment), file level span and syntax tree level span should be handled asynchronously. So using such implementation produces incorrect trace in other edge cases.

Can we choose to expose a handle (maybe an unique id for each entry) from TimeTraceProfiler instead of exposing the internal entry?

atetubou · 2024-03-13T08:10:44Z

IIUC, the approach you choose here is to let SemaPPCallbacks control the "entered file stack" and allow it to remove element (which is file) from middle of the internal stack in TimeTraceProfiler, but this creates async event which is not designed for this purpose.
Can we let SemaPPCallbacks track the last push file into the stack and when exit file, pop all the elements from the stack until we popped the last pushed file?

As I wrote in #56554 (comment), file level span and syntax tree level span should be handled asynchronously. So using such implementation produces incorrect trace in other edge cases.

Can we choose to expose a handle (maybe an unique id for each entry) from TimeTraceProfiler instead of exposing the internal entry?

I think pointer to TimeTraceProfilerEntry is already like handle as definition of the struct is not written in header file. Having another handle for that seems unnecessary indirection layer to me. Or better to change the name of struct?

ZequanWu · 2024-03-13T18:43:38Z

IIUC, the approach you choose here is to let SemaPPCallbacks control the "entered file stack" and allow it to remove element (which is file) from middle of the internal stack in TimeTraceProfiler, but this creates async event which is not designed for this purpose.
Can we let SemaPPCallbacks track the last push file into the stack and when exit file, pop all the elements from the stack until we popped the last pushed file?

As I wrote in #56554 (comment), file level span and syntax tree level span should be handled asynchronously. So using such implementation produces incorrect trace in other edge cases.

Can we choose to expose a handle (maybe an unique id for each entry) from TimeTraceProfiler instead of exposing the internal entry?

I think pointer to TimeTraceProfilerEntry is already like handle as definition of the struct is not written in header file. Having another handle for that seems unnecessary indirection layer to me. Or better to change the name of struct?

Okay, make sense. Looks good for me.
Adding @MaskRay to review in case he has something to say.

To avoid issue like #56554 and #83236 due to no guarantees for nested relationships between file level span and syntax tree level span, I'd like to have a `timeTraceAsyncProfilerBegin` specific to trace handling only `Source` spans around https://github.com/llvm/llvm-project/blob/8715f256911786520bb727ce067098d7082ac45c/clang/lib/Sema/Sema.cpp#L153-L170. This is a preparation PR to do that in [following PR](#83961).

atetubou · 2024-03-22T05:20:27Z

@MaskRay could you review this?

To avoid issue like llvm#56554 and llvm#83236 due to no guarantees for nested relationships between file level span and syntax tree level span, I'd like to have a `timeTraceAsyncProfilerBegin` specific to trace handling only `Source` spans around https://github.com/llvm/llvm-project/blob/8715f256911786520bb727ce067098d7082ac45c/clang/lib/Sema/Sema.cpp#L153-L170. This is a preparation PR to do that in [following PR](llvm#83961).

llvm/lib/Support/TimeProfiler.cpp

MaskRay · 2024-03-26T00:55:46Z

clang/lib/Sema/Sema.cpp

-        if (llvm::timeTraceProfilerEnabled())
-          llvm::timeTraceProfilerEnd();
+        if (llvm::timeTraceProfilerEnabled()) {
+          llvm::timeTraceProfilerEnd(ProfilerStack.pop_back_val());


https://llvm.org/docs/CodingStandards.html#don-t-use-braces-on-simple-single-statement-bodies-of-if-else-loop-statements

This fixes incorrect trace for #56554. This shows trace like https://ui.perfetto.dev/#!/?s=aa809778dc50f2b155b062317fa18bbe2bb2fb9175e6282add8121c7c178214e for the case shown in #83236. #83778 is preparing PR. Fix #56554

MaskRay · 2024-03-26T01:05:12Z

Manually fixed the style and landed as 83eb8ae

atetubou · 2024-03-26T04:50:48Z

Thank you for your review and merge!

atetubou force-pushed the use_new_trace branch from cdc771f to 2de443f Compare March 5, 2024 05:42

This was referenced Mar 5, 2024

Expose TimeTraceProfiler for Async Events #83778

Merged

[clang][NFC] Format clang/lib/Sema/Sema.cpp #83974

Closed

atetubou force-pushed the use_new_trace branch from 2de443f to eaf3fd4 Compare March 6, 2024 05:22

atetubou changed the title ~~Use TimeTraceProfilerEntry for Source span~~ Use timeTraceAsyncProfilerBegin for Source span Mar 6, 2024

atetubou marked this pull request as ready for review March 6, 2024 05:53

llvmbot added clang Clang issues not falling into any other category clang:frontend Language frontend issues, e.g. anything involving "Sema" llvm:support labels Mar 6, 2024

ZequanWu reviewed Mar 11, 2024

View reviewed changes

llvm/lib/Support/TimeProfiler.cpp Outdated Show resolved Hide resolved

llvm/lib/Support/TimeProfiler.cpp Outdated Show resolved Hide resolved

ZequanWu requested a review from MaskRay March 13, 2024 18:43

atetubou force-pushed the use_new_trace branch from e32f0fb to dad326b Compare March 18, 2024 09:03

Use timeTraceAsyncProfilerBegin for Source span

e61cf0e

atetubou force-pushed the use_new_trace branch from dad326b to e61cf0e Compare March 21, 2024 01:48

ZequanWu approved these changes Mar 25, 2024

View reviewed changes

llvm/lib/Support/TimeProfiler.cpp Outdated Show resolved Hide resolved

MaskRay reviewed Mar 26, 2024

View reviewed changes

MaskRay approved these changes Mar 26, 2024

View reviewed changes

MaskRay closed this Mar 26, 2024

atetubou deleted the use_new_trace branch March 26, 2024 04:50

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Use timeTraceAsyncProfilerBegin for Source span #83961

Use timeTraceAsyncProfilerBegin for Source span #83961

atetubou commented Mar 5, 2024 •

edited

llvmbot commented Mar 6, 2024 •

edited

atetubou commented Mar 11, 2024

ZequanWu left a comment

atetubou commented Mar 12, 2024

ZequanWu commented Mar 12, 2024

atetubou commented Mar 13, 2024

ZequanWu commented Mar 13, 2024

atetubou commented Mar 22, 2024

MaskRay Mar 26, 2024

MaskRay commented Mar 26, 2024

atetubou commented Mar 26, 2024

Use timeTraceAsyncProfilerBegin for Source span #83961

Use timeTraceAsyncProfilerBegin for Source span #83961

Conversation

atetubou commented Mar 5, 2024 • edited

llvmbot commented Mar 6, 2024 • edited

atetubou commented Mar 11, 2024

ZequanWu left a comment

Choose a reason for hiding this comment

atetubou commented Mar 12, 2024

ZequanWu commented Mar 12, 2024

atetubou commented Mar 13, 2024

ZequanWu commented Mar 13, 2024

atetubou commented Mar 22, 2024

MaskRay Mar 26, 2024

Choose a reason for hiding this comment

MaskRay commented Mar 26, 2024

atetubou commented Mar 26, 2024

atetubou commented Mar 5, 2024 •

edited

llvmbot commented Mar 6, 2024 •

edited