https://github.com/ivanaivanovska updated https://github.com/llvm/llvm-project/pull/103039
>From 6d3e4470dfe21f8f3832a2d38b4c4327aa7422a3 Mon Sep 17 00:00:00 2001 From: Ivana Ivanovska <iivanov...@google.com> Date: Tue, 13 Aug 2024 10:30:34 +0000 Subject: [PATCH 1/6] Added instant events and marking defered templated instantiation. --- clang/lib/Sema/SemaExpr.cpp | 18 ++++++ .../lib/Sema/SemaTemplateInstantiateDecl.cpp | 17 +++++ clang/unittests/Support/TimeProfilerTest.cpp | 51 ++++++++++++++- llvm/include/llvm/Support/TimeProfiler.h | 19 +++++- llvm/lib/Support/TimeProfiler.cpp | 64 +++++++++++++------ 5 files changed, 145 insertions(+), 24 deletions(-) diff --git a/clang/lib/Sema/SemaExpr.cpp b/clang/lib/Sema/SemaExpr.cpp index 95f53dfefbcc52..9e88fe5a94289d 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,22 @@ 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::TimeTraceScope TimeScope( + "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; + }, + llvm::TimeTraceEventType::InstantEvent); } } } else { diff --git a/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp b/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp index 0e064be2391838..191f46ed00b7cc 100644 --- a/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp +++ b/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp @@ -4983,6 +4983,23 @@ void Sema::InstantiateFunctionDefinition(SourceLocation PointOfInstantiation, Function->setInstantiationIsPending(true); PendingInstantiations.push_back( std::make_pair(Function, PointOfInstantiation)); + + llvm::TimeTraceScope TimeScope( + "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; + }, + llvm::TimeTraceEventType::InstantEvent); + } 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..f4952b18e4f6ef 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,10 @@ timeTraceProfilerBegin(StringRef Name, TimeTraceProfilerEntry *timeTraceAsyncProfilerBegin(StringRef Name, StringRef Detail); +// Mark an instant event. +TimeTraceProfilerEntry *timeTraceInstantEventProfilerBegin(StringRef Name, + llvm::function_ref<TimeTraceMetadata()> Metadata); + /// Manually end the last time section. void timeTraceProfilerEnd(); void timeTraceProfilerEnd(TimeTraceProfilerEntry *E); @@ -181,9 +187,18 @@ class TimeTraceScope { Entry = timeTraceProfilerBegin(Name, Detail); } TimeTraceScope(StringRef Name, - llvm::function_ref<TimeTraceMetadata()> Metadata) { - if (getTimeTraceProfilerInstance() != nullptr) + llvm::function_ref<TimeTraceMetadata()> Metadata, TimeTraceEventType Et = TimeTraceEventType::CompleteEvent) { + if (getTimeTraceProfilerInstance() == nullptr) + return; + assert((Et == TimeTraceEventType::InstantEvent || + Et == TimeTraceEventType::CompleteEvent) && + "Event Type not supported."); + + if (Et == TimeTraceEventType::CompleteEvent) { Entry = timeTraceProfilerBegin(Name, Metadata); + } else { + Entry = timeTraceInstantEventProfilerBegin(Name, Metadata); + } } ~TimeTraceScope() { if (getTimeTraceProfilerInstance() != nullptr) diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp index c2014028ddadca..738f5f5842bb0d 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" @@ -70,23 +71,23 @@ using NameAndCountAndDurationType = /// Represents an open or completed time section entry to be captured. struct llvm::TimeTraceProfilerEntry { - const TimePointType Start; + TimePointType Start; TimePointType End; - const std::string Name; + std::string Name; TimeTraceMetadata Metadata; + TimeTraceEventType EventType; - const bool AsyncEvent = false; 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 @@ -116,19 +117,19 @@ struct llvm::TimeTraceProfiler { TimeTraceProfilerEntry *begin(std::string Name, llvm::function_ref<std::string()> Detail, - bool AsyncEvent = false) { + TimeTraceEventType Et = TimeTraceEventType::CompleteEvent) { Stack.emplace_back(std::make_unique<TimeTraceProfilerEntry>( ClockType::now(), TimePointType(), std::move(Name), Detail(), - AsyncEvent)); + Et)); return Stack.back().get(); } TimeTraceProfilerEntry * begin(std::string Name, llvm::function_ref<TimeTraceMetadata()> Metadata, - bool AsyncEvent = false) { + TimeTraceEventType Et = TimeTraceEventType::CompleteEvent) { Stack.emplace_back(std::make_unique<TimeTraceProfilerEntry>( ClockType::now(), TimePointType(), std::move(Name), Metadata(), - AsyncEvent)); + Et)); return Stack.back().get(); } @@ -144,9 +145,22 @@ struct llvm::TimeTraceProfiler { // Calculate duration at full precision for overall counts. DurationType Duration = E.End - E.Start; - // Only include sections longer or equal to TimeTraceGranularity msec. - if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity) + // Only include Instant Events or events with a duration longer or equal to + // TimeTraceGranularity msec. + if (E.EventType == TimeTraceEventType::InstantEvent || + duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity) { Entries.emplace_back(E); + } else { + // if the event is not included, exclude also all instant events that + // happened during this event. + for (SmallVector<TimeTraceProfilerEntry, 128>::iterator it = Entries.begin(); it != Entries.end();) { + if (TimeTraceEventType::InstantEvent == it->EventType && + it->Start > E.Start && it->Start < E.End) + it = Entries.erase(it); + else + ++it; + } + } // 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 @@ -194,13 +208,15 @@ struct llvm::TimeTraceProfiler { J.attribute("pid", Pid); J.attribute("tid", int64_t(Tid)); J.attribute("ts", StartUs); - if (E.AsyncEvent) { + if (E.EventType == TimeTraceEventType::AsyncEvent) { 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 +231,7 @@ struct llvm::TimeTraceProfiler { } }); - if (E.AsyncEvent) { + if (E.EventType == TimeTraceEventType::AsyncEvent) { J.object([&] { J.attribute("pid", Pid); J.attribute("tid", int64_t(Tid)); @@ -406,7 +422,7 @@ 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 +430,7 @@ 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 +438,15 @@ 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; +} + +TimeTraceProfilerEntry * +llvm::timeTraceInstantEventProfilerBegin(StringRef Name, + llvm::function_ref<TimeTraceMetadata()> Metadata) { + if (TimeTraceProfilerInstance != nullptr) + return TimeTraceProfilerInstance->begin(std::string(Name), Metadata, TimeTraceEventType::InstantEvent); return nullptr; } @@ -430,7 +454,7 @@ 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; } >From 3a8d8ee992bbd22b2ac342042a5c61f2e96687d3 Mon Sep 17 00:00:00 2001 From: Ivana Ivanovska <iivanov...@google.com> Date: Wed, 28 Aug 2024 09:57:49 +0000 Subject: [PATCH 2/6] Refactored TimeTraceProfilerEntry to allow easier extensibility. Implemented inserting Instant Events with a single function. --- clang/lib/Sema/Sema.cpp | 8 +- clang/lib/Sema/SemaExpr.cpp | 27 +- .../lib/Sema/SemaTemplateInstantiateDecl.cpp | 28 +- llvm/include/llvm/Support/TimeProfiler.h | 40 +-- llvm/lib/Support/TimeProfiler.cpp | 324 +++++++++++------- llvm/unittests/Support/TimeProfilerTest.cpp | 2 +- 6 files changed, 255 insertions(+), 174 deletions(-) diff --git a/clang/lib/Sema/Sema.cpp b/clang/lib/Sema/Sema.cpp index 29acd06af603be..d8305861bf21c6 100644 --- a/clang/lib/Sema/Sema.cpp +++ b/clang/lib/Sema/Sema.cpp @@ -160,7 +160,7 @@ namespace sema { class SemaPPCallbacks : public PPCallbacks { Sema *S = nullptr; llvm::SmallVector<SourceLocation, 8> IncludeStack; - llvm::SmallVector<llvm::TimeTraceProfilerEntry *, 8> ProfilerStack; + llvm::SmallVector<std::shared_ptr<llvm::DurableEvent>, 8> ProfilerStack; public: void set(Sema &S) { this->S = &S; } @@ -192,8 +192,10 @@ class SemaPPCallbacks : public PPCallbacks { } case ExitFile: if (!IncludeStack.empty()) { - if (llvm::timeTraceProfilerEnabled()) - llvm::timeTraceProfilerEnd(ProfilerStack.pop_back_val()); + if (llvm::timeTraceProfilerEnabled()) { + auto E = ProfilerStack.pop_back_val(); + llvm::timeTraceProfilerEnd(E); + } S->DiagnoseNonDefaultPragmaAlignPack( Sema::PragmaAlignPackDiagnoseKind::ChangedStateAtExit, diff --git a/clang/lib/Sema/SemaExpr.cpp b/clang/lib/Sema/SemaExpr.cpp index 9e88fe5a94289d..a7dd01c936bac8 100644 --- a/clang/lib/Sema/SemaExpr.cpp +++ b/clang/lib/Sema/SemaExpr.cpp @@ -18049,21 +18049,18 @@ void Sema::MarkFunctionReferenced(SourceLocation Loc, FunctionDecl *Func, // Notify the consumer that a function was implicitly instantiated. Consumer.HandleCXXImplicitFunctionInstantiation(Func); - llvm::TimeTraceScope TimeScope( - "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; - }, - llvm::TimeTraceEventType::InstantEvent); + 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 191f46ed00b7cc..550add5495c833 100644 --- a/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp +++ b/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp @@ -4984,22 +4984,18 @@ void Sema::InstantiateFunctionDefinition(SourceLocation PointOfInstantiation, PendingInstantiations.push_back( std::make_pair(Function, PointOfInstantiation)); - llvm::TimeTraceScope TimeScope( - "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; - }, - llvm::TimeTraceEventType::InstantEvent); - + 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/llvm/include/llvm/Support/TimeProfiler.h b/llvm/include/llvm/Support/TimeProfiler.h index f4952b18e4f6ef..323d7c8c5f8c55 100644 --- a/llvm/include/llvm/Support/TimeProfiler.h +++ b/llvm/include/llvm/Support/TimeProfiler.h @@ -94,13 +94,17 @@ struct TimeTraceMetadata { bool isEmpty() const { return Detail.empty() && File.empty(); } }; +struct TimeTraceProfilerEntry; +struct InstantEvent; +struct DurableEvent; +struct CompleteEvent; +struct AsyncEvent; + struct TimeTraceProfiler; TimeTraceProfiler *getTimeTraceProfilerInstance(); bool isTimeTraceVerbose(); -struct TimeTraceProfilerEntry; - /// Initialize the time trace profiler. /// This sets up the global \p TimeTraceProfilerInstance /// variable to be the profiler instance. @@ -136,13 +140,13 @@ 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. -TimeTraceProfilerEntry *timeTraceProfilerBegin(StringRef Name, - StringRef Detail); -TimeTraceProfilerEntry * +std::shared_ptr<DurableEvent> timeTraceProfilerBegin(StringRef Name, + StringRef Detail); +std::shared_ptr<DurableEvent> timeTraceProfilerBegin(StringRef Name, llvm::function_ref<std::string()> Detail); -TimeTraceProfilerEntry * +std::shared_ptr<DurableEvent> timeTraceProfilerBegin(StringRef Name, llvm::function_ref<TimeTraceMetadata()> MetaData); @@ -151,16 +155,17 @@ timeTraceProfilerBegin(StringRef Name, /// 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); +std::shared_ptr<DurableEvent> timeTraceAsyncProfilerBegin(StringRef Name, + StringRef Detail); // Mark an instant event. -TimeTraceProfilerEntry *timeTraceInstantEventProfilerBegin(StringRef Name, +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); +void timeTraceProfilerEnd(std::shared_ptr<DurableEvent> &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 @@ -187,18 +192,9 @@ class TimeTraceScope { Entry = timeTraceProfilerBegin(Name, Detail); } TimeTraceScope(StringRef Name, - llvm::function_ref<TimeTraceMetadata()> Metadata, TimeTraceEventType Et = TimeTraceEventType::CompleteEvent) { - if (getTimeTraceProfilerInstance() == nullptr) - return; - assert((Et == TimeTraceEventType::InstantEvent || - Et == TimeTraceEventType::CompleteEvent) && - "Event Type not supported."); - - if (Et == TimeTraceEventType::CompleteEvent) { + llvm::function_ref<TimeTraceMetadata()> Metadata) { + if (getTimeTraceProfilerInstance() != nullptr) Entry = timeTraceProfilerBegin(Name, Metadata); - } else { - Entry = timeTraceInstantEventProfilerBegin(Name, Metadata); - } } ~TimeTraceScope() { if (getTimeTraceProfilerInstance() != nullptr) @@ -206,7 +202,7 @@ class TimeTraceScope { } private: - TimeTraceProfilerEntry *Entry = nullptr; + std::shared_ptr<DurableEvent> Entry = nullptr; }; } // end namespace llvm diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp index 738f5f5842bb0d..ac0c1d89bb8176 100644 --- a/llvm/lib/Support/TimeProfiler.cpp +++ b/llvm/lib/Support/TimeProfiler.cpp @@ -69,25 +69,20 @@ using NameAndCountAndDurationType = } // anonymous namespace -/// Represents an open or completed time section entry to be captured. +/// Represents an entry to be captured. struct llvm::TimeTraceProfilerEntry { - TimePointType Start; - TimePointType End; - std::string Name; + const TimePointType Start; + const std::string Name; TimeTraceMetadata Metadata; - TimeTraceEventType EventType; - TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N, - std::string &&Dt, TimeTraceEventType Et) - : Start(std::move(S)), End(std::move(E)), Name(std::move(N)), Metadata(), - EventType(Et) { + TimeTraceProfilerEntry(TimePointType &&S, std::string &&N, std::string &&Dt) + : Start(std::move(S)), Name(std::move(N)), Metadata() { Metadata.Detail = std::move(Dt); } - TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N, - TimeTraceMetadata &&Mt, TimeTraceEventType Et) - : Start(std::move(S)), End(std::move(E)), Name(std::move(N)), - Metadata(std::move(Mt)), EventType(Et) {} + TimeTraceProfilerEntry(TimePointType &&S, std::string &&N, + TimeTraceMetadata &&Mt) + : Start(std::move(S)), Name(std::move(N)), Metadata(std::move(Mt)) {} // Calculate timings for FlameGraph. Cast time points to microsecond precision // rather than casting duration. This avoids truncation issues causing inner @@ -98,11 +93,128 @@ struct llvm::TimeTraceProfilerEntry { .count(); } + virtual void writeEvent(json::OStream &J, sys::Process::Pid Pid, uint64_t Tid, + TimePointType StartTime) const { + J.object([&] { + J.attribute("pid", Pid); + J.attribute("tid", int64_t(Tid)); + J.attribute("ts", getFlameGraphStartUs(StartTime)); + writeAdditionalEventFileds(J); + J.attribute("name", Name); + if (!Metadata.isEmpty()) { + J.attributeObject("args", [&] { + if (!Metadata.Detail.empty()) + J.attribute("detail", Metadata.Detail); + if (!Metadata.File.empty()) + J.attribute("file", Metadata.File); + if (Metadata.Line > 0) + J.attribute("line", Metadata.Line); + }); + } + }); + } + + virtual void writeAdditionalEventFileds(json::OStream &J) const {} + + virtual ~TimeTraceProfilerEntry() = default; +}; + +struct llvm::InstantEvent : llvm::TimeTraceProfilerEntry { + InstantEvent(TimePointType &&S, std::string &&N, std::string &&Dt) + : TimeTraceProfilerEntry(std::move(S), std::move(N), std::move(Dt)) {} + + InstantEvent(TimePointType &&S, std::string &&N, TimeTraceMetadata &&Mt) + : TimeTraceProfilerEntry(std::move(S), std::move(N), std::move(Mt)) {} + + void writeAdditionalEventFileds(json::OStream &J) const override { + J.attribute("ph", "i"); + } +}; + +struct llvm::DurableEvent : llvm::TimeTraceProfilerEntry { + DurableEvent(TimePointType &&S, TimePointType &&E, std::string &&N, + std::string &&Dt) + : TimeTraceProfilerEntry(std::move(S), std::move(N), std::move(Dt)), + InstantEvents{}, End(std::move(E)) {} + + DurableEvent(TimePointType &&S, TimePointType &&E, std::string &&N, + TimeTraceMetadata &&Mt) + : TimeTraceProfilerEntry(std::move(S), std::move(N), std::move(Mt)), + InstantEvents{}, End(std::move(E)) {} + + virtual void writeEvent(json::OStream &J, sys::Process::Pid Pid, uint64_t Tid, + TimePointType StartTime) const override { + TimeTraceProfilerEntry::writeEvent(J, Pid, Tid, StartTime); + writeInstantEvents(J, Pid, Tid, StartTime); + } + + void writeInstantEvents(json::OStream &J, sys::Process::Pid Pid, uint64_t Tid, + TimePointType StartTime) const { + for (auto IE : InstantEvents) { + IE->writeEvent(J, Pid, Tid, StartTime); + } + } + + virtual void writeAdditionalEventFileds(json::OStream &J) const override {} + ClockType::rep getFlameGraphDurUs() const { return (time_point_cast<microseconds>(End) - time_point_cast<microseconds>(Start)) .count(); } + + std::vector<std::shared_ptr<InstantEvent>> InstantEvents; + TimePointType End; +}; + +struct llvm::CompleteEvent : llvm::DurableEvent { + CompleteEvent(TimePointType &&S, TimePointType &&E, std::string &&N, + std::string &&Dt) + : DurableEvent(std::move(S), std::move(E), std::move(N), std::move(Dt)) {} + + CompleteEvent(TimePointType &&S, TimePointType &&E, std::string &&N, + TimeTraceMetadata &&Mt) + : DurableEvent(std::move(S), std::move(E), std::move(N), std::move(Mt)) {} + + virtual void writeAdditionalEventFileds(json::OStream &J) const override { + J.attribute("ph", "X"); + J.attribute("dur", getFlameGraphDurUs()); + } +}; + +struct llvm::AsyncEvent : llvm::DurableEvent { + AsyncEvent(TimePointType &&S, TimePointType &&E, std::string &&N, + std::string &&Dt) + : DurableEvent(std::move(S), std::move(E), std::move(N), std::move(Dt)) {} + + AsyncEvent(TimePointType &&S, TimePointType &&E, std::string &&N, + TimeTraceMetadata &&Mt) + : DurableEvent(std::move(S), std::move(E), std::move(N), std::move(Mt)) {} + + void writeEvent(json::OStream &J, sys::Process::Pid Pid, uint64_t Tid, + TimePointType StartTime) const override { + DurableEvent::writeEvent(J, Pid, Tid, StartTime); + writeEndEvent(J, Pid, Tid, StartTime); + } + + void writeEndEvent(json::OStream &J, sys::Process::Pid Pid, uint64_t Tid, + TimePointType StartTime) const { + J.object([&] { + J.attribute("pid", Pid); + J.attribute("tid", int64_t(Tid)); + J.attribute("ts", getFlameGraphStartUs(StartTime) + getFlameGraphDurUs()); + J.attribute("cat", Name); + J.attribute("ph", "e"); + J.attribute("id", 0); + J.attribute("name", Name); + }); + } + + void writeAdditionalEventFileds(json::OStream &J) const override { + J.attribute("cat", Name); + J.attribute("ph", "b"); + J.attribute("id", 0); + } }; struct llvm::TimeTraceProfiler { @@ -114,52 +226,68 @@ struct llvm::TimeTraceProfiler { TimeTraceVerbose(TimeTraceVerbose) { llvm::get_thread_name(ThreadName); } - - TimeTraceProfilerEntry *begin(std::string Name, - llvm::function_ref<std::string()> Detail, - TimeTraceEventType Et = TimeTraceEventType::CompleteEvent) { - Stack.emplace_back(std::make_unique<TimeTraceProfilerEntry>( - ClockType::now(), TimePointType(), std::move(Name), Detail(), - Et)); - return Stack.back().get(); + std::shared_ptr<DurableEvent> begin(std::string Name, + llvm::function_ref<std::string()> Detail, + bool AsyncEventType) { + if (AsyncEventType) { + Stack.emplace_back(std::make_shared<AsyncEvent>( + ClockType::now(), TimePointType(), std::move(Name), Detail())); + } else { + Stack.emplace_back(std::make_shared<CompleteEvent>( + ClockType::now(), TimePointType(), std::move(Name), Detail())); + } + return Stack.back(); } - TimeTraceProfilerEntry * + std::shared_ptr<DurableEvent> begin(std::string Name, llvm::function_ref<TimeTraceMetadata()> Metadata, - TimeTraceEventType Et = TimeTraceEventType::CompleteEvent) { - Stack.emplace_back(std::make_unique<TimeTraceProfilerEntry>( - ClockType::now(), TimePointType(), std::move(Name), Metadata(), - Et)); - return Stack.back().get(); + bool AsyncEventType) { + + if (AsyncEventType) { + Stack.emplace_back(std::make_shared<AsyncEvent>( + ClockType::now(), TimePointType(), std::move(Name), Metadata())); + } else { + Stack.emplace_back(std::make_shared<CompleteEvent>( + ClockType::now(), TimePointType(), std::move(Name), Metadata())); + } + return Stack.back(); + } + + void insert(std::string Name, llvm::function_ref<std::string()> Detail) { + if (Stack.empty()) + return; + + Stack.back().get()->InstantEvents.emplace_back( + std::make_shared<InstantEvent>(ClockType::now(), std::move(Name), + Detail())); + } + + void insert(std::string Name, + llvm::function_ref<TimeTraceMetadata()> Metadata) { + if (Stack.empty()) + return; + + Stack.back().get()->InstantEvents.emplace_back( + std::make_shared<InstantEvent>(ClockType::now(), std::move(Name), + Metadata())); } void end() { assert(!Stack.empty() && "Must call begin() first"); - end(*Stack.back()); + end(Stack.back()); } - void end(TimeTraceProfilerEntry &E) { + void end(std::shared_ptr<DurableEvent> &E) { assert(!Stack.empty() && "Must call begin() first"); - E.End = ClockType::now(); + E->End = ClockType::now(); // Calculate duration at full precision for overall counts. - DurationType Duration = E.End - E.Start; + DurationType Duration = E->End - E->Start; - // Only include Instant Events or events with a duration longer or equal to + // Only include events with a duration longer or equal to // TimeTraceGranularity msec. - if (E.EventType == TimeTraceEventType::InstantEvent || - duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity) { + if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity) { Entries.emplace_back(E); - } else { - // if the event is not included, exclude also all instant events that - // happened during this event. - for (SmallVector<TimeTraceProfilerEntry, 128>::iterator it = Entries.begin(); it != Entries.end();) { - if (TimeTraceEventType::InstantEvent == it->EventType && - it->Start > E.Start && it->Start < E.End) - it = Entries.erase(it); - else - ++it; - } } // Track total time taken by each "name", but only the topmost levels of @@ -168,18 +296,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::shared_ptr<DurableEvent> &Val) { + return Val->Name == E->Name; })) { - auto &CountAndTotal = CountAndTotalPerName[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::shared_ptr<DurableEvent> &Val) { + return Val.get() == E.get(); + }); } // Write events from this TimeTraceProfilerInstance and @@ -200,54 +327,13 @@ struct llvm::TimeTraceProfiler { J.arrayBegin(); // Emit all events for the main flame graph. - auto writeEvent = [&](const auto &E, uint64_t Tid) { - auto StartUs = E.getFlameGraphStartUs(StartTime); - auto DurUs = E.getFlameGraphDurUs(); - - J.object([&] { - J.attribute("pid", Pid); - J.attribute("tid", int64_t(Tid)); - J.attribute("ts", StartUs); - if (E.EventType == TimeTraceEventType::AsyncEvent) { - J.attribute("cat", E.Name); - J.attribute("ph", "b"); - J.attribute("id", 0); - } 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()) { - J.attributeObject("args", [&] { - if (!E.Metadata.Detail.empty()) - J.attribute("detail", E.Metadata.Detail); - if (!E.Metadata.File.empty()) - J.attribute("file", E.Metadata.File); - if (E.Metadata.Line > 0) - J.attribute("line", E.Metadata.Line); - }); - } - }); - - if (E.EventType == TimeTraceEventType::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); + for (const auto &E : Entries) { + E->writeEvent(J, Pid, this->Tid, StartTime); + } for (const TimeTraceProfiler *TTP : Instances.List) - for (const TimeTraceProfilerEntry &E : TTP->Entries) - writeEvent(E, TTP->Tid); + for (const auto &E : TTP->Entries) { + E->writeEvent(J, Pid, TTP->Tid, StartTime); + } // Emit totals by section name as additional "thread" events, sorted from // longest one. @@ -335,8 +421,8 @@ struct llvm::TimeTraceProfiler { J.objectEnd(); } - SmallVector<std::unique_ptr<TimeTraceProfilerEntry>, 16> Stack; - SmallVector<TimeTraceProfilerEntry, 128> Entries; + SmallVector<std::shared_ptr<DurableEvent>, 16> Stack; + SmallVector<std::shared_ptr<DurableEvent>, 128> Entries; StringMap<CountAndDurationType> CountAndTotalPerName; // System clock time when the session was begun. const time_point<system_clock> BeginningOfTime; @@ -418,43 +504,47 @@ Error llvm::timeTraceProfilerWrite(StringRef PreferredFileName, return Error::success(); } -TimeTraceProfilerEntry *llvm::timeTraceProfilerBegin(StringRef Name, - StringRef Detail) { +std::shared_ptr<DurableEvent> llvm::timeTraceProfilerBegin(StringRef Name, + StringRef Detail) { if (TimeTraceProfilerInstance != nullptr) return TimeTraceProfilerInstance->begin( - std::string(Name), [&]() { return std::string(Detail); }, TimeTraceEventType::CompleteEvent); + std::string(Name), [&]() { return std::string(Detail); }, false); return nullptr; } -TimeTraceProfilerEntry * +std::shared_ptr<DurableEvent> llvm::timeTraceProfilerBegin(StringRef Name, llvm::function_ref<std::string()> Detail) { if (TimeTraceProfilerInstance != nullptr) - return TimeTraceProfilerInstance->begin(std::string(Name), Detail, TimeTraceEventType::CompleteEvent); + return TimeTraceProfilerInstance->begin(std::string(Name), Detail, false); return nullptr; } -TimeTraceProfilerEntry * +std::shared_ptr<DurableEvent> llvm::timeTraceProfilerBegin(StringRef Name, llvm::function_ref<TimeTraceMetadata()> Metadata) { if (TimeTraceProfilerInstance != nullptr) - return TimeTraceProfilerInstance->begin(std::string(Name), Metadata, TimeTraceEventType::CompleteEvent); + return TimeTraceProfilerInstance->begin(std::string(Name), Metadata, false); return nullptr; } -TimeTraceProfilerEntry * -llvm::timeTraceInstantEventProfilerBegin(StringRef Name, - llvm::function_ref<TimeTraceMetadata()> Metadata) { +void llvm::timeTraceProfilerInsert(StringRef Name, StringRef Detail) { if (TimeTraceProfilerInstance != nullptr) - return TimeTraceProfilerInstance->begin(std::string(Name), Metadata, TimeTraceEventType::InstantEvent); - return 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); } -TimeTraceProfilerEntry *llvm::timeTraceAsyncProfilerBegin(StringRef Name, - StringRef Detail) { +std::shared_ptr<DurableEvent> +llvm::timeTraceAsyncProfilerBegin(StringRef Name, StringRef Detail) { if (TimeTraceProfilerInstance != nullptr) return TimeTraceProfilerInstance->begin( - std::string(Name), [&]() { return std::string(Detail); }, TimeTraceEventType::AsyncEvent); + std::string(Name), [&]() { return std::string(Detail); }, true); return nullptr; } @@ -463,7 +553,7 @@ void llvm::timeTraceProfilerEnd() { TimeTraceProfilerInstance->end(); } -void llvm::timeTraceProfilerEnd(TimeTraceProfilerEntry *E) { +void llvm::timeTraceProfilerEnd(std::shared_ptr<DurableEvent> &E) { if (TimeTraceProfilerInstance != nullptr) - TimeTraceProfilerInstance->end(*E); + TimeTraceProfilerInstance->end(E); } diff --git a/llvm/unittests/Support/TimeProfilerTest.cpp b/llvm/unittests/Support/TimeProfilerTest.cpp index bb820ec99a393e..250e0e4f4704b8 100644 --- a/llvm/unittests/Support/TimeProfilerTest.cpp +++ b/llvm/unittests/Support/TimeProfilerTest.cpp @@ -57,7 +57,7 @@ TEST(TimeProfiler, Begin_End_Smoke) { TEST(TimeProfiler, Async_Begin_End_Smoke) { setupProfiler(); - auto *Profiler = timeTraceAsyncProfilerBegin("event", "detail"); + auto Profiler = timeTraceAsyncProfilerBegin("event", "detail"); timeTraceProfilerEnd(Profiler); std::string json = teardownProfiler(); >From ce972c51b98fbfbcf08530db5db17675b79cf8a6 Mon Sep 17 00:00:00 2001 From: Ivana Ivanovska <iivanov...@google.com> Date: Thu, 29 Aug 2024 12:17:01 +0000 Subject: [PATCH 3/6] Reverted refactoring. Implemented review comments. --- clang/lib/Sema/Sema.cpp | 8 +- llvm/include/llvm/Support/TimeProfiler.h | 24 +- llvm/lib/Support/TimeProfiler.cpp | 316 ++++++++------------ llvm/unittests/Support/TimeProfilerTest.cpp | 2 +- 4 files changed, 145 insertions(+), 205 deletions(-) diff --git a/clang/lib/Sema/Sema.cpp b/clang/lib/Sema/Sema.cpp index d8305861bf21c6..29acd06af603be 100644 --- a/clang/lib/Sema/Sema.cpp +++ b/clang/lib/Sema/Sema.cpp @@ -160,7 +160,7 @@ namespace sema { class SemaPPCallbacks : public PPCallbacks { Sema *S = nullptr; llvm::SmallVector<SourceLocation, 8> IncludeStack; - llvm::SmallVector<std::shared_ptr<llvm::DurableEvent>, 8> ProfilerStack; + llvm::SmallVector<llvm::TimeTraceProfilerEntry *, 8> ProfilerStack; public: void set(Sema &S) { this->S = &S; } @@ -192,10 +192,8 @@ class SemaPPCallbacks : public PPCallbacks { } case ExitFile: if (!IncludeStack.empty()) { - if (llvm::timeTraceProfilerEnabled()) { - auto E = ProfilerStack.pop_back_val(); - llvm::timeTraceProfilerEnd(E); - } + 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 323d7c8c5f8c55..9a6bcdefee6c20 100644 --- a/llvm/include/llvm/Support/TimeProfiler.h +++ b/llvm/include/llvm/Support/TimeProfiler.h @@ -94,17 +94,13 @@ struct TimeTraceMetadata { bool isEmpty() const { return Detail.empty() && File.empty(); } }; -struct TimeTraceProfilerEntry; -struct InstantEvent; -struct DurableEvent; -struct CompleteEvent; -struct AsyncEvent; - struct TimeTraceProfiler; TimeTraceProfiler *getTimeTraceProfilerInstance(); bool isTimeTraceVerbose(); +struct TimeTraceProfilerEntry; + /// Initialize the time trace profiler. /// This sets up the global \p TimeTraceProfilerInstance /// variable to be the profiler instance. @@ -140,13 +136,13 @@ 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. -std::shared_ptr<DurableEvent> timeTraceProfilerBegin(StringRef Name, - StringRef Detail); -std::shared_ptr<DurableEvent> +TimeTraceProfilerEntry *timeTraceProfilerBegin(StringRef Name, + StringRef Detail); +TimeTraceProfilerEntry * timeTraceProfilerBegin(StringRef Name, llvm::function_ref<std::string()> Detail); -std::shared_ptr<DurableEvent> +TimeTraceProfilerEntry * timeTraceProfilerBegin(StringRef Name, llvm::function_ref<TimeTraceMetadata()> MetaData); @@ -155,8 +151,8 @@ timeTraceProfilerBegin(StringRef Name, /// separately from other traces. See /// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.jh64i9l3vwa1 /// for more details. -std::shared_ptr<DurableEvent> timeTraceAsyncProfilerBegin(StringRef Name, - StringRef Detail); +TimeTraceProfilerEntry *timeTraceAsyncProfilerBegin(StringRef Name, + StringRef Detail); // Mark an instant event. void timeTraceProfilerInsert(StringRef Name, @@ -165,7 +161,7 @@ void timeTraceProfilerInsert(StringRef Name, StringRef Detail); /// Manually end the last time section. void timeTraceProfilerEnd(); -void timeTraceProfilerEnd(std::shared_ptr<DurableEvent> &E); +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 @@ -202,7 +198,7 @@ class TimeTraceScope { } private: - std::shared_ptr<DurableEvent> Entry = nullptr; + TimeTraceProfilerEntry *Entry = nullptr; }; } // end namespace llvm diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp index ac0c1d89bb8176..31faa36c29f14d 100644 --- a/llvm/lib/Support/TimeProfiler.cpp +++ b/llvm/lib/Support/TimeProfiler.cpp @@ -69,20 +69,25 @@ using NameAndCountAndDurationType = } // anonymous namespace -/// Represents an entry to be captured. +/// Represents an open or completed time section entry to be captured. struct llvm::TimeTraceProfilerEntry { const TimePointType Start; + TimePointType End; const std::string Name; TimeTraceMetadata Metadata; - TimeTraceProfilerEntry(TimePointType &&S, std::string &&N, std::string &&Dt) - : Start(std::move(S)), Name(std::move(N)), Metadata() { + TimeTraceEventType EventType; + TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N, + std::string &&Dt, TimeTraceEventType Et) + : Start(std::move(S)), End(std::move(E)), Name(std::move(N)), Metadata(), + EventType(Et) { Metadata.Detail = std::move(Dt); } - TimeTraceProfilerEntry(TimePointType &&S, std::string &&N, - TimeTraceMetadata &&Mt) - : Start(std::move(S)), Name(std::move(N)), Metadata(std::move(Mt)) {} + TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N, + TimeTraceMetadata &&Mt, TimeTraceEventType Et) + : Start(std::move(S)), End(std::move(E)), Name(std::move(N)), + 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 @@ -93,128 +98,28 @@ struct llvm::TimeTraceProfilerEntry { .count(); } - virtual void writeEvent(json::OStream &J, sys::Process::Pid Pid, uint64_t Tid, - TimePointType StartTime) const { - J.object([&] { - J.attribute("pid", Pid); - J.attribute("tid", int64_t(Tid)); - J.attribute("ts", getFlameGraphStartUs(StartTime)); - writeAdditionalEventFileds(J); - J.attribute("name", Name); - if (!Metadata.isEmpty()) { - J.attributeObject("args", [&] { - if (!Metadata.Detail.empty()) - J.attribute("detail", Metadata.Detail); - if (!Metadata.File.empty()) - J.attribute("file", Metadata.File); - if (Metadata.Line > 0) - J.attribute("line", Metadata.Line); - }); - } - }); - } - - virtual void writeAdditionalEventFileds(json::OStream &J) const {} - - virtual ~TimeTraceProfilerEntry() = default; -}; - -struct llvm::InstantEvent : llvm::TimeTraceProfilerEntry { - InstantEvent(TimePointType &&S, std::string &&N, std::string &&Dt) - : TimeTraceProfilerEntry(std::move(S), std::move(N), std::move(Dt)) {} - - InstantEvent(TimePointType &&S, std::string &&N, TimeTraceMetadata &&Mt) - : TimeTraceProfilerEntry(std::move(S), std::move(N), std::move(Mt)) {} - - void writeAdditionalEventFileds(json::OStream &J) const override { - J.attribute("ph", "i"); - } -}; - -struct llvm::DurableEvent : llvm::TimeTraceProfilerEntry { - DurableEvent(TimePointType &&S, TimePointType &&E, std::string &&N, - std::string &&Dt) - : TimeTraceProfilerEntry(std::move(S), std::move(N), std::move(Dt)), - InstantEvents{}, End(std::move(E)) {} - - DurableEvent(TimePointType &&S, TimePointType &&E, std::string &&N, - TimeTraceMetadata &&Mt) - : TimeTraceProfilerEntry(std::move(S), std::move(N), std::move(Mt)), - InstantEvents{}, End(std::move(E)) {} - - virtual void writeEvent(json::OStream &J, sys::Process::Pid Pid, uint64_t Tid, - TimePointType StartTime) const override { - TimeTraceProfilerEntry::writeEvent(J, Pid, Tid, StartTime); - writeInstantEvents(J, Pid, Tid, StartTime); - } - - void writeInstantEvents(json::OStream &J, sys::Process::Pid Pid, uint64_t Tid, - TimePointType StartTime) const { - for (auto IE : InstantEvents) { - IE->writeEvent(J, Pid, Tid, StartTime); - } - } - - virtual void writeAdditionalEventFileds(json::OStream &J) const override {} - ClockType::rep getFlameGraphDurUs() const { return (time_point_cast<microseconds>(End) - time_point_cast<microseconds>(Start)) .count(); } - - std::vector<std::shared_ptr<InstantEvent>> InstantEvents; - TimePointType End; }; -struct llvm::CompleteEvent : llvm::DurableEvent { - CompleteEvent(TimePointType &&S, TimePointType &&E, std::string &&N, - std::string &&Dt) - : DurableEvent(std::move(S), std::move(E), std::move(N), std::move(Dt)) {} - - CompleteEvent(TimePointType &&S, TimePointType &&E, std::string &&N, - TimeTraceMetadata &&Mt) - : DurableEvent(std::move(S), std::move(E), std::move(N), std::move(Mt)) {} - - virtual void writeAdditionalEventFileds(json::OStream &J) const override { - J.attribute("ph", "X"); - J.attribute("dur", getFlameGraphDurUs()); - } -}; - -struct llvm::AsyncEvent : llvm::DurableEvent { - AsyncEvent(TimePointType &&S, TimePointType &&E, std::string &&N, - std::string &&Dt) - : DurableEvent(std::move(S), std::move(E), std::move(N), std::move(Dt)) {} - - AsyncEvent(TimePointType &&S, TimePointType &&E, std::string &&N, - TimeTraceMetadata &&Mt) - : DurableEvent(std::move(S), std::move(E), std::move(N), std::move(Mt)) {} - - void writeEvent(json::OStream &J, sys::Process::Pid Pid, uint64_t Tid, - TimePointType StartTime) const override { - DurableEvent::writeEvent(J, Pid, Tid, StartTime); - writeEndEvent(J, Pid, Tid, StartTime); - } - - void writeEndEvent(json::OStream &J, sys::Process::Pid Pid, uint64_t Tid, - TimePointType StartTime) const { - J.object([&] { - J.attribute("pid", Pid); - J.attribute("tid", int64_t(Tid)); - J.attribute("ts", getFlameGraphStartUs(StartTime) + getFlameGraphDurUs()); - J.attribute("cat", Name); - J.attribute("ph", "e"); - J.attribute("id", 0); - J.attribute("name", Name); - }); - } - - void writeAdditionalEventFileds(json::OStream &J) const override { - J.attribute("cat", Name); - J.attribute("ph", "b"); - J.attribute("id", 0); - } +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 { @@ -226,40 +131,32 @@ struct llvm::TimeTraceProfiler { TimeTraceVerbose(TimeTraceVerbose) { llvm::get_thread_name(ThreadName); } - std::shared_ptr<DurableEvent> begin(std::string Name, - llvm::function_ref<std::string()> Detail, - bool AsyncEventType) { - if (AsyncEventType) { - Stack.emplace_back(std::make_shared<AsyncEvent>( - ClockType::now(), TimePointType(), std::move(Name), Detail())); - } else { - Stack.emplace_back(std::make_shared<CompleteEvent>( - ClockType::now(), TimePointType(), std::move(Name), Detail())); - } - return Stack.back(); + + 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(), + EventType)); + return Stack.back()->Event.get(); } - std::shared_ptr<DurableEvent> + TimeTraceProfilerEntry * begin(std::string Name, llvm::function_ref<TimeTraceMetadata()> Metadata, - bool AsyncEventType) { - - if (AsyncEventType) { - Stack.emplace_back(std::make_shared<AsyncEvent>( - ClockType::now(), TimePointType(), std::move(Name), Metadata())); - } else { - Stack.emplace_back(std::make_shared<CompleteEvent>( - ClockType::now(), TimePointType(), std::move(Name), Metadata())); - } - return Stack.back(); + 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( - std::make_shared<InstantEvent>(ClockType::now(), std::move(Name), - Detail())); + Stack.back().get()->InstantEvents.emplace_back(TimeTraceProfilerEntry( + ClockType::now(), TimePointType(), std::move(Name), Detail(), + TimeTraceEventType::InstantEvent)); } void insert(std::string Name, @@ -267,27 +164,31 @@ struct llvm::TimeTraceProfiler { if (Stack.empty()) return; - Stack.back().get()->InstantEvents.emplace_back( - std::make_shared<InstantEvent>(ClockType::now(), std::move(Name), - Metadata())); + Stack.back().get()->InstantEvents.emplace_back(TimeTraceProfilerEntry( + ClockType::now(), TimePointType(), std::move(Name), Metadata(), + TimeTraceEventType::InstantEvent)); } void end() { assert(!Stack.empty() && "Must call begin() first"); - end(Stack.back()); + end(*Stack.back()->Event); } - void end(std::shared_ptr<DurableEvent> &E) { + void end(TimeTraceProfilerEntry &E) { assert(!Stack.empty() && "Must call begin() first"); - E->End = ClockType::now(); + E.End = ClockType::now(); // Calculate duration at full precision for overall counts. - DurationType Duration = E->End - E->Start; + DurationType Duration = E.End - E.Start; - // Only include events with a duration longer or equal to - // TimeTraceGranularity msec. + // Only include sections longer or equal to TimeTraceGranularity msec. 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 @@ -296,16 +197,16 @@ 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::shared_ptr<DurableEvent> &Val) { - return Val->Name == E->Name; + [&](const std::unique_ptr<InProgressEntry> &Val) { + return Val->Event->Name == E.Name; })) { - auto &CountAndTotal = CountAndTotalPerName[E->Name]; + auto &CountAndTotal = CountAndTotalPerName[E.Name]; CountAndTotal.first++; CountAndTotal.second += Duration; }; - llvm::erase_if(Stack, [&](const std::shared_ptr<DurableEvent> &Val) { - return Val.get() == E.get(); + llvm::erase_if(Stack, [&](const std::unique_ptr<InProgressEntry> &Val) { + return Val->Event.get() == &E; }); } @@ -327,13 +228,54 @@ struct llvm::TimeTraceProfiler { J.arrayBegin(); // Emit all events for the main flame graph. - for (const auto &E : Entries) { - E->writeEvent(J, Pid, this->Tid, StartTime); - } - for (const TimeTraceProfiler *TTP : Instances.List) - for (const auto &E : TTP->Entries) { - E->writeEvent(J, Pid, TTP->Tid, StartTime); + auto writeEvent = [&](const auto &E, uint64_t Tid) { + auto StartUs = E.getFlameGraphStartUs(StartTime); + auto DurUs = E.getFlameGraphDurUs(); + + J.object([&] { + J.attribute("pid", Pid); + J.attribute("tid", int64_t(Tid)); + J.attribute("ts", StartUs); + if (TimeTraceEventType::AsyncEvent == E.EventType) { + J.attribute("cat", E.Name); + J.attribute("ph", "b"); + J.attribute("id", 0); + } 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()) { + J.attributeObject("args", [&] { + if (!E.Metadata.Detail.empty()) + J.attribute("detail", E.Metadata.Detail); + if (!E.Metadata.File.empty()) + J.attribute("file", E.Metadata.File); + if (E.Metadata.Line > 0) + J.attribute("line", E.Metadata.Line); + }); + } + }); + + if (TimeTraceEventType::AsyncEvent == E.EventType) { + 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); + for (const TimeTraceProfiler *TTP : Instances.List) + for (const TimeTraceProfilerEntry &E : TTP->Entries) + writeEvent(E, TTP->Tid); // Emit totals by section name as additional "thread" events, sorted from // longest one. @@ -421,8 +363,8 @@ struct llvm::TimeTraceProfiler { J.objectEnd(); } - SmallVector<std::shared_ptr<DurableEvent>, 16> Stack; - SmallVector<std::shared_ptr<DurableEvent>, 128> Entries; + SmallVector<std::unique_ptr<InProgressEntry>, 16> Stack; + SmallVector<TimeTraceProfilerEntry, 128> Entries; StringMap<CountAndDurationType> CountAndTotalPerName; // System clock time when the session was begun. const time_point<system_clock> BeginningOfTime; @@ -504,27 +446,39 @@ Error llvm::timeTraceProfilerWrite(StringRef PreferredFileName, return Error::success(); } -std::shared_ptr<DurableEvent> 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); + std::string(Name), [&]() { return std::string(Detail); }, + TimeTraceEventType::CompleteEvent); return nullptr; } -std::shared_ptr<DurableEvent> +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; } -std::shared_ptr<DurableEvent> +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; +} + +TimeTraceProfilerEntry *llvm::timeTraceAsyncProfilerBegin(StringRef Name, + StringRef Detail) { + if (TimeTraceProfilerInstance != nullptr) + return TimeTraceProfilerInstance->begin( + std::string(Name), [&]() { return std::string(Detail); }, + TimeTraceEventType::AsyncEvent); return nullptr; } @@ -540,20 +494,12 @@ void llvm::timeTraceProfilerInsert( TimeTraceProfilerInstance->insert(std::string(Name), Metadata); } -std::shared_ptr<DurableEvent> -llvm::timeTraceAsyncProfilerBegin(StringRef Name, StringRef Detail) { - if (TimeTraceProfilerInstance != nullptr) - return TimeTraceProfilerInstance->begin( - std::string(Name), [&]() { return std::string(Detail); }, true); - return nullptr; -} - void llvm::timeTraceProfilerEnd() { if (TimeTraceProfilerInstance != nullptr) TimeTraceProfilerInstance->end(); } -void llvm::timeTraceProfilerEnd(std::shared_ptr<DurableEvent> &E) { +void llvm::timeTraceProfilerEnd(TimeTraceProfilerEntry *E) { if (TimeTraceProfilerInstance != nullptr) - TimeTraceProfilerInstance->end(E); + TimeTraceProfilerInstance->end(*E); } diff --git a/llvm/unittests/Support/TimeProfilerTest.cpp b/llvm/unittests/Support/TimeProfilerTest.cpp index 250e0e4f4704b8..bb820ec99a393e 100644 --- a/llvm/unittests/Support/TimeProfilerTest.cpp +++ b/llvm/unittests/Support/TimeProfilerTest.cpp @@ -57,7 +57,7 @@ TEST(TimeProfiler, Begin_End_Smoke) { TEST(TimeProfiler, Async_Begin_End_Smoke) { setupProfiler(); - auto Profiler = timeTraceAsyncProfilerBegin("event", "detail"); + auto *Profiler = timeTraceAsyncProfilerBegin("event", "detail"); timeTraceProfilerEnd(Profiler); std::string json = teardownProfiler(); >From 475f1c2e4de3c42387df6b09d7d498ef97210dbf Mon Sep 17 00:00:00 2001 From: Ivana Ivanovska <iivanov...@google.com> Date: Fri, 30 Aug 2024 12:38:09 +0000 Subject: [PATCH 4/6] Applied review comments. --- clang/lib/Sema/SemaExpr.cpp | 21 +++--- .../lib/Sema/SemaTemplateInstantiateDecl.cpp | 21 +++--- clang/unittests/Support/TimeProfilerTest.cpp | 8 +-- llvm/include/llvm/Support/TimeProfiler.h | 18 ++++-- llvm/lib/Support/TimeProfiler.cpp | 64 +++++++++---------- 5 files changed, 65 insertions(+), 67 deletions(-) diff --git a/clang/lib/Sema/SemaExpr.cpp b/clang/lib/Sema/SemaExpr.cpp index a7dd01c936bac8..d6ec07954e88a5 100644 --- a/clang/lib/Sema/SemaExpr.cpp +++ b/clang/lib/Sema/SemaExpr.cpp @@ -18049,18 +18049,15 @@ void Sema::MarkFunctionReferenced(SourceLocation Loc, FunctionDecl *Func, // 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; - }); + if (llvm::isTimeTraceVerbose()) { + llvm::timeTraceInstantEvent("DeferInstantiation", [&] { + std::string Name; + llvm::raw_string_ostream OS(Name); + Func->getNameForDiagnostic(OS, getPrintingPolicy(), + /*Qualified=*/true); + return Name; + }); + } } } } else { diff --git a/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp b/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp index 550add5495c833..946cac74d83754 100644 --- a/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp +++ b/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp @@ -4984,18 +4984,15 @@ void Sema::InstantiateFunctionDefinition(SourceLocation PointOfInstantiation, 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; - }); + if (llvm::isTimeTraceVerbose()) { + llvm::timeTraceInstantEvent("DeferInstantiation", [&] { + std::string Name; + llvm::raw_string_ostream OS(Name); + Function->getNameForDiagnostic(OS, getPrintingPolicy(), + /*Qualified=*/true); + return Name; + }); + } } 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 ccda12e943dd73..339b470153e64e 100644 --- a/clang/unittests/Support/TimeProfilerTest.cpp +++ b/clang/unittests/Support/TimeProfilerTest.cpp @@ -268,7 +268,7 @@ Frontend (test.cc) | | ParseFunctionDefinition (user) | | | InstantiateClass (S<int>, test.cc:3) | | | InstantiateClass (S<float>, test.cc:3) -| | | DeferInstantiation (S<float>::foo, test.cc:5) +| | | DeferInstantiation (S<float>::foo) | PerformPendingInstantiations | | InstantiateFunction (S<float>::foo, test.cc:5) )", @@ -315,12 +315,12 @@ Frontend (test.cc) | ParseFunctionDefinition (fooA) | ParseDeclarationOrFunctionDefinition (test.cc:3:5) | | ParseFunctionDefinition (user) -| | | DeferInstantiation (fooA<int>, a.h:7) +| | | DeferInstantiation (fooA<int>) | PerformPendingInstantiations | | InstantiateFunction (fooA<int>, a.h:7) | | | InstantiateFunction (fooB<int>, b.h:8) -| | | | DeferInstantiation (fooC<int>, b.h:3) -| | | DeferInstantiation (fooMTA<int>, a.h:4) +| | | | DeferInstantiation (fooC<int>) +| | | DeferInstantiation (fooMTA<int>) | | | InstantiateFunction (fooC<int>, b.h:3) | | | InstantiateFunction (fooMTA<int>, a.h:4) )", diff --git a/llvm/include/llvm/Support/TimeProfiler.h b/llvm/include/llvm/Support/TimeProfiler.h index 9a6bcdefee6c20..67d792a8ec6574 100644 --- a/llvm/include/llvm/Support/TimeProfiler.h +++ b/llvm/include/llvm/Support/TimeProfiler.h @@ -83,7 +83,18 @@ namespace llvm { class raw_pwrite_stream; -enum class TimeTraceEventType { CompleteEvent, InstantEvent, AsyncEvent }; +// Type of the time trace event. +enum class TimeTraceEventType { + // Complete events have a duration (start and end time points) and are marked + // by the "X" phase type. + CompleteEvent, + // Instant events don't have a duration, they happen at an instant in time. + // They are marked with "i" phase type. The field End is ignored for them. + InstantEvent, + // Async events mark asynchronous operations and are specified by the "b" + // (start) and "e" (end) phase types. + AsyncEvent +}; struct TimeTraceMetadata { std::string Detail; @@ -155,9 +166,8 @@ 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); +void timeTraceInstantEvent(StringRef Name, + llvm::function_ref<std::string()> Detail); /// Manually end the last time section. void timeTraceProfilerEnd(); diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp index 31faa36c29f14d..29afc80be5cbdd 100644 --- a/llvm/lib/Support/TimeProfiler.cpp +++ b/llvm/lib/Support/TimeProfiler.cpp @@ -76,7 +76,7 @@ struct llvm::TimeTraceProfilerEntry { const std::string Name; TimeTraceMetadata Metadata; - TimeTraceEventType EventType; + const TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent; TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N, std::string &&Dt, TimeTraceEventType Et) : Start(std::move(S)), End(std::move(E)), Name(std::move(N)), Metadata(), @@ -105,20 +105,22 @@ struct llvm::TimeTraceProfilerEntry { } }; +// Represents a currently open (in-progress) time trace entry. InstantEvents +// that happen during an open event are associated with the duration of this +// parent event and they are dropped if parent duration is shorter than +// the granularity. struct InProgressEntry { - std::unique_ptr<TimeTraceProfilerEntry> Event; + 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)), + InProgressEntry(TimePointType S, TimePointType E, std::string N, + std::string Dt, TimeTraceEventType Et) + : Event(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)), + InProgressEntry(TimePointType S, TimePointType E, std::string N, + TimeTraceMetadata Mt, TimeTraceEventType Et) + : Event(std::move(S), std::move(E), std::move(N), std::move(Mt), Et), InstantEvents() {} }; @@ -135,19 +137,25 @@ struct llvm::TimeTraceProfiler { TimeTraceProfilerEntry * begin(std::string Name, llvm::function_ref<std::string()> Detail, TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent) { + assert(EventType != TimeTraceEventType::InstantEvent && + "Instant Events don't have begin and end, they can only be " + "instantiated once"); Stack.emplace_back(std::make_unique<InProgressEntry>( ClockType::now(), TimePointType(), std::move(Name), Detail(), EventType)); - return Stack.back()->Event.get(); + return &Stack.back()->Event; } TimeTraceProfilerEntry * begin(std::string Name, llvm::function_ref<TimeTraceMetadata()> Metadata, TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent) { + assert(EventType != TimeTraceEventType::InstantEvent && + "Instant Events don't have begin and end, they can only be " + "instantiated once."); Stack.emplace_back(std::make_unique<InProgressEntry>( ClockType::now(), TimePointType(), std::move(Name), Metadata(), EventType)); - return Stack.back()->Event.get(); + return &Stack.back()->Event; } void insert(std::string Name, llvm::function_ref<std::string()> Detail) { @@ -159,19 +167,9 @@ struct llvm::TimeTraceProfiler { 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(), - TimeTraceEventType::InstantEvent)); - } - void end() { assert(!Stack.empty() && "Must call begin() first"); - end(*Stack.back()->Event); + end(Stack.back()->Event); } void end(TimeTraceProfilerEntry &E) { @@ -184,7 +182,7 @@ struct llvm::TimeTraceProfiler { // Only include sections longer or equal to TimeTraceGranularity msec. if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity) { Entries.emplace_back(E); - if (Stack.back()->Event.get() == &E) { + if (&Stack.back()->Event == &E) { for (auto &IE : Stack.back()->InstantEvents) { Entries.emplace_back(IE); } @@ -198,7 +196,7 @@ struct llvm::TimeTraceProfiler { // itself. if (llvm::none_of(llvm::drop_begin(llvm::reverse(Stack)), [&](const std::unique_ptr<InProgressEntry> &Val) { - return Val->Event->Name == E.Name; + return Val->Event.Name == E.Name; })) { auto &CountAndTotal = CountAndTotalPerName[E.Name]; CountAndTotal.first++; @@ -206,7 +204,7 @@ struct llvm::TimeTraceProfiler { }; llvm::erase_if(Stack, [&](const std::unique_ptr<InProgressEntry> &Val) { - return Val->Event.get() == &E; + return &Val->Event == &E; }); } @@ -244,6 +242,8 @@ struct llvm::TimeTraceProfiler { J.attribute("ph", "X"); J.attribute("dur", DurUs); } else { // instant event + assert(E.EventType == TimeTraceEventType::InstantEvent && + "InstantEvent expected"); J.attribute("ph", "i"); } J.attribute("name", E.Name); @@ -482,16 +482,10 @@ TimeTraceProfilerEntry *llvm::timeTraceAsyncProfilerBegin(StringRef Name, 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) { +void llvm::timeTraceInstantEvent(StringRef Name, + llvm::function_ref<std::string()> Detail) { if (TimeTraceProfilerInstance != nullptr) - TimeTraceProfilerInstance->insert(std::string(Name), Metadata); + TimeTraceProfilerInstance->insert(std::string(Name), Detail); } void llvm::timeTraceProfilerEnd() { >From 9291d17268c6d59aa7f64e3782b3e8bf86760edc Mon Sep 17 00:00:00 2001 From: Ivana Ivanovska <iivanov...@google.com> Date: Mon, 7 Oct 2024 09:06:34 +0000 Subject: [PATCH 5/6] Applied review comments, changed looking for the specific event in the Stack. --- llvm/lib/Support/TimeProfiler.cpp | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp index 29afc80be5cbdd..ded591b1fdb93a 100644 --- a/llvm/lib/Support/TimeProfiler.cpp +++ b/llvm/lib/Support/TimeProfiler.cpp @@ -138,8 +138,7 @@ struct llvm::TimeTraceProfiler { begin(std::string Name, llvm::function_ref<std::string()> Detail, TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent) { assert(EventType != TimeTraceEventType::InstantEvent && - "Instant Events don't have begin and end, they can only be " - "instantiated once"); + "Instant Events don't have begin and end."); Stack.emplace_back(std::make_unique<InProgressEntry>( ClockType::now(), TimePointType(), std::move(Name), Detail(), EventType)); @@ -150,8 +149,7 @@ struct llvm::TimeTraceProfiler { begin(std::string Name, llvm::function_ref<TimeTraceMetadata()> Metadata, TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent) { assert(EventType != TimeTraceEventType::InstantEvent && - "Instant Events don't have begin and end, they can only be " - "instantiated once."); + "Instant Events don't have begin and end."); Stack.emplace_back(std::make_unique<InProgressEntry>( ClockType::now(), TimePointType(), std::move(Name), Metadata(), EventType)); @@ -179,13 +177,17 @@ struct llvm::TimeTraceProfiler { // Calculate duration at full precision for overall counts. DurationType Duration = E.End - E.Start; + const auto *Iter = + llvm::find_if(Stack, [&](const std::unique_ptr<InProgressEntry> &Val) { + return &Val->Event == &E; + }); + assert(Iter != Stack.end() && "Event not in the Stack"); + // Only include sections longer or equal to TimeTraceGranularity msec. if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity) { Entries.emplace_back(E); - if (&Stack.back()->Event == &E) { - for (auto &IE : Stack.back()->InstantEvents) { - Entries.emplace_back(IE); - } + for (auto &IE : Iter->get()->InstantEvents) { + Entries.emplace_back(IE); } } @@ -203,9 +205,7 @@ struct llvm::TimeTraceProfiler { CountAndTotal.second += Duration; }; - llvm::erase_if(Stack, [&](const std::unique_ptr<InProgressEntry> &Val) { - return &Val->Event == &E; - }); + Stack.erase(Iter); } // Write events from this TimeTraceProfilerInstance and @@ -234,7 +234,7 @@ struct llvm::TimeTraceProfiler { J.attribute("pid", Pid); J.attribute("tid", int64_t(Tid)); J.attribute("ts", StartUs); - if (TimeTraceEventType::AsyncEvent == E.EventType) { + if (E.EventType == TimeTraceEventType::AsyncEvent) { J.attribute("cat", E.Name); J.attribute("ph", "b"); J.attribute("id", 0); >From a28003b0de9f185cd8cc9428b3037635b6d40405 Mon Sep 17 00:00:00 2001 From: Ivana Ivanovska <iivanov...@google.com> Date: Mon, 7 Oct 2024 12:29:52 +0000 Subject: [PATCH 6/6] Renamed `timeTraceInstantEvent` into `timeTraceAddInstantEvent` --- clang/lib/Sema/SemaExpr.cpp | 2 +- clang/lib/Sema/SemaTemplateInstantiateDecl.cpp | 2 +- llvm/include/llvm/Support/TimeProfiler.h | 4 ++-- llvm/lib/Support/TimeProfiler.cpp | 4 ++-- 4 files changed, 6 insertions(+), 6 deletions(-) diff --git a/clang/lib/Sema/SemaExpr.cpp b/clang/lib/Sema/SemaExpr.cpp index d6ec07954e88a5..6589bf7ebf37e2 100644 --- a/clang/lib/Sema/SemaExpr.cpp +++ b/clang/lib/Sema/SemaExpr.cpp @@ -18050,7 +18050,7 @@ void Sema::MarkFunctionReferenced(SourceLocation Loc, FunctionDecl *Func, Consumer.HandleCXXImplicitFunctionInstantiation(Func); if (llvm::isTimeTraceVerbose()) { - llvm::timeTraceInstantEvent("DeferInstantiation", [&] { + llvm::timeTraceAddInstantEvent("DeferInstantiation", [&] { std::string Name; llvm::raw_string_ostream OS(Name); Func->getNameForDiagnostic(OS, getPrintingPolicy(), diff --git a/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp b/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp index 946cac74d83754..846a86dd53ca5c 100644 --- a/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp +++ b/clang/lib/Sema/SemaTemplateInstantiateDecl.cpp @@ -4985,7 +4985,7 @@ void Sema::InstantiateFunctionDefinition(SourceLocation PointOfInstantiation, std::make_pair(Function, PointOfInstantiation)); if (llvm::isTimeTraceVerbose()) { - llvm::timeTraceInstantEvent("DeferInstantiation", [&] { + llvm::timeTraceAddInstantEvent("DeferInstantiation", [&] { std::string Name; llvm::raw_string_ostream OS(Name); Function->getNameForDiagnostic(OS, getPrintingPolicy(), diff --git a/llvm/include/llvm/Support/TimeProfiler.h b/llvm/include/llvm/Support/TimeProfiler.h index 67d792a8ec6574..8c0ecf9b7c911f 100644 --- a/llvm/include/llvm/Support/TimeProfiler.h +++ b/llvm/include/llvm/Support/TimeProfiler.h @@ -166,8 +166,8 @@ TimeTraceProfilerEntry *timeTraceAsyncProfilerBegin(StringRef Name, StringRef Detail); // Mark an instant event. -void timeTraceInstantEvent(StringRef Name, - llvm::function_ref<std::string()> Detail); +void timeTraceAddInstantEvent(StringRef Name, + llvm::function_ref<std::string()> Detail); /// Manually end the last time section. void timeTraceProfilerEnd(); diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp index ded591b1fdb93a..70483eb51396fb 100644 --- a/llvm/lib/Support/TimeProfiler.cpp +++ b/llvm/lib/Support/TimeProfiler.cpp @@ -482,8 +482,8 @@ TimeTraceProfilerEntry *llvm::timeTraceAsyncProfilerBegin(StringRef Name, return nullptr; } -void llvm::timeTraceInstantEvent(StringRef Name, - llvm::function_ref<std::string()> Detail) { +void llvm::timeTraceAddInstantEvent(StringRef Name, + llvm::function_ref<std::string()> Detail) { if (TimeTraceProfilerInstance != nullptr) TimeTraceProfilerInstance->insert(std::string(Name), Detail); } _______________________________________________ cfe-commits mailing list cfe-commits@lists.llvm.org https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits