GHC 6.10, strange behaviour when profiling?

Hello, I'm experiencing some strange behaviour with GHC 6.10 and would like an explanation why. Here's the problem. With GHC 6.8.[23] memory usage of a program was about 250mb (computing pi to 10^6 decimals). Now I tried recompiling and running with GHC 6.10 and I got more than 1.4gb before I killed it, so naturally I tried profiling but here's the strangeness. When I compile for profiling with -prof -auto-all and run with +RTS -p -RTS memory use is still about the same as before (> 1.4gb), but when I try running with +RTS -hc -RTS memory only reaches about 250mb. What is the explanation for this behaviour? I would send a program but it requires HERA, which is not on hackage ... Here is the output of -s ./Test 100000 +RTS -s 47,467,176 bytes allocated in the heap 18,046,776 bytes copied during GC 9,215,104 bytes maximum residency (6 sample(s)) 711,520 bytes maximum slop 80 MB total memory in use (11 MB lost due to fragmentation) Generation 0: 84 collections, 0 parallel, 0.01s, 0.01s elapsed Generation 1: 6 collections, 0 parallel, 0.01s, 0.01s elapsed INIT time 0.00s ( 0.00s elapsed) MUT time 3.66s ( 3.71s elapsed) GC time 0.02s ( 0.02s elapsed) RP time 0.00s ( 0.00s elapsed) PROF time 0.00s ( 0.00s elapsed) EXIT time 0.00s ( 0.00s elapsed) Total time 3.68s ( 3.73s elapsed) %GC time 0.5% (0.6% elapsed) Alloc rate 12,982,553 bytes per MUT second Productivity 99.5% of total user, 97.9% of total elapsed ./Test 100000 +RTS -s -hc 47,471,160 bytes allocated in the heap 18,637,752 bytes copied during GC 13,580,144 bytes maximum residency (37 sample(s)) 810,712 bytes maximum slop 33 MB total memory in use (7 MB lost due to fragmentation) Generation 0: 85 collections, 0 parallel, 0.02s, 0.02s elapsed Generation 1: 37 collections, 0 parallel, 0.00s, 0.01s elapsed INIT time 0.00s ( 0.00s elapsed) MUT time 3.67s ( 3.73s elapsed) GC time 0.02s ( 0.03s elapsed) RP time 0.00s ( 0.00s elapsed) PROF time 0.00s ( 0.00s elapsed) EXIT time 0.00s ( 0.00s elapsed) Total time 3.70s ( 3.77s elapsed) %GC time 0.6% (0.8% elapsed) Alloc rate 12,941,165 bytes per MUT second Productivity 99.2% of total user, 97.4% of total elapsed -- Best regards, Aleš

Could you please file this as a bug at this address, http://hackage.haskell.org/trac/ghc/newticket?type=bug Cheers, Don ales.bizjak0:
Hello,
I'm experiencing some strange behaviour with GHC 6.10 and would like an explanation why.
Here's the problem. With GHC 6.8.[23] memory usage of a program was about 250mb (computing pi to 10^6 decimals). Now I tried recompiling and running with GHC 6.10 and I got more than 1.4gb before I killed it, so naturally I tried profiling but here's the strangeness. When I compile for profiling with -prof -auto-all and run with +RTS -p -RTS memory use is still about the same as before (> 1.4gb), but when I try running with +RTS -hc -RTS memory only reaches about 250mb.
What is the explanation for this behaviour?
I would send a program but it requires HERA, which is not on hackage ...
Here is the output of -s
./Test 100000 +RTS -s 47,467,176 bytes allocated in the heap 18,046,776 bytes copied during GC 9,215,104 bytes maximum residency (6 sample(s)) 711,520 bytes maximum slop 80 MB total memory in use (11 MB lost due to fragmentation)
Generation 0: 84 collections, 0 parallel, 0.01s, 0.01s elapsed Generation 1: 6 collections, 0 parallel, 0.01s, 0.01s elapsed
INIT time 0.00s ( 0.00s elapsed) MUT time 3.66s ( 3.71s elapsed) GC time 0.02s ( 0.02s elapsed) RP time 0.00s ( 0.00s elapsed) PROF time 0.00s ( 0.00s elapsed) EXIT time 0.00s ( 0.00s elapsed) Total time 3.68s ( 3.73s elapsed)
%GC time 0.5% (0.6% elapsed)
Alloc rate 12,982,553 bytes per MUT second
Productivity 99.5% of total user, 97.9% of total elapsed
./Test 100000 +RTS -s -hc 47,471,160 bytes allocated in the heap 18,637,752 bytes copied during GC 13,580,144 bytes maximum residency (37 sample(s)) 810,712 bytes maximum slop 33 MB total memory in use (7 MB lost due to fragmentation)
Generation 0: 85 collections, 0 parallel, 0.02s, 0.02s elapsed Generation 1: 37 collections, 0 parallel, 0.00s, 0.01s elapsed
INIT time 0.00s ( 0.00s elapsed) MUT time 3.67s ( 3.73s elapsed) GC time 0.02s ( 0.03s elapsed) RP time 0.00s ( 0.00s elapsed) PROF time 0.00s ( 0.00s elapsed) EXIT time 0.00s ( 0.00s elapsed) Total time 3.70s ( 3.77s elapsed)
%GC time 0.6% (0.8% elapsed)
Alloc rate 12,941,165 bytes per MUT second
Productivity 99.2% of total user, 97.4% of total elapsed
-- Best regards, Aleš _______________________________________________ Haskell-Cafe mailing list Haskell-Cafe@haskell.org http://www.haskell.org/mailman/listinfo/haskell-cafe

