title: A change in my library made it much slower. Profiling isn't helping me. What might be the reason for the slow-down?
body: <h1>My Problem, Briefly</h1>
  
  <p>I made a change to my library, now it's much slower but I can't figure out where it spends all that additional time. Profiling reports are not helping. Please help me figure out what the reason might be.</p>
  
  <h1>Some Context</h1>
  
  <p>I made a Redis client-library called <a href="http://hackage.haskell.org/package/hedis" rel="noreferrer">Hedis</a> and have a benchmark program for it. Now, I made some internal changes to the library, to clean up the architecture. This caused performance (in Redis-requests per second, as measured by said benchmark) to drop by a factor of about 2.5.</p>
  
  <p>The benchmark opens 50 network connections to a Redis server on localhost. The connections are handled differently between the two versions:</p>
  
  <ul>
  <li><strong>The fast version</strong> uses one thread per connection (thus, the benchmark has 50 threads running concurrently). It reads from the socket
  handle by using <code>unsafeInterleaveIO</code> (I describe my approach in broad
  strokes in a <a href="http://informatikr.com/2012/redis-pipelining.html" rel="noreferrer">blog post here</a>). I was a bit unhappy
  with the architecture, hence I changed things to</li>
  <li><strong>the slow version</strong> which uses three threads per connection. They communicate via two <code>Chan</code>s (150 threads running in the benchmark).</li>
  </ul>
  
  <p>Some more information that might be relevant:</p>
  
  <ul>
  <li>Compiled with GHC 7.2.2.</li>
  <li>The benchmark program is unchanged between the two versions, so network
  traffic is the same.</li>
  <li>Both versions use the single-threaded runtime (compiled <em>without</em>
  <code>-threaded</code>).</li>
  <li>All threads are created by calling <code>forkIO</code>. <em>Not</em> the more expensive
  <code>forkOS</code>.</li>
  </ul>
  
  <h1>Profiling Results</h1>
  
  <p>Profiling does not give me a clear reason for the drop in performance. According to the profiling report, both versions spend more than 99% of their time in <code>System.IO.hFlush</code> and <code>Data.ByteString.hGetSome</code>. The number of times <code>hFlush</code> and <code>hGetSome</code> are called is the same in both versions. Since network traffic is also the same in both cases, these functions can't be the reason for the slow-down.</p>
  
  <p>The only significant difference I can measure between the two versions is what <code>time</code> (the Unix utility) tells me: the slow version (with three times as many threads) spends significantly more time in "sys" instead of "user", compared to the fast version. The GHC <code>+RTS -s</code> flag reports this as reduced productivity.</p>
  
  <p>Here are the program outputs for both versions with the <code>+RTS -s</code> flag:</p>
  
  <h2>Benchmark of the Fast Version</h2>
  
  <pre><code>$ time ./dist/build/hedis-benchmark/hedis-benchmark +RTS -s -p
  ping                   33305.29 Req/s
  get                    25802.92 Req/s
  mget                   18215.94 Req/s
  ping (pipelined)      268994.36 Req/s
     5,118,163,904 bytes allocated in the heap
       185,075,608 bytes copied during GC
         4,084,384 bytes maximum residency (39 sample(s))
           916,544 bytes maximum slop
                10 MB total memory in use (0 MB lost due to fragmentation)
  
                                      Tot time (elapsed)  Avg pause  Max pause
    Gen  0      7416 colls,     0 par    0.38s    0.40s     0.0001s    0.0003s
    Gen  1        39 colls,     0 par    0.03s    0.03s     0.0007s    0.0009s
  
    INIT    time    0.00s  (  0.00s elapsed)
    MUT     time    7.93s  ( 12.34s elapsed)
    GC      time    0.41s  (  0.43s elapsed)
    RP      time    0.00s  (  0.00s elapsed)
    PROF    time    0.00s  (  0.00s elapsed)
    EXIT    time    0.00s  (  0.00s elapsed)
    Total   time    8.33s  ( 12.76s elapsed)
  
    %GC     time       4.9%  (3.3% elapsed)
  
    Alloc rate    645,587,554 bytes per MUT second
  
    Productivity  95.1% of total user, 62.1% of total elapsed
  
  
  real    0m12.772s
  user    0m8.334s
  sys     0m4.424s
  </code></pre>
  
  <h2>Benchmark of the Slow Version</h2>
  
  <pre><code>$ time ./dist/build/hedis-benchmark/hedis-benchmark +RTS -s -p
  ping                   11457.83 Req/s
  get                    11169.64 Req/s
  mget                    8446.96 Req/s
  ping (pipelined)      130114.31 Req/s
     6,053,055,680 bytes allocated in the heap
     1,184,574,408 bytes copied during GC
         9,750,264 bytes maximum residency (198 sample(s))
         2,872,280 bytes maximum slop
                26 MB total memory in use (0 MB lost due to fragmentation)
  
                                      Tot time (elapsed)  Avg pause  Max pause
    Gen  0      9105 colls,     0 par    2.11s    2.14s     0.0002s    0.0006s
    Gen  1       198 colls,     0 par    0.23s    0.24s     0.0012s    0.0093s
  
    INIT    time    0.00s  (  0.00s elapsed)
    MUT     time   10.99s  ( 27.92s elapsed)
    GC      time    2.34s  (  2.38s elapsed)
    RP      time    0.00s  (  0.00s elapsed)
    PROF    time    0.00s  (  0.00s elapsed)
    EXIT    time    0.00s  (  0.00s elapsed)
    Total   time   13.33s  ( 30.30s elapsed)
  
    %GC     time      17.6%  (7.8% elapsed)
  
    Alloc rate    550,656,490 bytes per MUT second
  
    Productivity  82.4% of total user, 36.3% of total elapsed
  
  
  real    0m30.305s
  user    0m13.333s
  sys     0m16.964s
  </code></pre>
  
  <p>Do you have any ideas or hints where that additional time might come from?</p>