[Haskell-cafe] how to read CPU time vs wall time report from GHC?
iusty at k1024.org
Sun Aug 14 21:53:21 CEST 2011
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%
> 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.
More information about the Haskell-Cafe