Ghc-events

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)