[GHC] #9809: Overwhelming the TimerManager

17 Nov 2014

      #9809: Overwhelming the TimerManager
-------------------------------------+-------------------------------------
       Reporter:  fryguybob          |                   Owner:  simonmar
           Type:  bug                |                  Status:  new
       Priority:  normal             |               Milestone:
      Component:  Runtime System     |                 Version:  7.9
       Keywords:                     |        Operating System:  Linux
   Architecture:  Unknown/Multiple   |         Type of failure:  Runtime
     Difficulty:  Unknown            |  performance bug
     Blocked By:                     |               Test Case:
Related Tickets:                     |                Blocking:
                                     |  Differential Revisions:
-------------------------------------+-------------------------------------
 I was talking on IRC with davean about an issue that potentially could
 have been related to STM (I don't think it is at all after investigating)
 and I reduced the issue to the following program:

 {{{#!hs
 -- Main.hs
 module Main where

 import Control.Monad
 import Control.Concurrent
 import Control.Concurrent.STM
 import System.Environment

 main :: IO ()
 main = do
     as <- getArgs
     case as of
         ["-f"]  -> replicateM_ 100000 . void . forkIO . void $
 registerDelay 10
         _       -> replicateM_ 100000 .                 void $
 registerDelay 10

     threadDelay 1000
 }}}

 This ends up registering a lot of events with the TimerManager.  With the
 "-f" flag it does so from many threads and when run that way it appears to
 eventually overwhelm the TimerManager and causing over 350 MB total memory
 in use.

 {{{
 $ ghc --version
 The Glorious Glasgow Haskell Compilation System, version 7.9.20141115
 $ ghc -O2 -threaded -debug Main.hs -o Main-head
 ...
 $ ./Main-head -f +RTS -s
    3,566,966,936 bytes allocated in the heap
    4,200,021,784 bytes copied during GC
      118,273,720 bytes maximum residency (96 sample(s))
       12,649,480 bytes maximum slop
              354 MB total memory in use (0 MB lost due to fragmentation)

                                      Tot time (elapsed)  Avg pause  Max
 pause
   Gen  0      6350 colls,     0 par    2.430s   2.434s     0.0004s
 0.0073s
   Gen  1        96 colls,     0 par    7.438s   7.441s     0.0775s
 0.2526s

   TASKS: 4 (1 bound, 3 peak workers (3 total), using -N1)

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

   INIT    time    0.002s  (  0.002s elapsed)
   MUT     time    0.461s  (  0.460s elapsed)
   GC      time    9.869s  (  9.875s elapsed)
   EXIT    time    0.003s  (  0.003s elapsed)
   Total   time   10.336s  ( 10.340s elapsed)

   Alloc rate    7,741,472,461 bytes per MUT second

   Productivity   4.5% of total user, 4.5% of total elapsed

 gc_alloc_block_sync: 0
 whitehole_spin: 0
 gen[0].sync: 0
 gen[1].sync: 0
 }}}

 Running without forking many threads and the total memory in use stays low
 (3 MB).

 {{{
      154,305,648 bytes allocated in the heap
       16,922,272 bytes copied during GC
        1,378,608 bytes maximum residency (3 sample(s))
           28,520 bytes maximum slop
                3 MB total memory in use (0 MB lost due to fragmentation)

                                      Tot time (elapsed)  Avg pause  Max
 pause
   Gen  0       298 colls,     0 par    0.056s   0.056s     0.0002s
 0.0015s
   Gen  1         3 colls,     0 par    0.005s   0.005s     0.0017s
 0.0047s

   TASKS: 4 (1 bound, 3 peak workers (3 total), using -N1)

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

   INIT    time    0.001s  (  0.001s elapsed)
   MUT     time    0.148s  (  0.148s elapsed)
   GC      time    0.061s  (  0.061s elapsed)
   EXIT    time    0.000s  (  0.000s elapsed)
   Total   time    0.211s  (  0.210s elapsed)

   Alloc rate    1,042,557,595 bytes per MUT second

   Productivity  70.8% of total user, 71.2% of total elapsed

 gc_alloc_block_sync: 0
 whitehole_spin: 0
 gen[0].sync: 0
 gen[1].sync: 0

 }}}

 Using 7.6.3, things don't get out of hand, also with 3 MB total memory
 use.

 {{{
 $ ./Main-7.6.3 -f +RTS -s
      213,519,392 bytes allocated in the heap
      116,111,712 bytes copied during GC
          505,080 bytes maximum residency (11 sample(s))
          113,032 bytes maximum slop
                3 MB total memory in use (0 MB lost due to fragmentation)

                                     Tot time (elapsed)  Avg pause  Max
 pause
   Gen  0       403 colls,     0 par    0.33s    0.33s     0.0008s
 0.0028s
   Gen  1        11 colls,     0 par    0.01s    0.01s     0.0011s
 0.0019s

   TASKS: 3 (1 bound, 2 peak workers (2 total), using -N1)

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

   INIT    time    0.00s  (  0.00s elapsed)
   MUT     time    1.99s  (  1.50s elapsed)
   GC      time    0.34s  (  0.34s elapsed)
   EXIT    time    0.00s  (  0.00s elapsed)
   Total   time    2.33s  (  1.84s elapsed)

   Alloc rate    107,426,859 bytes per MUT second

   Productivity  85.5% of total user, 108.1% of total elapsed

 gc_alloc_block_sync: 0
 whitehole_spin: 0
 gen[0].sync: 0
 gen[1].sync: 0
 }}}

 I looked for causes and eliminated any `STM` interactions causing problems
 (`STM` shows up in the `Unique` values and in creating a `TVar` for the
 registered delay) but did discover that the `emTimeouts` queue gets very
 large at some point when executing with "-f".  If I print the size of
 `expired` on this line:

 https://github.com/ghc/ghc/blob/021b7978d14799bae779907faf7490cfd21b3f46/lib...

 I end up seeing somewhere from 4 to 20 events for a while then eventually
 it jumps up to 80000 or so.  Perhaps davean can chime in about the
 particular use case that he has that I reduced to this simple program for
 a more real world use.

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