[llvm-bugs] [Bug 43043] New: -ftime-trace output can break flame graph assumptions on Windows

[via llvm-bugs]

https://bugs.llvm.org/show_bug.cgi?id=43043

            Bug ID: 43043
           Summary: -ftime-trace output can break flame graph assumptions
                    on Windows
           Product: new-bugs
           Version: 9.0
          Hardware: PC
                OS: Windows NT
            Status: NEW
          Severity: enhancement
          Priority: P
         Component: new bugs
          Assignee: unassignedbugs at nondot.org
          Reporter: russell_gallop at sn.scee.net
                CC: htmldeveloper at gmail.com, llvm-bugs at lists.llvm.org

Created attachment 22393
  --> https://bugs.llvm.org/attachment.cgi?id=22393&action=edit
Screengrabs of Chrome://tracing and speedscope problems with overlap

-ftime-trace records times to execute scopes of execution to produce a flame
graph to be visualised
with chrome://tracing or speedscope. In a flame graph, the smaller scopes
should be enclosed within
larger scopes (e.g. time increasing to the right, top scope enclosing lower
scopes)

+---------------------------+
|      ExecuteCompiler      |
+---------------------------+
 | Frontend |  | Backend |
 +----------+  +---------+

Sometimes the compiler reports that an enclosed scope (e.g. RunPass) finishes
*after* the enclosing
scope (e.g. OptFunction).

+-------------+
| OptFunction |
+-------------++
   |  RunPass  |
   +-----------+

This seems to happen most around the end of the last RunPass within OptFunction
which have practically
no code between them (so should finish at the same microsecond)*.

Generally this is rare and only overruns by 1 microsecond but it causes
problems for both
chrome://tracing (chrome 75.0.3770.100) which draws the overrunning scope on
top of the "enclosing"
scope (see attachment) and for speedscope (1.5.1) which fails to close the
enclosing scope leading
the scoping to become wrong (note that speedscope does report warnings about
this in the "Console"),
(another example attached, the second OptFunction should be at the same level
as the first).

This looks like a problem with the calculation, in combination with durations
being implementation
defined. Linux (Ubuntu 18.04, g++ 7.30-27ubuntu1~18.04) steady clock reports
times in ns while
Windows (10, VS2019, SDK10) reports them in 100ns. LLVM does some calculations
on these in the
native precision, then duration_casts (truncating) to microseconds for
reporting. The combination
of two truncated durations (timestamp + duration of the outer scope) can become
less than another
two truncated durations (timestamp + duration of the inner scope), even if they
were correct in
relation to each other before truncation. This seems more likely on Windows
which is doing those
calculations at 100ns level than Linux which is doing them at ns level.

As an example (StartTime is clang start time, E1 is the first (Outer) event
scope, E2 is the second (Inner) event scope). The first times are times read
from the steady_clock::now() (with leading significant digits removed).
StartTime 210100ns (start)
E1.Start 354700ns (ts = 144600ns, truncated to 144us)
E2.Start 442200ns (ts = 232100ns, truncated to 232us)
E2.End 530300ns (dur = 88100ns, truncated to 88us)
E1.End 530500ns (dur = 175800ns, truncated to 175us)

In this example, when the visualisation tool reads the JSON file:
Event 1 would be timestamped 144us and have duration 175us so finish at 319us.
Event 2 would be timestamped 232us and have duration 88us to finish at 320us
(after it's enclosing event).

* there is also a bug in speedscope with displaying events with identical
finish times: https://github.com/jlfwong/speedscope/issues/223, this happens
more often with clang traces since r358834 (which added RunPass))

-- 
You are receiving this mail because:
You are on the CC list for the bug.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.llvm.org/pipermail/llvm-bugs/attachments/20190819/5d4d21b3/attachment.html>