[llvm] r371039 - Fix time-trace breaking flame graph assumptions

[Russell Gallop via llvm-commits]

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;