[GHC] #14486: Something is fishy in RTS's "max pause" GC statistic

19 Nov 2017

      #14486: Something is fishy in RTS's "max pause" GC statistic
-------------------------------------+-------------------------------------
           Reporter:  bgamari        |             Owner:  (none)
               Type:  bug            |            Status:  new
           Priority:  normal         |         Milestone:
          Component:  Runtime        |           Version:  8.2.1
  System                             |
           Keywords:                 |  Operating System:  Unknown/Multiple
       Architecture:                 |   Type of failure:  None/Unknown
  Unknown/Multiple                   |
          Test Case:                 |        Blocked By:
           Blocking:                 |   Related Tickets:
Differential Rev(s):                 |         Wiki Page:
-------------------------------------+-------------------------------------
 While looking into a GC issue, I found a peculiar inconsistency between
 the `+RTS -s` output and that from the eventlog.

 The `-s` output is,
 {{{
   13,756,939,024 bytes allocated in the heap
    6,085,406,120 bytes copied during GC
      182,001,080 bytes maximum residency (22 sample(s))
          753,160 bytes maximum slop
              508 MB total memory in use (0 MB lost due to fragmentation)

                                      Tot time (elapsed)  Avg pause  Max
 pause
   Gen  0     28674 colls, 28674 par    5.268s   2.949s     0.0001s
 0.1016s
   Gen  1        22 colls,    21 par    0.004s   0.002s     0.0001s
 0.0005s

   Parallel GC work balance: 79.36% (serial 0%, perfect 100%)

   TASKS: 9 (1 bound, 8 peak workers (8 total), using -N2)

   SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)

   INIT    time    0.007s  (  0.017s elapsed)
   MUT     time    4.353s  (  2.556s elapsed)
   GC      time    5.272s  (  2.951s elapsed)
   EXIT    time    0.004s  (  0.072s elapsed)
   Total   time    9.635s  (  5.596s elapsed)

   Alloc rate    3,160,479,659 bytes per MUT second

   Productivity  45.2% of total user, 47.0% of total elapsed
 }}}

 Note the "Max pause" statistic: gen0 apparently pauses for four orders of
 magnitude more than gen1. This seems rather hard to believe.

 Moreover, if I open the eventlog from the same run in threadscope, I find,

 ||= Generation =||= Collections =||= Par collections =||= Elapsed time
 =||= Avg pause =||= Max pause =||
 || GC Total || 27215 || 25518 || 2.83s || 0.0001s || 0.1016s ||
 || Gen 0 || 25504 || 25504 || 1.55s || 0.0001s || 0.0012s ||
 || Gen 1 || 15 || 14 || 0.99s || 0.0657s || 0.1016s ||

 Hmmmmmmmmm...

-- 
Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14486
GHC http://www.haskell.org/ghc/
The Glasgow Haskell Compiler