[GHC] #16034: Quadratic GC slowdown using RTS debug

11 Dec 2018

      #16034: Quadratic GC slowdown using RTS debug
-------------------------------------+-------------------------------------
           Reporter:  remyo          |             Owner:  (none)
               Type:  bug            |            Status:  new
           Priority:  normal         |         Milestone:
          Component:  Runtime        |           Version:  8.6.3
  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:
-------------------------------------+-------------------------------------
 Hello,

 Under some conditions of heavy heap usage, I seem to experience a
 quadratic slowdown due to GC using the debugging RTS only (for example, in
 the context of ticky profiling).

 I have been able to reproduce it using the following program (depending on
 the aeson library):
 {{{#!hs
 import Data.Aeson (eitherDecode, Value)
 import qualified Data.ByteString.Lazy as BL
 import Data.Maybe (catMaybes)
 import System.Directory (listDirectory)
 import System.FilePath ( () )

 main :: IO()
 main = do
     let dir = "data"
     files <- listDirectory dir
     values <- catMaybes <$> mapM (readF dir) files
     print $ length values

 readF :: FilePath -> FilePath -> IO (Maybe Value)
 readF dir fp = do
     print (dir  fp)
     blob <- BL.readFile (dir  fp)
     case eitherDecode blob of
         Left _ -> return Nothing
         Right v -> return $ Just $! v
 }}}

 Here data is a directory filled with (identical) JSON files. See the
 attached Python script for the proposed dataset.

 {{{
 $ ghc -O -dynamic -o main Main.hs
 $ ./main +RTS -s
 ...
   18,583,045,600 bytes allocated in the heap
    6,334,338,280 bytes copied during GC
      975,763,072 bytes maximum residency (14 sample(s))
        6,986,112 bytes maximum slop
              930 MB total memory in use (0 MB lost due to fragmentation)

                                      Tot time (elapsed)  Avg pause  Max
 pause
   Gen  0     17727 colls,     0 par    2.596s   2.597s     0.0001s
 0.0006s
   Gen  1        14 colls,     0 par    2.422s   2.422s     0.1730s
 0.7947s

   INIT    time    0.000s  (  0.000s elapsed)
   MUT     time    3.349s  (  3.351s elapsed)
   GC      time    5.019s  (  5.020s elapsed)
   EXIT    time    0.000s  (  0.000s elapsed)
   Total   time    8.368s  (  8.371s elapsed)

   %GC     time       0.0%  (0.0% elapsed)

   Alloc rate    5,548,968,539 bytes per MUT second

   Productivity  40.0% of total user, 40.0% of total elapsed
 }}}

 {{{
 $ ghc -O -dynamic -debug -o main.debug Main.hs
 $ ./main +RTS -s
 ...
   18,583,045,600 bytes allocated in the heap
    6,334,332,424 bytes copied during GC
      975,763,072 bytes maximum residency (14 sample(s))
        6,986,112 bytes maximum slop
              930 MB total memory in use (0 MB lost due to fragmentation)

                                      Tot time (elapsed)  Avg pause  Max
 pause
   Gen  0     17727 colls,     0 par   172.941s  172.959s     0.0098s
 0.0459s
   Gen  1        14 colls,     0 par    9.532s   9.532s     0.6808s
 3.2061s

   INIT    time    0.000s  (  0.000s elapsed)
   MUT     time    5.020s  (  5.017s elapsed)
   GC      time  182.473s  (182.491s elapsed)
   EXIT    time    0.000s  (  0.000s elapsed)
   Total   time  187.492s  (187.508s elapsed)

   %GC     time       0.0%  (0.0% elapsed)

   Alloc rate    3,701,999,827 bytes per MUT second

   Productivity   2.7% of total user, 2.7% of total elapsed
 }}}

 In debug mode, the runtime is almost quadratic:
 {{{
 Nb of files   Duration (non-debug)  Duration (debug)
  100            0.8s                   2.8s
  200            1.6s                   8.8s
  400            3.2s                  27.6s
 1000            8.2s                 168.9s
 }}}

 The problem can be seen with either GHC 8.6.3 (here on Archlinux, with
 aeson 1.4.2.0) but was also observed using GHC 8.4.4, with static
 binaries, using "stack". I was able to reproduce with both threaded and
 non-threaded mode.

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