llvmbot wrote:
<!--LLVM PR SUMMARY COMMENT--> @llvm/pr-subscribers-llvm-support Author: Takuto Ikuta (atetubou) <details> <summary>Changes</summary> This fixes incorrect trace for https://github.com/llvm/llvm-project/issues/56554. This shows trace like https://ui.perfetto.dev/#!/?s=aa809778dc50f2b155b062317fa18bbe2bb2fb9175e6282add8121c7c178214e for the case shown in https://github.com/llvm/llvm-project/issues/83236. https://github.com/llvm/llvm-project/pull/83778 is preparing PR. Fix #<!-- -->56554 --- Full diff: https://github.com/llvm/llvm-project/pull/83961.diff 4 Files Affected: - (modified) clang/lib/Sema/Sema.cpp (+6-4) - (modified) llvm/include/llvm/Support/TimeProfiler.h (+25-9) - (modified) llvm/lib/Support/TimeProfiler.cpp (+71-30) - (modified) llvm/unittests/Support/TimeProfilerTest.cpp (+11) ``````````diff diff --git a/clang/lib/Sema/Sema.cpp b/clang/lib/Sema/Sema.cpp index cfb653e665ea03..2fb12e327c304d 100644 --- a/clang/lib/Sema/Sema.cpp +++ b/clang/lib/Sema/Sema.cpp @@ -135,6 +135,7 @@ namespace sema { class SemaPPCallbacks : public PPCallbacks { Sema *S = nullptr; llvm::SmallVector<SourceLocation, 8> IncludeStack; + llvm::SmallVector<llvm::TimeTraceProfilerEntry *, 8> ProfilerStack; public: void set(Sema &S) { this->S = &S; } @@ -153,8 +154,8 @@ class SemaPPCallbacks : public PPCallbacks { if (IncludeLoc.isValid()) { if (llvm::timeTraceProfilerEnabled()) { OptionalFileEntryRef FE = SM.getFileEntryRefForID(SM.getFileID(Loc)); - llvm::timeTraceProfilerBegin("Source", FE ? FE->getName() - : StringRef("<unknown>")); + ProfilerStack.push_back(llvm::timeTraceAsyncProfilerBegin( + "Source", FE ? FE->getName() : StringRef("<unknown>"))); } IncludeStack.push_back(IncludeLoc); @@ -166,8 +167,9 @@ class SemaPPCallbacks : public PPCallbacks { } case ExitFile: if (!IncludeStack.empty()) { - if (llvm::timeTraceProfilerEnabled()) - llvm::timeTraceProfilerEnd(); + if (llvm::timeTraceProfilerEnabled()) { + llvm::timeTraceProfilerEnd(ProfilerStack.pop_back_val()); + } S->DiagnoseNonDefaultPragmaAlignPack( Sema::PragmaAlignPackDiagnoseKind::ChangedStateAtExit, diff --git a/llvm/include/llvm/Support/TimeProfiler.h b/llvm/include/llvm/Support/TimeProfiler.h index 454a65f70231f4..31f7df10916db9 100644 --- a/llvm/include/llvm/Support/TimeProfiler.h +++ b/llvm/include/llvm/Support/TimeProfiler.h @@ -86,6 +86,8 @@ class raw_pwrite_stream; struct TimeTraceProfiler; TimeTraceProfiler *getTimeTraceProfilerInstance(); +struct TimeTraceProfilerEntry; + /// Initialize the time trace profiler. /// This sets up the global \p TimeTraceProfilerInstance /// variable to be the profiler instance. @@ -120,19 +122,30 @@ Error timeTraceProfilerWrite(StringRef PreferredFileName, /// Profiler copies the string data, so the pointers can be given into /// temporaries. Time sections can be hierarchical; every Begin must have a /// matching End pair but they can nest. -void timeTraceProfilerBegin(StringRef Name, StringRef Detail); -void timeTraceProfilerBegin(StringRef Name, - llvm::function_ref<std::string()> Detail); +TimeTraceProfilerEntry *timeTraceProfilerBegin(StringRef Name, + StringRef Detail); +TimeTraceProfilerEntry * +timeTraceProfilerBegin(StringRef Name, + llvm::function_ref<std::string()> Detail); + +/// Manually begin a time section, with the given \p Name and \p Detail. +/// This starts Async Events having \p Name as a category which is shown +/// separately from other traces. See +/// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.jh64i9l3vwa1 +/// for more details. +TimeTraceProfilerEntry *timeTraceAsyncProfilerBegin(StringRef Name, + StringRef Detail); /// Manually end the last time section. void timeTraceProfilerEnd(); +void timeTraceProfilerEnd(TimeTraceProfilerEntry *E); /// The TimeTraceScope is a helper class to call the begin and end functions /// of the time trace profiler. When the object is constructed, it begins /// the section; and when it is destroyed, it stops it. If the time profiler /// is not initialized, the overhead is a single branch. -struct TimeTraceScope { - +class TimeTraceScope { +public: TimeTraceScope() = delete; TimeTraceScope(const TimeTraceScope &) = delete; TimeTraceScope &operator=(const TimeTraceScope &) = delete; @@ -141,20 +154,23 @@ struct TimeTraceScope { TimeTraceScope(StringRef Name) { if (getTimeTraceProfilerInstance() != nullptr) - timeTraceProfilerBegin(Name, StringRef("")); + Entry = timeTraceProfilerBegin(Name, StringRef("")); } TimeTraceScope(StringRef Name, StringRef Detail) { if (getTimeTraceProfilerInstance() != nullptr) - timeTraceProfilerBegin(Name, Detail); + Entry = timeTraceProfilerBegin(Name, Detail); } TimeTraceScope(StringRef Name, llvm::function_ref<std::string()> Detail) { if (getTimeTraceProfilerInstance() != nullptr) - timeTraceProfilerBegin(Name, Detail); + Entry = timeTraceProfilerBegin(Name, Detail); } ~TimeTraceScope() { if (getTimeTraceProfilerInstance() != nullptr) - timeTraceProfilerEnd(); + timeTraceProfilerEnd(Entry); } + +private: + TimeTraceProfilerEntry *Entry = nullptr; }; } // end namespace llvm diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp index 4d625b3eb5b170..3114f8e7ded598 100644 --- a/llvm/lib/Support/TimeProfiler.cpp +++ b/llvm/lib/Support/TimeProfiler.cpp @@ -11,6 +11,7 @@ //===----------------------------------------------------------------------===// #include "llvm/Support/TimeProfiler.h" +#include "llvm/ADT/STLExtras.h" #include "llvm/ADT/STLFunctionalExtras.h" #include "llvm/ADT/StringMap.h" #include "llvm/Support/JSON.h" @@ -20,6 +21,7 @@ #include <algorithm> #include <cassert> #include <chrono> +#include <memory> #include <mutex> #include <string> #include <vector> @@ -64,17 +66,19 @@ using CountAndDurationType = std::pair<size_t, DurationType>; using NameAndCountAndDurationType = std::pair<std::string, CountAndDurationType>; +} // anonymous namespace + /// Represents an open or completed time section entry to be captured. -struct TimeTraceProfilerEntry { +struct llvm::TimeTraceProfilerEntry { const TimePointType Start; TimePointType End; const std::string Name; const std::string Detail; - + const bool AsyncEvent = false; TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N, - std::string &&Dt) + std::string &&Dt, bool Ae) : Start(std::move(S)), End(std::move(E)), Name(std::move(N)), - Detail(std::move(Dt)) {} + Detail(std::move(Dt)), AsyncEvent(Ae) {} // Calculate timings for FlameGraph. Cast time points to microsecond precision // rather than casting duration. This avoids truncation issues causing inner @@ -92,8 +96,6 @@ struct TimeTraceProfilerEntry { } }; -} // anonymous namespace - struct llvm::TimeTraceProfiler { TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "") : BeginningOfTime(system_clock::now()), StartTime(ClockType::now()), @@ -102,23 +104,24 @@ struct llvm::TimeTraceProfiler { llvm::get_thread_name(ThreadName); } - void begin(std::string Name, llvm::function_ref<std::string()> Detail) { - Stack.emplace_back(ClockType::now(), TimePointType(), std::move(Name), - Detail()); + TimeTraceProfilerEntry *begin(std::string Name, + llvm::function_ref<std::string()> Detail, + bool AsyncEvent = false) { + Stack.emplace_back(std::make_unique<TimeTraceProfilerEntry>( + ClockType::now(), TimePointType(), std::move(Name), Detail(), + AsyncEvent)); + return Stack.back().get(); } void end() { + TimeTraceProfilerEntry *E = Stack.back().get(); + end(*E); + } + + void end(TimeTraceProfilerEntry &E) { assert(!Stack.empty() && "Must call begin() first"); - TimeTraceProfilerEntry &E = Stack.back(); E.End = ClockType::now(); - // Check that end times monotonically increase. - assert((Entries.empty() || - (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >= - Entries.back().getFlameGraphStartUs(StartTime) + - Entries.back().getFlameGraphDurUs())) && - "TimeProfiler scope ended earlier than previous scope"); - // Calculate duration at full precision for overall counts. DurationType Duration = E.End - E.Start; @@ -132,15 +135,18 @@ struct llvm::TimeTraceProfiler { // happens to be the ones that don't have any currently open entries above // itself. if (llvm::none_of(llvm::drop_begin(llvm::reverse(Stack)), - [&](const TimeTraceProfilerEntry &Val) { - return Val.Name == E.Name; + [&](const std::unique_ptr<TimeTraceProfilerEntry> &Val) { + return Val->Name == E.Name; })) { auto &CountAndTotal = CountAndTotalPerName[E.Name]; CountAndTotal.first++; CountAndTotal.second += Duration; - } + }; - Stack.pop_back(); + llvm::erase_if(Stack, + [&](const std::unique_ptr<TimeTraceProfilerEntry> &Val) { + return Val.get() == &E; + }); } // Write events from this TimeTraceProfilerInstance and @@ -168,14 +174,32 @@ struct llvm::TimeTraceProfiler { J.object([&] { J.attribute("pid", Pid); J.attribute("tid", int64_t(Tid)); - J.attribute("ph", "X"); J.attribute("ts", StartUs); - J.attribute("dur", DurUs); + if (E.AsyncEvent) { + J.attribute("cat", E.Name); + J.attribute("ph", "b"); + J.attribute("id", 0); + } else { + J.attribute("ph", "X"); + J.attribute("dur", DurUs); + } J.attribute("name", E.Name); if (!E.Detail.empty()) { J.attributeObject("args", [&] { J.attribute("detail", E.Detail); }); } }); + + if (E.AsyncEvent) { + J.object([&] { + J.attribute("pid", Pid); + J.attribute("tid", int64_t(Tid)); + J.attribute("ts", StartUs + DurUs); + J.attribute("cat", E.Name); + J.attribute("ph", "e"); + J.attribute("id", 0); + J.attribute("name", E.Name); + }); + } }; for (const TimeTraceProfilerEntry &E : Entries) writeEvent(E, this->Tid); @@ -269,7 +293,7 @@ struct llvm::TimeTraceProfiler { J.objectEnd(); } - SmallVector<TimeTraceProfilerEntry, 16> Stack; + SmallVector<std::unique_ptr<TimeTraceProfilerEntry>, 16> Stack; SmallVector<TimeTraceProfilerEntry, 128> Entries; StringMap<CountAndDurationType> CountAndTotalPerName; // System clock time when the session was begun. @@ -341,19 +365,36 @@ Error llvm::timeTraceProfilerWrite(StringRef PreferredFileName, return Error::success(); } -void llvm::timeTraceProfilerBegin(StringRef Name, StringRef Detail) { +TimeTraceProfilerEntry *llvm::timeTraceProfilerBegin(StringRef Name, + StringRef Detail) { + if (TimeTraceProfilerInstance != nullptr) + return TimeTraceProfilerInstance->begin( + std::string(Name), [&]() { return std::string(Detail); }, false); + return nullptr; +} + +TimeTraceProfilerEntry * +llvm::timeTraceProfilerBegin(StringRef Name, + llvm::function_ref<std::string()> Detail) { if (TimeTraceProfilerInstance != nullptr) - TimeTraceProfilerInstance->begin(std::string(Name), - [&]() { return std::string(Detail); }); + return TimeTraceProfilerInstance->begin(std::string(Name), Detail, false); + return nullptr; } -void llvm::timeTraceProfilerBegin(StringRef Name, - llvm::function_ref<std::string()> Detail) { +TimeTraceProfilerEntry *llvm::timeTraceAsyncProfilerBegin(StringRef Name, + StringRef Detail) { if (TimeTraceProfilerInstance != nullptr) - TimeTraceProfilerInstance->begin(std::string(Name), Detail); + return TimeTraceProfilerInstance->begin( + std::string(Name), [&]() { return std::string(Detail); }, true); + return nullptr; } void llvm::timeTraceProfilerEnd() { if (TimeTraceProfilerInstance != nullptr) TimeTraceProfilerInstance->end(); } + +void llvm::timeTraceProfilerEnd(TimeTraceProfilerEntry *E) { + if (TimeTraceProfilerInstance != nullptr) + TimeTraceProfilerInstance->end(*E); +} diff --git a/llvm/unittests/Support/TimeProfilerTest.cpp b/llvm/unittests/Support/TimeProfilerTest.cpp index 6be716bae6b3fb..bb820ec99a393e 100644 --- a/llvm/unittests/Support/TimeProfilerTest.cpp +++ b/llvm/unittests/Support/TimeProfilerTest.cpp @@ -54,6 +54,17 @@ TEST(TimeProfiler, Begin_End_Smoke) { ASSERT_TRUE(json.find(R"("detail":"detail")") != std::string::npos); } +TEST(TimeProfiler, Async_Begin_End_Smoke) { + setupProfiler(); + + auto *Profiler = timeTraceAsyncProfilerBegin("event", "detail"); + timeTraceProfilerEnd(Profiler); + + std::string json = teardownProfiler(); + ASSERT_TRUE(json.find(R"("name":"event")") != std::string::npos); + ASSERT_TRUE(json.find(R"("detail":"detail")") != std::string::npos); +} + TEST(TimeProfiler, Begin_End_Disabled) { // Nothing should be observable here. The test is really just making sure // we've not got a stray nullptr deref. `````````` </details> https://github.com/llvm/llvm-project/pull/83961 _______________________________________________ cfe-commits mailing list cfe-commits@lists.llvm.org https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
