[TimeProfiler] Added instant events to llvm TimeProfiler. #103039
Merged
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
|
✅ With the latest revision this PR passed the C/C++ code formatter. |
Contributor
|
What is the reason for changing from // Instant event.
struct TimeProfilerInstantEntry {
const TimePointType Instant;
const std::string Name;
TimeTraceMetadata Metadata;
};
// Duration event.
struct TimeProfilerDurationEntry {
const TimePointType Start;
TimePointType End;
const std::string Name;
TimeTraceMetadata Metadata;
std::vector<std::unique_ptr<TimeTraceProfilerInstantEntry>> InstantEvents; // Instant event associated to the duration event.
}This will remove the need for different implementations for each event type and reduce the complexity. We can also move the |
ivanaivanovska
force-pushed
the
instantevents
branch
from
25413e8 to
3a8d8ee
Compare
ilya-biryukov
requested changes
Aug 28, 2024
usx95
reviewed
Aug 29, 2024
llvmbot
added
clang
Member
|
@llvm/pr-subscribers-llvm-support @llvm/pr-subscribers-clang Author: None (ivanaivanovska) ChangesAdded an instant event type and issuing such events each time a template instantiation is deferred. Full diff: https://github.com/llvm/llvm-project/pull/103039.diff 5 Files Affected:
diff --git a/clang/lib/Sema/SemaExpr.cpp b/clang/lib/Sema/SemaExpr.cpp
index 95f53dfefbcc52..a7dd01c936bac8 100644
--- a/clang/lib/Sema/SemaExpr.cpp
+++ b/clang/lib/Sema/SemaExpr.cpp
@@ -18,6 +18,7 @@
#include "clang/AST/ASTLambda.h"
#include "clang/AST/ASTMutationListener.h"
#include "clang/AST/CXXInheritance.h"
+#include "clang/AST/Decl.h"
#include "clang/AST/DeclObjC.h"
#include "clang/AST/DeclTemplate.h"
#include "clang/AST/EvaluatedExprVisitor.h"
@@ -64,6 +65,7 @@
#include "llvm/Support/Casting.h"
#include "llvm/Support/ConvertUTF.h"
#include "llvm/Support/SaveAndRestore.h"
+#include "llvm/Support/TimeProfiler.h"
#include "llvm/Support/TypeSize.h"
#include <optional>
@@ -18046,6 +18048,19 @@ void Sema::MarkFunctionReferenced(SourceLocation Loc, FunctionDecl *Func,
std::make_pair(Func, PointOfInstantiation));
// Notify the consumer that a function was implicitly instantiated.
Consumer.HandleCXXImplicitFunctionInstantiation(Func);
+
+ llvm::timeTraceProfilerInsert("DeferInstantiation", [&]() {
+ llvm::TimeTraceMetadata M;
+ llvm::raw_string_ostream OS(M.Detail);
+ Func->getNameForDiagnostic(OS, getPrintingPolicy(),
+ /*Qualified=*/true);
+ if (llvm::isTimeTraceVerbose()) {
+ auto Loc = SourceMgr.getExpansionLoc(Func->getLocation());
+ M.File = SourceMgr.getFilename(Loc);
+ M.Line = SourceMgr.getExpansionLineNumber(Loc);
+ }
+ return M;
+ });
}
}
} else {
diff --git a/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp b/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp
index 0e064be2391838..550add5495c833 100644
--- a/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp
+++ b/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp
@@ -4983,6 +4983,19 @@ void Sema::InstantiateFunctionDefinition(SourceLocation PointOfInstantiation,
Function->setInstantiationIsPending(true);
PendingInstantiations.push_back(
std::make_pair(Function, PointOfInstantiation));
+
+ llvm::timeTraceProfilerInsert("DeferInstantiation", [&]() {
+ llvm::TimeTraceMetadata M;
+ llvm::raw_string_ostream OS(M.Detail);
+ Function->getNameForDiagnostic(OS, getPrintingPolicy(),
+ /*Qualified=*/true);
+ if (llvm::isTimeTraceVerbose()) {
+ auto Loc = SourceMgr.getExpansionLoc(Function->getLocation());
+ M.File = SourceMgr.getFilename(Loc);
+ M.Line = SourceMgr.getExpansionLineNumber(Loc);
+ }
+ return M;
+ });
} else if (TSK == TSK_ImplicitInstantiation) {
if (AtEndOfTU && !getDiagnostics().hasErrorOccurred() &&
!getSourceManager().isInSystemHeader(PatternDecl->getBeginLoc())) {
diff --git a/clang/unittests/Support/TimeProfilerTest.cpp b/clang/unittests/Support/TimeProfilerTest.cpp
index f53fe71d630bf5..ccda12e943dd73 100644
--- a/clang/unittests/Support/TimeProfilerTest.cpp
+++ b/clang/unittests/Support/TimeProfilerTest.cpp
@@ -238,13 +238,55 @@ Frontend (test.cc)
buildTraceGraph(Json));
}
+TEST(TimeProfilerTest, ClassTemplateInstantiations) {
+ std::string Code = R"(
+ template<class T>
+ struct S
+ {
+ void foo() {}
+ void bar();
+ };
+
+ template struct S<double>; // explicit instantiation of S<double>
+
+ void user() {
+ S<int> a; // implicit instantiation of S<int>
+ S<float>* b;
+ b->foo(); // implicit instatiation of S<float> and S<float>::foo()
+ }
+ )";
+
+ setupProfiler();
+ ASSERT_TRUE(compileFromString(Code, "-std=c++20", "test.cc"));
+ std::string Json = teardownProfiler();
+ ASSERT_EQ(R"(
+Frontend (test.cc)
+| ParseClass (S)
+| InstantiateClass (S<double>, test.cc:9)
+| InstantiateFunction (S<double>::foo, test.cc:5)
+| ParseDeclarationOrFunctionDefinition (test.cc:11:5)
+| | ParseFunctionDefinition (user)
+| | | InstantiateClass (S<int>, test.cc:3)
+| | | InstantiateClass (S<float>, test.cc:3)
+| | | DeferInstantiation (S<float>::foo, test.cc:5)
+| PerformPendingInstantiations
+| | InstantiateFunction (S<float>::foo, test.cc:5)
+)",
+ buildTraceGraph(Json));
+}
+
TEST(TimeProfilerTest, TemplateInstantiations) {
std::string B_H = R"(
template <typename T>
- T fooB(T t) {
+ T fooC(T t) {
return T();
}
+ template <typename T>
+ constexpr T fooB(T t) {
+ return fooC(t);
+ }
+
#define MacroTemp(x) template <typename T> void foo##x(T) { T(); }
)";
@@ -267,14 +309,19 @@ TEST(TimeProfilerTest, TemplateInstantiations) {
std::string Json = teardownProfiler();
ASSERT_EQ(R"(
Frontend (test.cc)
+| ParseFunctionDefinition (fooC)
| ParseFunctionDefinition (fooB)
| ParseFunctionDefinition (fooMTA)
| ParseFunctionDefinition (fooA)
| ParseDeclarationOrFunctionDefinition (test.cc:3:5)
| | ParseFunctionDefinition (user)
+| | | DeferInstantiation (fooA<int>, a.h:7)
| PerformPendingInstantiations
| | InstantiateFunction (fooA<int>, a.h:7)
-| | | InstantiateFunction (fooB<int>, b.h:3)
+| | | InstantiateFunction (fooB<int>, b.h:8)
+| | | | DeferInstantiation (fooC<int>, b.h:3)
+| | | DeferInstantiation (fooMTA<int>, a.h:4)
+| | | InstantiateFunction (fooC<int>, b.h:3)
| | | InstantiateFunction (fooMTA<int>, a.h:4)
)",
buildTraceGraph(Json));
diff --git a/llvm/include/llvm/Support/TimeProfiler.h b/llvm/include/llvm/Support/TimeProfiler.h
index 9e2ba31991f542..9a6bcdefee6c20 100644
--- a/llvm/include/llvm/Support/TimeProfiler.h
+++ b/llvm/include/llvm/Support/TimeProfiler.h
@@ -83,6 +83,8 @@ namespace llvm {
class raw_pwrite_stream;
+enum class TimeTraceEventType { CompleteEvent, InstantEvent, AsyncEvent };
+
struct TimeTraceMetadata {
std::string Detail;
// Source file and line number information for the event.
@@ -152,6 +154,11 @@ timeTraceProfilerBegin(StringRef Name,
TimeTraceProfilerEntry *timeTraceAsyncProfilerBegin(StringRef Name,
StringRef Detail);
+// Mark an instant event.
+void timeTraceProfilerInsert(StringRef Name,
+ llvm::function_ref<TimeTraceMetadata()> Metadata);
+void timeTraceProfilerInsert(StringRef Name, StringRef Detail);
+
/// Manually end the last time section.
void timeTraceProfilerEnd();
void timeTraceProfilerEnd(TimeTraceProfilerEntry *E);
diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp
index c2014028ddadca..31faa36c29f14d 100644
--- a/llvm/lib/Support/TimeProfiler.cpp
+++ b/llvm/lib/Support/TimeProfiler.cpp
@@ -13,6 +13,7 @@
#include "llvm/Support/TimeProfiler.h"
#include "llvm/ADT/STLExtras.h"
#include "llvm/ADT/STLFunctionalExtras.h"
+#include "llvm/ADT/SmallVector.h"
#include "llvm/ADT/StringMap.h"
#include "llvm/Support/JSON.h"
#include "llvm/Support/Path.h"
@@ -75,18 +76,18 @@ struct llvm::TimeTraceProfilerEntry {
const std::string Name;
TimeTraceMetadata Metadata;
- const bool AsyncEvent = false;
+ TimeTraceEventType EventType;
TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
- std::string &&Dt, bool Ae)
+ std::string &&Dt, TimeTraceEventType Et)
: Start(std::move(S)), End(std::move(E)), Name(std::move(N)), Metadata(),
- AsyncEvent(Ae) {
+ EventType(Et) {
Metadata.Detail = std::move(Dt);
}
TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
- TimeTraceMetadata &&Mt, bool Ae)
+ TimeTraceMetadata &&Mt, TimeTraceEventType Et)
: Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
- Metadata(std::move(Mt)), AsyncEvent(Ae) {}
+ Metadata(std::move(Mt)), EventType(Et) {}
// Calculate timings for FlameGraph. Cast time points to microsecond precision
// rather than casting duration. This avoids truncation issues causing inner
@@ -104,6 +105,23 @@ struct llvm::TimeTraceProfilerEntry {
}
};
+struct InProgressEntry {
+ std::unique_ptr<TimeTraceProfilerEntry> Event;
+ std::vector<TimeTraceProfilerEntry> InstantEvents;
+
+ InProgressEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
+ std::string &&Dt, TimeTraceEventType Et)
+ : Event(std::make_unique<TimeTraceProfilerEntry>(
+ std::move(S), std::move(E), std::move(N), std::move(Dt), Et)),
+ InstantEvents() {}
+
+ InProgressEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
+ TimeTraceMetadata &&Mt, TimeTraceEventType Et)
+ : Event(std::make_unique<TimeTraceProfilerEntry>(
+ std::move(S), std::move(E), std::move(N), std::move(Mt), Et)),
+ InstantEvents() {}
+};
+
struct llvm::TimeTraceProfiler {
TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "",
bool TimeTraceVerbose = false)
@@ -114,27 +132,46 @@ struct llvm::TimeTraceProfiler {
llvm::get_thread_name(ThreadName);
}
- TimeTraceProfilerEntry *begin(std::string Name,
- llvm::function_ref<std::string()> Detail,
- bool AsyncEvent = false) {
- Stack.emplace_back(std::make_unique<TimeTraceProfilerEntry>(
+ TimeTraceProfilerEntry *
+ begin(std::string Name, llvm::function_ref<std::string()> Detail,
+ TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent) {
+ Stack.emplace_back(std::make_unique<InProgressEntry>(
ClockType::now(), TimePointType(), std::move(Name), Detail(),
- AsyncEvent));
- return Stack.back().get();
+ EventType));
+ return Stack.back()->Event.get();
}
TimeTraceProfilerEntry *
begin(std::string Name, llvm::function_ref<TimeTraceMetadata()> Metadata,
- bool AsyncEvent = false) {
- Stack.emplace_back(std::make_unique<TimeTraceProfilerEntry>(
+ TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent) {
+ Stack.emplace_back(std::make_unique<InProgressEntry>(
+ ClockType::now(), TimePointType(), std::move(Name), Metadata(),
+ EventType));
+ return Stack.back()->Event.get();
+ }
+
+ void insert(std::string Name, llvm::function_ref<std::string()> Detail) {
+ if (Stack.empty())
+ return;
+
+ Stack.back().get()->InstantEvents.emplace_back(TimeTraceProfilerEntry(
+ ClockType::now(), TimePointType(), std::move(Name), Detail(),
+ TimeTraceEventType::InstantEvent));
+ }
+
+ void insert(std::string Name,
+ llvm::function_ref<TimeTraceMetadata()> Metadata) {
+ if (Stack.empty())
+ return;
+
+ Stack.back().get()->InstantEvents.emplace_back(TimeTraceProfilerEntry(
ClockType::now(), TimePointType(), std::move(Name), Metadata(),
- AsyncEvent));
- return Stack.back().get();
+ TimeTraceEventType::InstantEvent));
}
void end() {
assert(!Stack.empty() && "Must call begin() first");
- end(*Stack.back());
+ end(*Stack.back()->Event);
}
void end(TimeTraceProfilerEntry &E) {
@@ -145,8 +182,14 @@ struct llvm::TimeTraceProfiler {
DurationType Duration = E.End - E.Start;
// Only include sections longer or equal to TimeTraceGranularity msec.
- if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity)
+ if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity) {
Entries.emplace_back(E);
+ if (Stack.back()->Event.get() == &E) {
+ for (auto &IE : Stack.back()->InstantEvents) {
+ Entries.emplace_back(IE);
+ }
+ }
+ }
// 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
@@ -154,18 +197,17 @@ 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 std::unique_ptr<TimeTraceProfilerEntry> &Val) {
- return Val->Name == E.Name;
+ [&](const std::unique_ptr<InProgressEntry> &Val) {
+ return Val->Event->Name == E.Name;
})) {
auto &CountAndTotal = CountAndTotalPerName[E.Name];
CountAndTotal.first++;
CountAndTotal.second += Duration;
};
- llvm::erase_if(Stack,
- [&](const std::unique_ptr<TimeTraceProfilerEntry> &Val) {
- return Val.get() == &E;
- });
+ llvm::erase_if(Stack, [&](const std::unique_ptr<InProgressEntry> &Val) {
+ return Val->Event.get() == &E;
+ });
}
// Write events from this TimeTraceProfilerInstance and
@@ -194,13 +236,15 @@ struct llvm::TimeTraceProfiler {
J.attribute("pid", Pid);
J.attribute("tid", int64_t(Tid));
J.attribute("ts", StartUs);
- if (E.AsyncEvent) {
+ if (TimeTraceEventType::AsyncEvent == E.EventType) {
J.attribute("cat", E.Name);
J.attribute("ph", "b");
J.attribute("id", 0);
- } else {
+ } else if (E.EventType == TimeTraceEventType::CompleteEvent) {
J.attribute("ph", "X");
J.attribute("dur", DurUs);
+ } else { // instant event
+ J.attribute("ph", "i");
}
J.attribute("name", E.Name);
if (!E.Metadata.isEmpty()) {
@@ -215,7 +259,7 @@ struct llvm::TimeTraceProfiler {
}
});
- if (E.AsyncEvent) {
+ if (TimeTraceEventType::AsyncEvent == E.EventType) {
J.object([&] {
J.attribute("pid", Pid);
J.attribute("tid", int64_t(Tid));
@@ -319,7 +363,7 @@ struct llvm::TimeTraceProfiler {
J.objectEnd();
}
- SmallVector<std::unique_ptr<TimeTraceProfilerEntry>, 16> Stack;
+ SmallVector<std::unique_ptr<InProgressEntry>, 16> Stack;
SmallVector<TimeTraceProfilerEntry, 128> Entries;
StringMap<CountAndDurationType> CountAndTotalPerName;
// System clock time when the session was begun.
@@ -406,7 +450,8 @@ TimeTraceProfilerEntry *llvm::timeTraceProfilerBegin(StringRef Name,
StringRef Detail) {
if (TimeTraceProfilerInstance != nullptr)
return TimeTraceProfilerInstance->begin(
- std::string(Name), [&]() { return std::string(Detail); }, false);
+ std::string(Name), [&]() { return std::string(Detail); },
+ TimeTraceEventType::CompleteEvent);
return nullptr;
}
@@ -414,7 +459,8 @@ TimeTraceProfilerEntry *
llvm::timeTraceProfilerBegin(StringRef Name,
llvm::function_ref<std::string()> Detail) {
if (TimeTraceProfilerInstance != nullptr)
- return TimeTraceProfilerInstance->begin(std::string(Name), Detail, false);
+ return TimeTraceProfilerInstance->begin(std::string(Name), Detail,
+ TimeTraceEventType::CompleteEvent);
return nullptr;
}
@@ -422,7 +468,8 @@ TimeTraceProfilerEntry *
llvm::timeTraceProfilerBegin(StringRef Name,
llvm::function_ref<TimeTraceMetadata()> Metadata) {
if (TimeTraceProfilerInstance != nullptr)
- return TimeTraceProfilerInstance->begin(std::string(Name), Metadata, false);
+ return TimeTraceProfilerInstance->begin(std::string(Name), Metadata,
+ TimeTraceEventType::CompleteEvent);
return nullptr;
}
@@ -430,10 +477,23 @@ TimeTraceProfilerEntry *llvm::timeTraceAsyncProfilerBegin(StringRef Name,
StringRef Detail) {
if (TimeTraceProfilerInstance != nullptr)
return TimeTraceProfilerInstance->begin(
- std::string(Name), [&]() { return std::string(Detail); }, true);
+ std::string(Name), [&]() { return std::string(Detail); },
+ TimeTraceEventType::AsyncEvent);
return nullptr;
}
+void llvm::timeTraceProfilerInsert(StringRef Name, StringRef Detail) {
+ if (TimeTraceProfilerInstance != nullptr)
+ TimeTraceProfilerInstance->insert(std::string(Name),
+ [&]() { return std::string(Detail); });
+}
+
+void llvm::timeTraceProfilerInsert(
+ StringRef Name, llvm::function_ref<TimeTraceMetadata()> Metadata) {
+ if (TimeTraceProfilerInstance != nullptr)
+ TimeTraceProfilerInstance->insert(std::string(Name), Metadata);
+}
+
void llvm::timeTraceProfilerEnd() {
if (TimeTraceProfilerInstance != nullptr)
TimeTraceProfilerInstance->end();
|
Contributor
ilya-biryukov
left a comment
ilya-biryukov
left a comment
There was a problem hiding this comment.
I have left quite a few comments, but they are mostly about the code style.
I think this looks really good overall and almost ready to land.
Could you split the change to Sema into a separate PR so that we have time profiler changes separately?
usx95
approved these changes
Sep 30, 2024
Contributor
usx95
left a comment
usx95
left a comment
There was a problem hiding this comment.
Thanks. Looks great now.
Should be ready to land. Left some nit comments.
ivanaivanovska
force-pushed
the
instantevents
branch
from
a28003b to
4421b19
Compare
usx95
approved these changes
Oct 8, 2024
ivanaivanovska
changed the title
We will use them in a follow-up to mark defered templated instantiation.
ivanaivanovska
force-pushed
the
instantevents
branch
from
4421b19 to
921b4fb
Compare
ilya-biryukov
approved these changes
Oct 8, 2024
Contributor
ilya-biryukov
left a comment
ilya-biryukov
left a comment
There was a problem hiding this comment.
The change LG, thanks!
One small NIT: let's make sure the [TimeProfiler] tag gets added to the commit title when we land it. It's currently only in the commit, but not in the GitHub PR title, so we might loose it when GitHub pushes the commit to main.
I believe @usx95 was about to push it, I'll leave it up to him.
ivanaivanovska
changed the title
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
4 participants
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Added an instant event type and issuing such events each time a template instantiation is deferred.