[Haskell-cafe] how to read CPU time vs wall time report from GHC?

[Iustin Pop]

On Sun, Aug 14, 2011 at 08:32:36PM +0200, Wishnu Prasetya wrote:
> On 14-8-2011 20:25, Iustin Pop wrote:
> >On Sun, Aug 14, 2011 at 08:11:36PM +0200, Wishnu Prasetya wrote:
> >>Hi guys,
> >>
> >>I'm new in parallel programming with Haskell. I made a simple test
> >>program using that par combinator etc, and was a bit unhappy that it
> >>turns out to be  slower than its sequential version. But firstly, I
> >>dont fully understand how to read the runtime report produced by GHC
> >>with -s option:
> >>
> >>   SPARKS: 5 (5 converted, 0 pruned)
> >>
> >>   INIT  time    0.02s  (  0.01s elapsed)
> >>   MUT   time    3.46s  (  0.89s elapsed)
> >>   GC    time    5.49s  (  1.46s elapsed)
> >>   EXIT  time    0.00s  (  0.00s elapsed)
> >>   Total time    8.97s  (  2.36s elapsed)
> >>
> >>As I understand it from the documentation, the left time-column is
> >>the CPU time, whereas the right one is elapses wall time. But how
> >>come that the wall time is less than the CPU time? Isn't wall time =
> >>user's perspective of time; so that is CPU time + IO + etc?
> >Yes, but if you have multiple CPUs, then CPU time "accumulates" faster
> >than wall-clock time.
> >
> >Based on the above example, I guess you have or you run the program on 4
> >cores (2.36 * 4 = 9.44, which means you got a very nice ~95%
> >efficiency).
> >
> >regards,
> >iustin

> That makes sense... But are you sure thats how i should read this?

As far as I know, this is correct.

> I dont want to jump happy too early.

Well, you algorithm does work in parallel, but if you look at the GC/MUT
time, ~60% of the total runtime is spent in GC, so you have a space leak
or an otherwise inefficient algorithm. The final speedup is just
3.46s/2.36s, i.e. 1.46x instead of ~4x, so you still have some work to
do to make this better.

At least, this is how I read those numbers.

regards,
iustin