diff --git a/llvm/include/llvm/Support/TimeProfiler.h b/llvm/include/llvm/Support/TimeProfiler.h index 9e2ba31991f54..8c0ecf9b7c911 100644 --- a/llvm/include/llvm/Support/TimeProfiler.h +++ b/llvm/include/llvm/Support/TimeProfiler.h @@ -83,6 +83,19 @@ namespace llvm { class raw_pwrite_stream; +// 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; // Source file and line number information for the event. @@ -152,6 +165,10 @@ timeTraceProfilerBegin(StringRef Name, TimeTraceProfilerEntry *timeTraceAsyncProfilerBegin(StringRef Name, StringRef Detail); +// Mark an instant event. +void timeTraceAddInstantEvent(StringRef Name, + llvm::function_ref 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 c2014028ddadc..29c1c97ddf3c5 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; + const TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent; 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,25 @@ 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 { + TimeTraceProfilerEntry Event; + std::vector InstantEvents; + + 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::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 +134,40 @@ struct llvm::TimeTraceProfiler { llvm::get_thread_name(ThreadName); } - TimeTraceProfilerEntry *begin(std::string Name, - llvm::function_ref Detail, - bool AsyncEvent = false) { - Stack.emplace_back(std::make_unique( + TimeTraceProfilerEntry * + begin(std::string Name, llvm::function_ref Detail, + TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent) { + assert(EventType != TimeTraceEventType::InstantEvent && + "Instant Events don't have begin and end."); + Stack.emplace_back(std::make_unique( ClockType::now(), TimePointType(), std::move(Name), Detail(), - AsyncEvent)); - return Stack.back().get(); + EventType)); + return &Stack.back()->Event; } TimeTraceProfilerEntry * begin(std::string Name, llvm::function_ref Metadata, - bool AsyncEvent = false) { - Stack.emplace_back(std::make_unique( + TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent) { + assert(EventType != TimeTraceEventType::InstantEvent && + "Instant Events don't have begin and end."); + Stack.emplace_back(std::make_unique( ClockType::now(), TimePointType(), std::move(Name), Metadata(), - AsyncEvent)); - return Stack.back().get(); + EventType)); + return &Stack.back()->Event; + } + + void insert(std::string Name, llvm::function_ref Detail) { + if (Stack.empty()) + return; + + Stack.back().get()->InstantEvents.emplace_back(TimeTraceProfilerEntry( + ClockType::now(), TimePointType(), std::move(Name), Detail(), + TimeTraceEventType::InstantEvent)); } void end() { assert(!Stack.empty() && "Must call begin() first"); - end(*Stack.back()); + end(Stack.back()->Event); } void end(TimeTraceProfilerEntry &E) { @@ -144,9 +177,19 @@ 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 &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(Duration).count() >= TimeTraceGranularity) + if (duration_cast(Duration).count() >= TimeTraceGranularity) { Entries.emplace_back(E); + for (auto &IE : Iter->get()->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,15 @@ 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 &Val) { - return Val->Name == E.Name; + [&](const std::unique_ptr &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 &Val) { - return Val.get() == &E; - }); + Stack.erase(Iter); } // Write events from this TimeTraceProfilerInstance and @@ -194,13 +234,17 @@ 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 + assert(E.EventType == TimeTraceEventType::InstantEvent && + "InstantEvent expected"); + J.attribute("ph", "i"); } J.attribute("name", E.Name); if (!E.Metadata.isEmpty()) { @@ -215,7 +259,7 @@ struct llvm::TimeTraceProfiler { } }); - if (E.AsyncEvent) { + if (E.EventType == TimeTraceEventType::AsyncEvent) { J.object([&] { J.attribute("pid", Pid); J.attribute("tid", int64_t(Tid)); @@ -319,7 +363,7 @@ struct llvm::TimeTraceProfiler { J.objectEnd(); } - SmallVector, 16> Stack; + SmallVector, 16> Stack; SmallVector Entries; StringMap 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 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 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,17 @@ 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::timeTraceAddInstantEvent(StringRef Name, + llvm::function_ref Detail) { + if (TimeTraceProfilerInstance != nullptr) + TimeTraceProfilerInstance->insert(std::string(Name), Detail); +} + void llvm::timeTraceProfilerEnd() { if (TimeTraceProfilerInstance != nullptr) TimeTraceProfilerInstance->end(); diff --git a/llvm/unittests/Support/TimeProfilerTest.cpp b/llvm/unittests/Support/TimeProfilerTest.cpp index bb820ec99a393..aa1185bae2961 100644 --- a/llvm/unittests/Support/TimeProfilerTest.cpp +++ b/llvm/unittests/Support/TimeProfilerTest.cpp @@ -72,4 +72,28 @@ TEST(TimeProfiler, Begin_End_Disabled) { timeTraceProfilerEnd(); } +TEST(TimeProfiler, Instant_Add_Smoke) { + setupProfiler(); + + timeTraceProfilerBegin("sync event", "sync detail"); + timeTraceAddInstantEvent("instant event", [&] { return "instant detail"; }); + timeTraceProfilerEnd(); + + std::string json = teardownProfiler(); + ASSERT_TRUE(json.find(R"("name":"sync event")") != std::string::npos); + ASSERT_TRUE(json.find(R"("detail":"sync detail")") != std::string::npos); + ASSERT_TRUE(json.find(R"("name":"instant event")") != std::string::npos); + ASSERT_TRUE(json.find(R"("detail":"instant detail")") != std::string::npos); +} + +TEST(TimeProfiler, Instant_Not_Added_Smoke) { + setupProfiler(); + + timeTraceAddInstantEvent("instant event", [&] { return "instant detail"; }); + + std::string json = teardownProfiler(); + ASSERT_TRUE(json.find(R"("name":"instant event")") == std::string::npos); + ASSERT_TRUE(json.find(R"("detail":"instant detail")") == std::string::npos); +} + } // namespace