Is it possible to profiling space usage in Haskell

Question

Lecture chapter 12 by Erik mention "improve space usage" by introduce an example function sumWith.

I represent both lazy version and strict version as below.

sumWith1 v [] = v
sumWith1 v (x:xs) = sumWith1 (v+x) xs

sumWith2 v [] = v
sumWith2 v (x:xs) = (sumWith2 $! (v+x)) xs

test = sumWith1 0 [1..200000000]

I guess the strict version should improve performance at certain level thus I try to verify leverage GHC profiling tool.

$ ghc --make -O2 -prof -auto-all -rtsopts -o test1
$ ./test1 +RTS -p -RTS

Change sumWith1 to sumWith2 at test function and execute again as test2.

Here is the profiling result: http://pastie.org/4720019.

By looking at %alloc column, I don't see any diff between those two functions.

My question is how shall I improve the test case in order to find some difference. In other words, is it possible to profiling the space usage for such case?

Thank you.

Answer 1

Use GHC's heap profiler.

It is described in detail in RWH, ch25. Here is a fully worked example.

Answer 2

Here are the statistics for you program (I have reduced the upper limit to 1000000)

Here is your slighly modified program

sumWith1 v [] = v
sumWith1 v (x:xs) = sumWith1 (v+x) xs

sumWith2 v [] = v
sumWith2 v (x:xs) = (sumWith2 $! (v+x)) xs

main = print $ sumWith1 0 [1..1000000]

Compiling with ghc -prof -fprof-auto -rtsopts heap.hs

For sumwith1

./heap +RTS -sstderr -K500M
500000500000
     266,384,496 bytes allocated in the heap
     367,442,520 bytes copied during GC
     117,747,616 bytes maximum residency (8 sample(s))
       1,931,472 bytes maximum slop
             196 MB total memory in use (0 MB lost due to fragmentation)

                                    Tot time (elapsed)  Avg pause  Max pause
  Gen  0       393 colls,     0 par    0.19s    0.19s     0.0005s    0.0455s
  Gen  1         8 colls,     0 par    0.20s    0.21s     0.0257s    0.0832s

  INIT    time    0.00s  (  0.00s elapsed)
  MUT     time    0.15s  (  0.16s elapsed)
  GC      time    0.39s  (  0.39s elapsed)
  RP      time    0.00s  (  0.00s elapsed)
  PROF    time    0.00s  (  0.00s elapsed)
  EXIT    time    0.00s  (  0.00s elapsed)
  Total   time    0.55s  (  0.55s elapsed)

  %GC     time      71.2%  (71.5% elapsed)

  Alloc rate    1,689,230,189 bytes per MUT second

  Productivity  28.7% of total user, 28.7% of total elapsed

For sumwith2

./heap +RTS -sstderr -K500M           
500000500000
     256,057,488 bytes allocated in the heap
          65,256 bytes copied during GC
          30,240 bytes maximum residency (1 sample(s))
          21,440 bytes maximum slop
               1 MB total memory in use (0 MB lost due to fragmentation)

                                    Tot time (elapsed)  Avg pause  Max pause
  Gen  0       488 colls,     0 par    0.00s    0.00s     0.0000s    0.0000s
  Gen  1         1 colls,     0 par    0.00s    0.00s     0.0003s    0.0003s

  INIT    time    0.00s  (  0.00s elapsed)
  MUT     time    0.14s  (  0.14s elapsed)
  GC      time    0.00s  (  0.00s elapsed)
  RP      time    0.00s  (  0.00s elapsed)
  PROF    time    0.00s  (  0.00s elapsed)
  EXIT    time    0.00s  (  0.00s elapsed)
  Total   time    0.14s  (  0.14s elapsed)

  %GC     time       1.8%  (1.8% elapsed)

  Alloc rate    1,798,840,354 bytes per MUT second

  Productivity  98.0% of total user, 99.3% of total elapsed

You can see the considerable difference in GC amount and total memory used. For more information you can refer to the RWH chapter as pointed by Don.