Ghc-events

From HaskellWiki
Jump to navigation Jump to search
The printable version is no longer supported and may have rendering errors. Please update your browser bookmarks and please use the default browser print function instead.

Analysing Event Logs

General

The ghc-events package (http://hackage.haskell.org/package/ghc-events) is designed to let you do your own analyses.

The events are partly documented formally using state machines, in the form of code in the ghc-events package. Less formally, you can work out what they do by looking at the event header file and/or the data definition for the events.

The new memory/heap/gc events are partly documented here: http://trac.haskell.org/ThreadScope/wiki/RTSsummaryEvents

For CPU usage per HEC (also called cap or capability) and which is usually equiv to a core, you want to look at thread start/stop events on each HEC, and thus work out the fraction of time spent running threads on a core, vs doing GC or doing nothing. You can also look at the code in ThreadScope which does this calculation (or rather, it builds a data structure which lets us calculate it for any time interval).

There is an extension ghc-events-parallel (used by Eden-Trace Viewer, a tool to analyse parallel traces with multiple runtime system instance, longer story at http://www.mathematik.uni-marburg.de/~eden/). For more details you can also look at the GHC source code, for instance here (GHC variant for clusters and multicores): http://james.mathematik.uni-marburg.de:8080/gitweb/?p=ghc-eden.git;a=blob;f=includes/rts/EventLogFormat.h;h=321f54465445fc688594bc6e811e9f929743f4bd;hb=HEAD

Example

The 'cap' field here refers to a 'Capability', a kind of virtual processor that runs Haskell code. That's the number of processors you ask the runtime to use with +RTS -N. See http://hackage.haskell.org/trac/ghc/wiki/Commentary/Rts/Scheduler#Capabilities The time is probably in nanoseconds, this seems to be confirmed by https://github.com/ghc/ghc/blob/master/includes/rts/EventLogFormat.h which also apparently specifies the format.


 2117000: cap 1: creating thread 1
 2117000: cap 1: thread 1 is runnable
 2119000: cap 1: running thread 1
 2193000: cap 1: stopping thread 1 (making a foreign call)
 2195000: cap 1: running thread 1
 2200000: cap 1: stopping thread 1 (making a foreign call)
 2200000: cap 1: running thread 1
 2239000: cap 1: creating thread 2
 2239000: cap 1: thread 2 is runnable
 2244000: cap 1: stopping thread 1 (thread yielding)
 2244000: cap 1: thread 1 is runnable
 2333000: cap 1: running thread 2
 2386000: cap 1: stopping thread 2 (making a foreign call)
 2420000: cap 1: running thread 1
 2423000: cap 1: thread 2 has label "IOManager"
 2424000: cap 1: stopping thread 1 (thread finished)
 2484000: cap 0: creating thread 3
 2484000: cap 0: thread 3 is runnable
 2484000: cap 0: running thread 3
12187000: cap 0: stopping thread 3 (thread yielding)
12187000: cap 0: thread 3 is runnable
12189000: cap 0: running thread 3
21252000: cap 0: Repa.loadP[Delayed]: start
21263000: cap 0: creating thread 4
21263000: cap 0: thread 4 is runnable
21264000: cap 0: creating thread 5
21264000: cap 0: migrating thread 5 to cap 1
21264000: cap 0: waking up thread 5 on cap 1
21275000: cap 0: stopping thread 3 (blocked on an MVar)
21285000: cap 0: running thread 4
21287000: cap 1: waking up thread 5 on cap 1
21287000: cap 1: thread 5 is runnable
21287000: cap 1: running thread 5
23445000: cap 0: waking up thread 3 on cap 0
23445000: cap 0: thread 3 is runnable
23446000: cap 0: stopping thread 4 (blocked on an MVar)
23448000: cap 1: stopping thread 5 (blocked on an MVar)