title: Code becomes slower as more boxed arrays are allocated
body: <p><strong>Edit:</strong> <em>It turns out that things generally (not just array/ref operations) slow down the more arrays have been created, so I guess this might just be measuring increased GC times and might not be as strange as I thought. But I'd really like to know (and learn how to find out) what's happening here though, and if there's some way to mitigate this effect in code that creates lots of smallish arrays. Original question follows.</em></p>
  
  <hr>
  
  <p>In investigating some weird benchmarking results in a library, I stumbled upon some behavior I don't understand, though it might be really obvious. It seems that the time taken for many operations (creating a new <code>MutableArray</code>, reading or modifying an <code>IORef</code>) increases in proportion to the number of arrays in memory.</p>
  
  <p>Here's the first example:</p>
  
  <pre><code>module Main
      where 
  
  import Control.Monad
  import qualified Data.Primitive as P
  import Control.Concurrent
  import Data.IORef
  import Criterion.Main
  import Control.Monad.Primitive(PrimState)
  
  main = do 
    let n = 100000
    allTheArrays &lt;- newIORef []
    defaultMain $
      [ bench "array creation" $ do
           newArr &lt;- P.newArray 64 () :: IO (P.MutableArray (PrimState IO) ())
           atomicModifyIORef'  allTheArrays (\l-&gt; (newArr:l,()))
      ]
  </code></pre>
  
  <p>We're creating a new array and adding it to a stack. As criterion does more samples and the stack grows, array creation takes more time, and this seems to grow linearly and regularly:</p>
  
  <p><img src="https://i.stack.imgur.com/Pa8BM.png" alt="slowdown"></p>
  
  <p>Even more odd, <code>IORef</code> reads and writes are affected, and we can see the <code>atomicModifyIORef'</code> getting faster presumably as more arrays are GC'd.</p>
  
  <pre><code>main = do 
    let n = 1000000
    arrs &lt;- replicateM (n) $ (P.newArray 64 () :: IO (P.MutableArray (PrimState IO) ()))
    -- print $ length arrs -- THIS WORKS TO MAKE THINGS FASTER
    arrsRef &lt;- newIORef arrs
    defaultMain $
      [ bench "atomic-mods of IORef" $
      -- nfIO $           -- OR THIS ALSO WORKS
          replicateM 1000 $
            atomicModifyIORef' arrsRef (\(a:as)-&gt; (as,()))
      ]
  </code></pre>
  
  <p><img src="https://i.stack.imgur.com/pkPc0.png" alt="enter image description here"></p>
  
  <p>Either of the two lines that are commented get rid of this behavior but I'm not sure why (maybe after we force the spine of the list, the elements can actually by collected).</p>
  
  <h2>Questions</h2>
  
  <ul>
  <li>What's happening here? </li>
  <li>Is it expected behavior? </li>
  <li>Is there a way I can avoid this slowdown?</li>
  </ul>
  
  <p><strong>Edit</strong>: I assume this has something to do with GC taking longer, but I'd like to understand more precisely what's happening, especially in the first benchmark.</p>
  
  <hr>
  
  <h3>Bonus example</h3>
  
  <p>Finally, here's a simple test program that can be used to pre-allocate some number of arrays and time a bunch of <code>atomicModifyIORef</code>s. This seems to exhibit the slow IORef behavior.</p>
  
  <pre><code>import Control.Monad
  import System.Environment
  
  import qualified Data.Primitive as P
  import Control.Concurrent
  import Control.Concurrent.Chan
  import Control.Concurrent.MVar
  import Data.IORef
  import Criterion.Main
  import Control.Exception(evaluate)
  import Control.Monad.Primitive(PrimState)
  
  import qualified Data.Array.IO as IO
  import qualified Data.Vector.Mutable as V
  
  import System.CPUTime
  import System.Mem(performGC)
  import System.Environment
  main :: IO ()
  main = do
    [n] &lt;- fmap (map read) getArgs
    arrs &lt;- replicateM (n) $ (P.newArray 64 () :: IO (P.MutableArray (PrimState IO) ()))
    arrsRef &lt;- newIORef arrs
  
    t0 &lt;- getCPUTimeDouble
  
    cnt &lt;- newIORef (0::Int)
    replicateM_ 1000000 $
      (atomicModifyIORef' cnt (\n-&gt; (n+1,())) &gt;&gt;= evaluate)
  
    t1 &lt;- getCPUTimeDouble
  
    -- make sure these stick around
    readIORef cnt &gt;&gt;= print
    readIORef arrsRef &gt;&gt;= (flip P.readArray 0 . head) &gt;&gt;= print
  
    putStrLn "The time:"
    print (t1 - t0)
  </code></pre>
  
  <p>A heap profile with <code>-hy</code> shows mostly <code>MUT_ARR_PTRS_CLEAN</code>, which I don't completely understand.</p>
  
  <p>If you want to reproduce, here is the cabal file I've been using</p>
  
  <pre><code>name:                small-concurrency-benchmarks
  version:             0.1.0.0       
  build-type:          Simple
  cabal-version:       &gt;=1.10
  
  executable small-concurrency-benchmarks
    main-is:             Main.hs 
    build-depends:       base &gt;=4.6
                       , criterion
                       , primitive
  
    default-language:    Haskell2010
    ghc-options: -O2  -rtsopts
  </code></pre>
  
  <p><strong>Edit</strong>: Here's another test program, that can be used to compare slowdown with heaps of the same size of arrays vs <code>[Integer]</code>. It takes some trial and error adjusting <code>n</code> and observing profiling to get comparable runs.</p>
  
  <pre><code>main4 :: IO ()
  main4= do
    [n] &lt;- fmap (map read) getArgs
    let ns = [(1::Integer).. n]
    arrsRef &lt;- newIORef ns
    print $ length ns
  
    t0 &lt;- getCPUTimeDouble
    mapM (evaluate . sum) (tails [1.. 10000])
    t1 &lt;- getCPUTimeDouble
  
    readIORef arrsRef &gt;&gt;= (print . sum)
  
    print (t1 - t0)
  </code></pre>
  
  <p>Interestingly, when I test this I find that the same heap size-worth of arrays affects performance to a greater degree than <code>[Integer]</code>. E.g.</p>
  
  <pre><code>         Baseline  20M   200M
  Lists:   0.7       1.0    4.4
  Arrays:  0.7       2.6   20.4
  </code></pre>
  
  <h1>Conclusions (WIP)</h1>
  
  <ol>
  <li><p>This is most likely due to GC behavior</p></li>
  <li><p>But mutable unboxed arrays seem to lead to more sever slowdowns (see above). Setting <code>+RTS -A200M</code> brings performance of the array garbage version in line with the list version, supporting that this has to do with GC.</p></li>
  <li><p>The slowdown is proportional to the number of arrays allocated, not the number of total cells in the array. Here is a set of runs showing, for a similar test to <code>main4</code>, the effects of number of arrays allocated both on the time taken to allocate, and a completely unrelated "payload". This is for 16777216 total cells (divided amongst however many arrays):</p>
  
  <pre><code>   Array size   Array create time  Time for "payload":
     8            3.164           14.264
     16           1.532           9.008
     32           1.208           6.668
     64           0.644           3.78
     128          0.528           2.052
     256          0.444           3.08
     512          0.336           4.648
     1024         0.356           0.652
  </code></pre>
  
  <p>And running this same test on <code>16777216*4</code> cells, shows basically identical payload times as above, only shifted down two places.</p></li>
  <li><p>From what I understand about how GHC works, and looking at (3), I think this overhead might be simply from having pointers to all these arrays sticking around in the <a href="https://ghc.haskell.org/trac/ghc/wiki/Commentary/Rts/Storage/GC/RememberedSets#Arrays:MUT_ARR_PTRS" rel="nofollow noreferrer"><em>remembered set</em></a> (see also: <a href="http://www.haskell.org/pipermail/glasgow-haskell-users/2012-March/022142.html" rel="nofollow noreferrer">here</a>), and whatever overhead that causes for the GC.</p></li>
  </ol>