Bug in RTS GC stats reporting?

[Julian Seward (Intl Vendor)]

Problem is (I think) that this is already correct on some platforms,
but not all.  There may be a missing scaling at some point upstream
for some platforms.  Precisely what ghc version is this and what 
platform are you running on?

J

| -----Original Message-----
| From: Nicholas Nethercote [mailto:njn25 at cam.ac.uk] 
| Sent: Thursday, November 01, 2001 4:37 PM
| To: glasgow-haskell-bugs at haskell.org
| Subject: Bug in RTS GC stats reporting?
| 
| 
| Hi,
| 
| I think there's a bug in the reporting of GC stats.  For 
| example, when running the nofib program imaginary/x2n1, I get 
| this output:
| 
|  41,864,696 bytes allocated in the heap
|   1,688,656 bytes copied during GC
|     764,280 bytes maximum residency (2 sample(s))
| 
|         155 collections in generation 0 (  0.14s)
|           2 collections in generation 1 (  0.01s)
| 
|           2 Mb total memory in use
| 
|   INIT  time    0.00s  (  0.00s elapsed)
|   MUT   time    0.26s  (  0.26s elapsed)
|   GC    time    0.15s  (  0.15s elapsed)
|   EXIT  time    0.00s  (  0.00s elapsed)
|   Total time    0.41s  (  0.41s elapsed)
| 
|   %GC time       0.4%  (0.4% elapsed)
| 
|   Alloc rate    161,018,061 bytes per MUT second
| 
|   Productivity  63.4% of total user, 63.4% of total elapsed
| 
| Notice the "%GC time" field: I don't think 0.15s is 0.4% of 0.41s.
| 
| If you look at ghc/rts/Stats.c line 576 (this recent version: 
| $Id: Stats.c,v 1.32 2001/08/14 13:40:09 sewardj Exp $) the 
| offending lines are:
| 
|             fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% 
| elapsed)\n\n",
|                     TICK_TO_DBL(GC_tot_time)*100/time,
|                     TICK_TO_DBL(GCe_tot_time)*100/etime);
| 
| Here GC_tot_time, GCe_tot_time, time, and etime are all of 
| type TICK_TYPE, but only the first two are being converted to 
| seconds.  If you change it to this:
| 
|             fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% 
| elapsed)\n\n",
|                     TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
|                     TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
| 
| The results are much better, viz:
| 
|  41,864,696 bytes allocated in the heap
|   1,688,656 bytes copied during GC
|     764,280 bytes maximum residency (2 sample(s))
| 
|         155 collections in generation 0 (  0.17s)
|           2 collections in generation 1 (  0.01s)
| 
|           2 Mb total memory in use
| 
|   INIT  time    0.00s  (  0.00s elapsed)
|   MUT   time    0.24s  (  0.24s elapsed)
|   GC    time    0.18s  (  0.18s elapsed)
|   EXIT  time    0.00s  (  0.00s elapsed)
|   Total time    0.42s  (  0.42s elapsed)
| 
|   %GC time      42.9%  (42.9% elapsed)
| 
|   Alloc rate    174,436,233 bytes per MUT second
| 
|   Productivity  57.1% of total user, 57.1% of total elapsed
| 
| Unless I'm completely misinterpreting the intended meaning of 
| "%GC time"...
| 
| Tell me if you want more information, although I wouldn't think so.
| --
| Nick Nethercote
| njn25 at cam.ac.uk
| 
| 
| _______________________________________________
| Glasgow-haskell-bugs mailing list 
| Glasgow-haskell-bugs at haskell.org 
| http://www.haskell.org/mailman/listinfo/glasgo| w-haskell-bugs
|