Fix -ftime-trace breaking flame-graph assumptions

[russell.gallop]

Summary

-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. Changing this so time points for the flame-graph are truncated, instead of durations, preserves 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: https://bugs.llvm.org/show_bug.cgi?id=43043

[rnk]

Code looks good.

llvm/lib/Support/TimeProfiler.cpp

160–161

nit: "microsecond precision" instead of "us precision", I read it wrong. Variables names seem clear, though.

llvm/unittests/Support/TimeProfilerTest.cpp

19 ↗

(On Diff #215852)

I'm not sure this test has that much value because it will not fail deterministically if you revert the fix to bring back the truncation bugs.

[russell.gallop]

Fixed comment

[russell.gallop]

llvm/unittests/Support/TimeProfilerTest.cpp

19 ↗

(On Diff #215852)

Thanks for the review. I agree it's not ideal, this was the best way I could think of for testing this behaviour.

It might be possible to set the time values to appropriate values to trigger this but that would require exposing a fair bit more of TimeProfiler.cpp.

One alternative might be to have a check in Write() that reconstructed the flame graph and asserted if there was a problem. It would require a very large file (or a lot of files) to reliably hit the issue though.

Or is this okay to send without a test?

[rnk]

llvm/unittests/Support/TimeProfilerTest.cpp

19 ↗

(On Diff #215852)

Test aside, adding the assert seems valuable. As it is written now, it should hold unless the steady clock lies, right?

For the test, how long does the test normally take? If it takes more than 8s-10s, I think I would prefer to remove it and commit this without a test.

[russell.gallop]

llvm/unittests/Support/TimeProfilerTest.cpp

19 ↗

(On Diff #215852)

Test aside, adding the assert seems valuable. As it is written now, it should hold unless the steady clock lies, right?

Yes, I think so. I'll try to add that.

For the test, how long does the test normally take? If it takes more than 8s-10s, I think I would prefer to remove it and commit this without a test.

I measure 5-7 seconds in Release which is quite a large increase to SupportTests.exe (previously 10s).

[russell.gallop]

Added structure check on time profile and assertion.

Without the fix, this assertion fires compiling a single moderately large source file (~30 seconds). With the fix it compiles fine (even with finer granularity (I tried down to 5 microseconds). I think that this is probably a better check than TimeProfilerTest.cpp so, unless anyone disagrees, I'll remove that and just commit the changes to TimeProfiler.cpp.

[mgrang]

llvm/lib/Support/TimeProfiler.cpp

103

You can use the range-based version of llvm:sort here.

llvm::sort(SortedEntries);

[russell.gallop]

llvm/lib/Support/TimeProfiler.cpp

103

Thanks, fixed.

[russell.gallop]

Fix some style issues and remove unit test.

[russell.gallop]

Realised that this could be done with just an assert (no separate check function) so this is a much smaller patch now. This still mostly hits the assertion with the previous way of calculating duration (duration_cast). I think the extra code in end() may make it slightly less likely that this case happens, but only with assertions enabled.

Please take another look.

[rnk]

lgtm, sorry for the delay

llvm/lib/Support/TimeProfiler.cpp

 
 using namespace std::chrono;
 
 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.
+  long long getFlameGraphStartUs(TimePointType StartTime) const {
+    return (time_point_cast<microseconds>(Start) -
+            time_point_cast<microseconds>(StartTime))
+        .count();
+  }
+
+  long long getFlameGraphDurUs() const {
+    return (time_point_cast<microseconds>(End) -
+            time_point_cast<microseconds>(Start))
+        .count();
+  }
 };
 
 struct TimeTraceProfiler {
-  TimeTraceProfiler() {
-    StartTime = steady_clock::now();
-  }
+  TimeTraceProfiler() { StartTime = steady_clock::now(); }
 
   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();
+
+    // 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
     // them; e.g. if there's a template instantiation that instantiates other
     // templates from within, we only want to add the topmost one. "topmost"
     // happens to be the ones that don't have any currently open entries above
     // itself.
     if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) {
           return Val.Name == E.Name;
         }) == Stack.rend()) {
       auto &CountAndTotal = CountAndTotalPerName[E.Name];
       CountAndTotal.first++;
-      CountAndTotal.second += E.Duration;
+      CountAndTotal.second += Duration;
     }
 
     Stack.pop_back();
   }
 
+  // Check that the TimeProfile conforms to Flame Graph assumptions.
+  void checkFlameGraph() const {
+    // Sort primarily by start time and secondarily by reverse end time.
+    // Do this on the steady_clock precision start and end times (easier and
+    // should not be any worse or better).
+    auto SortedEntries = SmallVector<Entry, 128>(Entries);
+    llvm::sort(SortedEntries, [](const Entry &A, const Entry &B) {
+      if (A.Start != B.Start) {
+        return A.Start < B.Start;
+      }
+      return A.End > B.End;
+    });
+
+    // Stack of when current scopes end in microseconds.
+    SmallVector<long long, 16> EndStack;
+    // List of end times (in microseconds) in order they should exit according
+    // to stack.
+    std::vector<long long> EndList;
+    EndList.reserve(Entries.size());
+
+    // Reconstruct stack by working through events.
+    for (const auto &E : SortedEntries) {
+      auto StartUs = E.getFlameGraphStartUs(StartTime);
+      auto DurUs = E.getFlameGraphDurUs();
+      auto EndUs = StartUs + DurUs;
+
+      // Remove closed scopes from EndStack and add to EndList in order exited.
+      while (!EndStack.empty() && (StartUs >= EndStack.back())) {
+        EndList.push_back(EndStack.back());
+        EndStack.pop_back();
+      }
+      // Add end time of this entry to stack.
+      EndStack.push_back(EndUs);
+    }
+
+    // Empty stack of unclosed scopes.
+    while (!EndStack.empty()) {
+      EndList.push_back(EndStack.back());
+      EndStack.pop_back();
+    }
+    // Check EndList monotonically increases.
+    long long LastEnd = 0;
+    for (const auto &End : EndList) {
+      assert((End >= LastEnd) &&
+             "TimeProfiler scope ended earlier than a deeper scope");
+      LastEnd = End;
+    }
+  }
+
   void Write(raw_pwrite_stream &OS) {
     assert(Stack.empty() &&
            "All profiler sections should be ended when calling Write");
+#ifndef NDEBUG
+    checkFlameGraph();
+#endif
+
     json::OStream J(OS);
     J.objectBegin();
     J.attributeBegin("traceEvents");
     J.arrayBegin();
 
     // 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);
         J.attribute("tid", 0);
         J.attribute("ph", "X");
         J.attribute("ts", StartUs);
         J.attribute("dur", DurUs);
         J.attribute("name", E.Name);
#endif
     J.arrayEnd();
     J.attributeEnd();
     J.objectEnd();
   }
 
   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;
 };
 
 void timeTraceProfilerInitialize(unsigned TimeTraceGranularity) {
   assert(TimeTraceProfilerInstance == nullptr &&
          "Profiler should not be initialized");