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

117–118

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

112

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

llvm::sort(SortedEntries);

[russell.gallop]

llvm/lib/Support/TimeProfiler.cpp

112

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.
+  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 {
   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();
+
+    // 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
     // 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();
   }
 
   void Write(raw_pwrite_stream &OS) {
     assert(Stack.empty() &&
            "All profiler sections should be ended when calling Write");
+
     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);
void Write(raw_pwrite_stream &OS) {
     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");