[RFC] Compiler pipeline timings visualization

Fri May 1 09:09:28 UTC 2020

tl;dr: I propose adding a new GHC flag for generating a log that allows
visualizing how much time each stage in the compiler pipleline took, similar
to Clang's -ftime-trace.

Hello, everyone.

I'd like to tell you about a feature I've been working on recently, namely,
the ability to generate and visualize how long each stage of the compilation
pipeline takes to complete. This is basically about the same as
the -ftime-trace flag that has landed in Clang several months ago [1].

The initial motivation for this feature was the desire to understand why
compilation times are so long when using LLVM as backend. But later I realized
that this functionality is useful on its own for end users, not just GHC devs,
so it would make sense to add a new flag -ddump-time-trace.

Since not only does Haskell have complex type system, but also there is
a variety of language extensions, we, the Haskell users, often experience
very long compilation times. For instance, the usage of the TypeFaimilies 
extension can considerably slow down the compilation process [2].
It is useful to understand how you can fix your code so that it compiles faster.

There are two options for that right now:
- Building GHC from source for profiling and using the just-built GHC for
  compiling your problem code.
- Building the compiler from source with event log support [3].

The former option just doesn't do it, since the output would be
"which GHC function calls took how much time", but there'd be no information
about which part of the user code was being compiled.

The latter option is much closer to what we need. If we link the GHC executable
with the -eventlog flag, then various significant events will be written to
a special log file. For example, "Parser began parsing the Main.hs file after
5 ms since GHC has started, and ended parsing it 3 ms after that".
The resulting log file can be parsed with the ghc-events library [4], and also
visualized using the ThreadScope app [5].

Bu this approach has its disadvantages.

Firstly, if the user wants visualization, they'd have to install ThreadScope.
Some companies' internal policies prohibit installing third-party apps from
the internet. It would be good if we could generate a log that could be
visualized on any computer with a browser. For that we could use
the Chrome Trace Event format [6]. This is an ordinary JSON file with a specific
structure that can be viewed in the Chrome browser by going to
the chrome://tracing page, or on https://speedscope.app. A file in exactly this
format would be generated by Clang if you passed it the -ftime-trace flag.

Secondly, the event log contains many events that are not relevant to the end
user, for example, thread creation, memory allocation, etc.

As an initial proof of concept, I've developed a command line tool for
transforming event log files to Chrome Trace Event files [7].

Thirdly, in order for the event log to be generated, you'd still have to build
GHC from source. The majority of the GHC users won't go this way. Not only
would it require some basic understanding of the GHC building process, but also
building itself takes quite some time. It would be great if the needed
functionality came with GHC out of the box.

This is why I've added support for generating Trace Event files into my fork
of GHC [8], and I would like to propose including this feature into the mainline
GHC.

(Note that my implementation is still a bit buggy, for example, it only works
in -j mode. This will be fixed.)

You can now execute the following command:

ghc -ddump-to-file -ddump-file-prefix="Main." -ddump-time-trace -j -O3 Main.hs

And receive this image [9]. Here, we've compiled two modules, one of which
depends on the other.

One more difference from event log is that now various metadata
(like file and module names) are emitted as a separate JSON attribute, instead
of being encoded in the name of an event. For example, parsing the Main.hs file
and parsing the QSort.hs file in one compilation are events with the same name,
but different metadata. We can group them together if we want to know how much
time the parsing took overall. The event log format doesn't allow us to do it.

So, we can now generate a Trace Event file from a single GHC invocation.
However, most projects use build systems that invoke the compiler many times.
It would be good if we could form a log for the whole project.

This is solved by merging logs. However, there is one subtlety: the events in
logs use relative timestamps (the number of microseconds since the process
has started). To combine logs from multiple processes, we add a clock
synchronization point into each trace log in the form of an additional
'beginningOfTime' JSON attribute that contains the absolute time when
the proccess has started.

There is a Python script that performs the actual merging [10].

This is how it looks like with multiple processes [11].

Also, I've implemented generation of the 'beginningOfTime' attribute in
LLVM [12], so build systems could take advantage of that and combine GHC trace
logs with llc/opt trace logs when GHC uses LLVM as backend.

Thoughts?

Sergej.

[1]  https://aras-p.info/blog/2019/01/16/time-trace-timeline-flame-chart-profiler-for-Clang/
[2]  https://gitlab.haskell.org/ghc/ghc/issues/8095
[3]  https://gitlab.haskell.org/ghc/ghc/-/wikis/event-log
[4]  http://hackage.haskell.org/package/ghc-events
[5]  https://wiki.haskell.org/ThreadScope
[6]  https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit
[7]  https://github.com/broadwaylamb/ghc-eventlog-chrome
[8]  https://gitlab.haskell.org/broadwaylamb/ghc/-/commits/timetrace-better-metadata
[9]  https://user-images.githubusercontent.com/16309982/79079705-39775e00-7d19-11ea-9507-eb0f11581c63.png
[10] https://github.com/broadwaylamb/merge_trace_events
[11] https://user-images.githubusercontent.com/16309982/79080338-ad673580-7d1c-11ea-9e30-5e6f72e77555.png
[12] https://github.com/llvm/llvm-project/commit/2899103108d38215af8aae377cd0e54794278209