Bug in RTS GC stats reporting?

[Nicholas Nethercote]

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