[clang] [llvm] Use TimeTraceProfilerEntry for Source span (PR #83961)
Takuto Ikuta via cfe-commits
cfe-commits at lists.llvm.org
Tue Mar 5 21:22:56 PST 2024
https://github.com/atetubou updated https://github.com/llvm/llvm-project/pull/83961
>From 90ebde07f7fa426a37dd4bdc362e1a809aaf0844 Mon Sep 17 00:00:00 2001
From: Takuto Ikuta <tikuta at google.com>
Date: Mon, 4 Mar 2024 19:12:31 +0900
Subject: [PATCH 1/2] Expose TimeTraceProfiler for Async Events
---
llvm/include/llvm/Support/TimeProfiler.h | 34 +++++--
llvm/lib/Support/TimeProfiler.cpp | 101 ++++++++++++++------
llvm/unittests/Support/TimeProfilerTest.cpp | 11 +++
3 files changed, 107 insertions(+), 39 deletions(-)
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.
>From eaf3fd48d1ae8fa011a430e0ad61acd512ba713b Mon Sep 17 00:00:00 2001
From: Takuto Ikuta <tikuta at google.com>
Date: Mon, 4 Mar 2024 17:02:05 +0900
Subject: [PATCH 2/2] Use timeTraceAsyncProfilerBegin for Source span
---
clang/lib/Sema/Sema.cpp | 10 ++++++----
1 file changed, 6 insertions(+), 4 deletions(-)
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,
More information about the cfe-commits
mailing list