I think you hit bug http://hackage.haskell.org/trac/ghc/ticket/2747,
which is an accounting bug in the garbage collector and goes away when
you trigger more garbage collections (which -hc does, I think).
Please file a bug report anyway, so we can verify that it is indeed
not a new bug. (Since the profiler modifies the program it can turn
on or off different optimisations, so it's quite possible that there
are other reasons for this behaviour.)
2008/11/10 Aleš Bizjak
Hello,
I'm experiencing some strange behaviour with GHC 6.10 and would like an explanation why.
Here's the problem. With GHC 6.8.[23] memory usage of a program was about 250mb (computing pi to 10^6 decimals). Now I tried recompiling and running with GHC 6.10 and I got more than 1.4gb before I killed it, so naturally I tried profiling but here's the strangeness. When I compile for profiling with -prof -auto-all and run with +RTS -p -RTS memory use is still about the same as before (> 1.4gb), but when I try running with +RTS -hc -RTS memory only reaches about 250mb.
What is the explanation for this behaviour?
I would send a program but it requires HERA, which is not on hackage ...
Here is the output of -s
./Test 100000 +RTS -s 47,467,176 bytes allocated in the heap 18,046,776 bytes copied during GC 9,215,104 bytes maximum residency (6 sample(s)) 711,520 bytes maximum slop 80 MB total memory in use (11 MB lost due to fragmentation)
Generation 0: 84 collections, 0 parallel, 0.01s, 0.01s elapsed Generation 1: 6 collections, 0 parallel, 0.01s, 0.01s elapsed
INIT time 0.00s ( 0.00s elapsed) MUT time 3.66s ( 3.71s elapsed) GC time 0.02s ( 0.02s elapsed) RP time 0.00s ( 0.00s elapsed) PROF time 0.00s ( 0.00s elapsed) EXIT time 0.00s ( 0.00s elapsed) Total time 3.68s ( 3.73s elapsed)
%GC time 0.5% (0.6% elapsed)
Alloc rate 12,982,553 bytes per MUT second
Productivity 99.5% of total user, 97.9% of total elapsed
./Test 100000 +RTS -s -hc 47,471,160 bytes allocated in the heap 18,637,752 bytes copied during GC 13,580,144 bytes maximum residency (37 sample(s)) 810,712 bytes maximum slop 33 MB total memory in use (7 MB lost due to fragmentation)
Generation 0: 85 collections, 0 parallel, 0.02s, 0.02s elapsed Generation 1: 37 collections, 0 parallel, 0.00s, 0.01s elapsed
INIT time 0.00s ( 0.00s elapsed) MUT time 3.67s ( 3.73s elapsed) GC time 0.02s ( 0.03s elapsed) RP time 0.00s ( 0.00s elapsed) PROF time 0.00s ( 0.00s elapsed) EXIT time 0.00s ( 0.00s elapsed) Total time 3.70s ( 3.77s elapsed)
%GC time 0.6% (0.8% elapsed)
Alloc rate 12,941,165 bytes per MUT second
Productivity 99.2% of total user, 97.4% of total elapsed
-- Best regards, Aleš _______________________________________________ Haskell-Cafe mailing list Haskell-Cafe@haskell.org http://www.haskell.org/mailman/listinfo/haskell-cafe

On Tue, 11 Nov 2008 11:54:57 +0100, Thomas Schilling
I think you hit bug http://hackage.haskell.org/trac/ghc/ticket/2747, which is an accounting bug in the garbage collector and goes away when you trigger more garbage collections (which -hc does, I think). Please file a bug report anyway, so we can verify that it is indeed not a new bug. (Since the profiler modifies the program it can turn on or off different optimisations, so it's quite possible that there are other reasons for this behaviour.)
I don't think compiling for profiling has anything to do with it because when compiling with just ghc --make -O2 Test.hs and then running with -hT behaves as it did with -hc and running without -hT eats up memory. I did some further tests and it seems that this is indeed the same bug as above. I will try the fix and if it doesn't fix things for me I will try to put together a minimal case where this happens and file a new bug report. Best regards, Aleš

Compiled with ghc-6.10.1.20081112 it runs approximately as it did with ghc-6.8.3 so the problem seems to be fixed. Thank you for your help.
participants (3)
-
Aleš Bizjak
-
Don Stewart
-
Thomas Schilling