[llvm] r371039 - Fix time-trace breaking flame graph assumptions
Russell Gallop via llvm-commits
llvm-commits at lists.llvm.org
Thu Sep 5 02:26:04 PDT 2019
Author: russell_gallop
Date: Thu Sep 5 02:26:04 2019
New Revision: 371039
URL: http://llvm.org/viewvc/llvm-project?rev=371039&view=rev
Log:
Fix time-trace breaking flame graph assumptions
-ftime-trace could break flame-graph assumptions on Windows, with an
inner scope overrunning outer scopes. This was due to the way that times
were truncated. Changed this so time_points for the flame-graph are
truncated instead of durations, preserving the relative order of event
starts and ends.
I have tried to retain the extra precision for the totals, which count
thousands or millions of events.
Added assert to check this property holds in future.
Fixes PR43043
Differential Revision: https://reviews.llvm.org/D66411
Modified:
llvm/trunk/lib/Support/TimeProfiler.cpp
Modified: llvm/trunk/lib/Support/TimeProfiler.cpp
URL: http://llvm.org/viewvc/llvm-project/llvm/trunk/lib/Support/TimeProfiler.cpp?rev=371039&r1=371038&r2=371039&view=diff
==============================================================================
--- llvm/trunk/lib/Support/TimeProfiler.cpp (original)
+++ llvm/trunk/lib/Support/TimeProfiler.cpp Thu Sep 5 02:26:04 2019
@@ -27,20 +27,35 @@ namespace llvm {
TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
typedef duration<steady_clock::rep, steady_clock::period> DurationType;
+typedef time_point<steady_clock> TimePointType;
typedef std::pair<size_t, DurationType> CountAndDurationType;
typedef std::pair<std::string, CountAndDurationType>
NameAndCountAndDurationType;
struct Entry {
- time_point<steady_clock> Start;
- DurationType Duration;
+ TimePointType Start;
+ TimePointType End;
std::string Name;
std::string Detail;
- Entry(time_point<steady_clock> &&S, DurationType &&D, std::string &&N,
- std::string &&Dt)
- : Start(std::move(S)), Duration(std::move(D)), Name(std::move(N)),
+ Entry(TimePointType &&S, TimePointType &&E, std::string &&N, std::string &&Dt)
+ : Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
Detail(std::move(Dt)){};
+
+ // Calculate timings for FlameGraph. Cast time points to microsecond precision
+ // rather than casting duration. This avoid truncation issues causing inner
+ // scopes overruning outer scopes.
+ steady_clock::rep getFlameGraphStartUs(TimePointType StartTime) const {
+ return (time_point_cast<microseconds>(Start) -
+ time_point_cast<microseconds>(StartTime))
+ .count();
+ }
+
+ steady_clock::rep getFlameGraphDurUs() const {
+ return (time_point_cast<microseconds>(End) -
+ time_point_cast<microseconds>(Start))
+ .count();
+ }
};
struct TimeTraceProfiler {
@@ -49,17 +64,27 @@ struct TimeTraceProfiler {
}
void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
- Stack.emplace_back(steady_clock::now(), DurationType{}, std::move(Name),
+ Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name),
Detail());
}
void end() {
assert(!Stack.empty() && "Must call begin() first");
auto &E = Stack.back();
- E.Duration = steady_clock::now() - E.Start;
+ E.End = steady_clock::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;
// Only include sections longer or equal to TimeTraceGranularity msec.
- if (duration_cast<microseconds>(E.Duration).count() >= TimeTraceGranularity)
+ if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity)
Entries.emplace_back(E);
// Track total time taken by each "name", but only the topmost levels of
@@ -72,7 +97,7 @@ struct TimeTraceProfiler {
}) == Stack.rend()) {
auto &CountAndTotal = CountAndTotalPerName[E.Name];
CountAndTotal.first++;
- CountAndTotal.second += E.Duration;
+ CountAndTotal.second += Duration;
}
Stack.pop_back();
@@ -88,8 +113,8 @@ struct TimeTraceProfiler {
// Emit all events for the main flame graph.
for (const auto &E : Entries) {
- auto StartUs = duration_cast<microseconds>(E.Start - StartTime).count();
- auto DurUs = duration_cast<microseconds>(E.Duration).count();
+ auto StartUs = E.getFlameGraphStartUs(StartTime);
+ auto DurUs = E.getFlameGraphDurUs();
J.object([&]{
J.attribute("pid", 1);
@@ -154,7 +179,7 @@ struct TimeTraceProfiler {
SmallVector<Entry, 16> Stack;
SmallVector<Entry, 128> Entries;
StringMap<CountAndDurationType> CountAndTotalPerName;
- time_point<steady_clock> StartTime;
+ TimePointType StartTime;
// Minimum time granularity (in microseconds)
unsigned TimeTraceGranularity;
More information about the llvm-commits
mailing list