This sounds great! Event logging needn't add much cost if we don't log much -- eg just compiler phases. It simply depends on how many events you generate!
For naïve uses, the log you show in [9] is a bit complicated. Something even simpler might be good. Simon | -----Original Message----- | From: ghc-devs <ghc-devs-boun...@haskell.org> On Behalf Of Andreas | Klebinger | Sent: 01 May 2020 11:04 | To: Sergej Jaskiewicz <jaskiewi...@icloud.com> | Cc: ghc-devs@haskell.org | Subject: Re: [RFC] Compiler pipeline timings visualization | | Hi Sergej, | | I think this is a good idea in general, and it seems you did some great | work there already. | Something like this can also help with pinpointing performance issues | inside the compiler | so would not just be useful to end users. | | intuitively I would assume that instead of adding another way | to produce compiler events we should: | * Ship GHC with eventlog enabled by default | * Provide an official converter from eventLog to the chrome trace format. | | The eventlog format is quite flexible, and if it's unsuitable to what | you want I would | prefer to extend it rather than adding support for additional formats | inside GHC itself. | | This way we: | * Continue to have one unified way to dump events from haskell apps (the | eventlog) | * Users need not go to third party apps, as the converter could | reasonably come with GHC (like hp2ps) | * We are free to include information that can't (easily) be encoded in | the chrome format. | | The downside is that users will have to invoke ghc, followed by some | other tool to get the | chrome trace, but to me that seems like a worthwhile tradeoff for | keeping the compiler and | various visualization formats somewhat separated. | | The obvious question there is how much enabling the eventlog by default | would impact non-logging ghc | invocations. I have not measured this and it might rule out this | approach if it has a big impact and isn't | easily corrected. | | As a last point I want to encourage you to open a ticket about this. | Mailing list threads tend to be harder to follow and find down the line | then tickets in my experience. | | Cheers, | Andreas | | Sergej Jaskiewicz via ghc-devs schrieb am 01.05.2020 um 11:09: | > 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 | > | > _______________________________________________ | > ghc-devs mailing list | > ghc-devs@haskell.org | > http://mail.haskell.org/cgi-bin/mailman/listinfo/ghc-devs | | _______________________________________________ | ghc-devs mailing list | ghc-devs@haskell.org | http://mail.haskell.org/cgi-bin/mailman/listinfo/ghc-devs _______________________________________________ ghc-devs mailing list ghc-devs@haskell.org http://mail.haskell.org/cgi-bin/mailman/listinfo/ghc-devs