Haskell pauses (seemingly) randomly while generating Fibonacci Numbers

Question

I was playing with GHCI, and came across this little (to me) oddity.

I tried this:

λ> let fibs = 1 : 1 : zipWith (+) fibs (tail fibs)
λ> fibs

Just to see how quick fibs grow and just to play around a bit. I think it's cool how Haskell displays each fib as it is calculated, so it's a nice demonstration of laziness.

However, as I saw the wall of numbers zoom by, there were momentary skips where the list generation would completely stop. Normally I would just think that it was computing the next number, but they seemed to happen randomly - and calculating the next fib number is always just one addition, so should never be slow. On one number, ghci paused for almost a second.

What's causing these momentary slowdowns? Why would they happen only on specific numbers and not others? Shouldn't this always be fast?

Answer 1

This is almost certainly garbage collection (GC), likely of a higher generation (i.e. a major GC). These can cause significant pauses in cases where lots of long-lived garbage is being created.

If you wanted to see this happening, you can make a quick executable and check:

Start with tmp.hs:

module Main where

fibs = 1:1:zipWith (+) fibs (tail fibs)

main = print $ fibs !! 100000

Compile with ghc -rtsopts tmp.hs

Run with ./tmp +RTS -s

     454,847,088 bytes allocated in the heap
     230,044,816 bytes copied during GC
       4,291,856 bytes maximum residency (226 sample(s))
      18,080,904 bytes maximum slop
              56 MB total memory in use (0 MB lost due to fragmentation)

                                    Tot time (elapsed)  Avg pause  Max pause
  Gen  0       676 colls,     0 par    0.07s    0.07s     0.0001s    0.0023s
  Gen  1       226 colls,     0 par    0.27s    0.28s     0.0012s    0.0084s

  INIT    time    0.00s  (  0.00s elapsed)
  MUT     time    0.14s  (  0.14s elapsed)
  GC      time    0.34s  (  0.35s elapsed)
  EXIT    time    0.00s  (  0.00s elapsed)
  Total   time    0.48s  (  0.49s elapsed)

  %GC     time      71.0%  (71.6% elapsed)

  Alloc rate    3,303,664,644 bytes per MUT second

  Productivity  28.9% of total user, 28.8% of total elapsed

This signifies 676 minor garbage collections and 226 major, with 2nd generation collections taking ~12x more time to complete than minor. Note that this was only the hundred thousandth number, so pauses may be longer at higher numbers. Also note that GHCI is an interpreter, so there will be associated slowdowns.

As an aside, I did try compiling and running this example with optimization turned on. There was no appreciable difference in time, and the memory/GC characteristics were almost identical.

Answer 2

As commented by Jan Dvorak above, it may be the GC kicking in. You can play with some runtime options (see section 4.16.3) to see if changing them affects this behavior.

In particular you can output information about GC occurrences to know if that's the issue:

-t[file] , -s[file] , -S[file] , --machine-readable

These options produce runtime-system statistics, such as the amount of time spent executing the program and in the garbage collector, the amount of memory allocated, the maximum size of the heap, and so on. The three variants give different levels of detail: -t produces a single line of output in the same format as GHC's -Rghc-timing option, -s produces a more detailed summary at the end of the program, and -S additionally produces information about each and every garbage collection.