Analyzing Eventlogs

[Dominic Steinitz]

Hi,

I am trying to reproduce the threadscope results that Don Stewart obtained on my code (http://stackoverflow.com/questions/14082158/idiomatic-option-pricing-and-risk-using-repa-parallel-arrays). Sadly I can't get threadscope to work so whilst I was trying to fix the problem I thought would analyse the eventlog myself.

My question is: is there somewhere that describes what the various fields in the eventlogs are? I had a dig around but couldn't find anything. Clearly I can create textual versions of the eventlog using http://hackage.haskell.org/package/ghc-events but it is not clear (to me at any rate) what the various fields mean.

What I would like to be able to do is produce a graph showing when processors are active, in particular when parallelism is being achieved. I assume the rightmost column is a timestamp but in what units (I suspect it is *not* microseconds)? How do I know when a processor is active and when it is inactive? Do I need to know anything else to draw what I hope is a pretty simple graph? I have included an example eventlog below for reference.

Many thanks, Dominic.

  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)

[Alp Mestanogullari]

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

And I think the time is 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.

--
Alp Mestanogullari

[Simon Peyton-Jones]

Duncan has been working on the event-log stuff recently, so he probably has up to date documentation somewhere.  Duncan?

It would be good to have a GHC Wiki page to summarise implementation stuff about Threadscope.  The user page is here http://www.haskell.org/haskellwiki/ThreadScope, but presumably should not contain implementation details.

 

Also in what way doesn’t Threadscope work for you?

 

Simon

[Dominic Steinitz]

I get this with threadscope:

threadscope Question.eventlog 

Segmentation fault: 11

It's almost certainly because I am on a Mac and because threadscope relies on gtk. I followed the instructions here: http://www.haskell.org/haskellwiki/Gtk2Hs/Mac#HomeBrew_.2864_bit.2C_last_checked_2012-08.29 and gtk-demo works as does http://projects.haskell.org/gtk2hs/documentation/#hello_world. Sadly the error message above doesn't really give any clues on how to fix the problem.

Other Mac users have reported problems with gtk so I thought it might be easier to do my own analysis of the eventlog as I really only want to show that my program (to simultaneously solve many partial differential equations) is actually using more than 1 processor (which Don Stewart already managed to show using threadscope).

I thought I might be able to use ghc-events (http://hackage.haskell.org/package/ghc-events) to parse the eventlog file and then display the results graphically with the diagrams package (http://projects.haskell.org/diagrams).

I will hold off asking more questions about the meaning of entries in the eventlog file until Duncan has had a chance to respond.

Thanks, Dominic.

On 1 Jan 2013, at 18:48, Simon Peyton-Jones <sim...@microsoft.com> wrote:

Duncan has been working on the event-log stuff recently, so he probably has up to date documentation somewhere.  Duncan?

It would be good to have a GHC Wiki page to summarise implementation stuff about Threadscope.  The user page is here http://www.haskell.org/haskellwiki/ThreadScope, but presumably should not contain implementation details.

 

Also in what way doesn’t Threadscope work for you?

 

Simon

 

[Dominic Steinitz]

Thanks very much. I will summarise the analysis I plan to do in an email but it might not be until the weekend as sadly I am back at work tomorrow.

[Duncan Coutts]

On Tue, 2013-01-01 at 20:22 +0000, Dominic Steinitz wrote:

> I thought I might be able to use ghc-events
> (http://hackage.haskell.org/package/ghc-events) to parse the eventlog
> file and then display the results graphically with the diagrams
> package (http://projects.haskell.org/diagrams).

Right, the ghc-events package is designed to let you do your own
analyses.

> I will hold off asking more questions about the meaning of entries in
> the eventlog file until Duncan has had a chance to respond.

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).

--
Duncan Coutts, Haskell Consultant
Well-Typed LLP, http://www.well-typed.com/

[Dominic Steinitz]

Hi Duncan,

Thanks for this. Perhaps it would be worth adding the information you provided to a wiki page? I'll do this unless anyone objects.

Dominic.

[Johannes Waldmann]

Dominic Steinitz <idontgetoutmuch@...> writes:

> Sadly I can't get threadscope to work [...]

It seems that theadscope (as provided on hackage) cannot be built
with ghc-7.6.1 (because the Gtk build fails). This works:

cabal install threadscope --with-ghc=ghc-7.4.2

and this "threadscope" can be used to read eventlogs
written by executables that have been compiled with ghc-7.6

- Johannes.