title: Node echo server degrades 10x when stream pipes are used over buffering
body: <p>On node v8.1.4 and v6.11.1</p>
  
  <p>I started out with the following echo server implementation, which I will refer to as <em>pipe.js</em> or <em>pipe</em>.</p>
  
  <pre><code>const http = require('http');
  
  const handler = (req, res) =&gt; req.pipe(res);
  http.createServer(handler).listen(3001);
  </code></pre>
  
  <p>And I benchmarked it with <a href="https://github.com/wg/wrk" rel="noreferrer">wrk</a> and the following
  lua script (shortened for brevity) that will send a small body as a payload.</p>
  
  <pre><code>wrk.method = "POST"
  wrk.body   = string.rep("a", 10)
  </code></pre>
  
  <p>At 2k requests per second and 44ms of average latency, performance is not great.</p>
  
  <p>So I wrote another implementation that uses intermediate buffers until the
  request is finished and then writes those buffers out. I will refer to this as
  <em>buffer.js</em> or <em>buffer</em>.</p>
  
  <pre><code>const http = require('http');
  
  const handler = (req, res) =&gt; {
    let buffs = [];
    req.on('data', (chunk) =&gt; {
      buffs.push(chunk);
    });
    req.on('end', () =&gt; {
      res.write(Buffer.concat(buffs));
      res.end();
    });
  };
  http.createServer(handler).listen(3001);
  </code></pre>
  
  <p>Performance drastically changed with <em>buffer.js</em> servicing 20k requests per
  second at 4ms of average latency.</p>
  
  <p>Visually, the graph below depicts the average number
  of requests serviced over 5 runs and various latency percentiles (p50 is
  median).</p>
  
  <p><a href="https://i.stack.imgur.com/0HBpU.png" rel="noreferrer"><img src="https://i.stack.imgur.com/0HBpU.png" alt="buffer-pipe-comparison"></a></p>
  
  <p>So, <em>buffer</em> is an order of magnitude better in all categories. My question is why?</p>
  
  <p>What follows next are my investigation notes, hopefully they are at least educational.</p>
  
  <h3>Response Behavior</h3>
  
  <p>Both implementations have been crafted so that they will give the same exact
  response as returned by <code>curl -D - --raw</code>. If given a body of 10 d's, both will
  return the exact same response (with modified time, of course):</p>
  
  <pre><code>HTTP/1.1 200 OK
  Date: Thu, 20 Jul 2017 18:33:47 GMT
  Connection: keep-alive
  Transfer-Encoding: chunked
  
  a
  dddddddddd
  0
  </code></pre>
  
  <p>Both output 128 bytes (remember this).</p>
  
  <h3>The Mere Fact of Buffering</h3>
  
  <p>Semantically, the only difference between the two implementations is that
  <em>pipe.js</em> writes data while the request hasn't ended. This might make one
  suspect that there could be multiple <code>data</code> events in <em>buffer.js</em>. This is not
  true.</p>
  
  <pre><code>req.on('data', (chunk) =&gt; {
    console.log(`chunk length: ${chunk.length}`);
    buffs.push(chunk);
  });
  req.on('end', () =&gt; {
    console.log(`buffs length: ${buffs.length}`);
    res.write(Buffer.concat(buffs));
    res.end();
  });
  </code></pre>
  
  <p>Empirically:</p>
  
  <ul>
  <li>Chunk length will always be 10</li>
  <li>Buffers length will always be 1</li>
  </ul>
  
  <p>Since there will only ever be one chunk, what happens if we remove buffering and implement a poor man's pipe:</p>
  
  <pre><code>const http = require('http');
  
  const handler = (req, res) =&gt; {
    req.on('data', (chunk) =&gt; res.write(chunk));
    req.on('end', () =&gt; res.end());
  };
  http.createServer(handler).listen(3001);
  </code></pre>
  
  <p>Turns out, this has as abysmal performance as <em>pipe.js</em>. I find this
  interesting because the same number of <code>res.write</code> and <code>res.end</code> calls are made
  with the same parameters. My best guess so far is that the performance
  differences are due to sending response data after the request data has ended.</p>
  
  <h3>Profiling</h3>
  
  <p>I profiled both application using the <a href="https://nodejs.org/en/docs/guides/simple-profiling/" rel="noreferrer">simple profiling guide
  (--prof)</a>.</p>
  
  <p>I've included only the relevant lines:</p>
  
  <p><em>pipe.js</em></p>
  
  <pre><code> [Summary]:
     ticks  total  nonlib   name
     2043   11.3%   14.1%  JavaScript
    11656   64.7%   80.7%  C++
       77    0.4%    0.5%  GC
     3568   19.8%          Shared libraries
      740    4.1%          Unaccounted
  
   [C++]:
     ticks  total  nonlib   name
     6374   35.4%   44.1%  syscall
     2589   14.4%   17.9%  writev
  </code></pre>
  
  <p><em>buffer.js</em></p>
  
  <pre><code> [Summary]:
     ticks  total  nonlib   name
     2512    9.0%   16.0%  JavaScript
    11989   42.7%   76.2%  C++
      419    1.5%    2.7%  GC
    12319   43.9%          Shared libraries
     1228    4.4%          Unaccounted
  
   [C++]:
     ticks  total  nonlib   name
     8293   29.6%   52.7%  writev
      253    0.9%    1.6%  syscall
  </code></pre>
  
  <p>We see that in both implementations, C++ dominates time; however, the functions
  that dominate are swapped. Syscalls account for nearly half the time for
  <em>pipe</em>, yet only 1% for <em>buffer</em> (forgive my rounding). Next step, which
  syscalls are the culprit?</p>
  
  <h3>Strace Here We Come</h3>
  
  <p>Invoking strace like <code>strace -c node pipe.js</code> will give us a summary of the syscalls. Here are the top syscalls:</p>
  
  <p><em>pipe.js</em></p>
  
  <pre><code>% time     seconds  usecs/call     calls    errors syscall
  ------ ----------- ----------- --------- --------- ----------------
   43.91    0.014974           2      9492           epoll_wait
   25.57    0.008720           0    405693           clock_gettime
   20.09    0.006851           0     61748           writev
    6.11    0.002082           0     61803       106 write
  </code></pre>
  
  <p><em>buffer.js</em></p>
  
  <pre><code>% time     seconds  usecs/call     calls    errors syscall
  ------ ----------- ----------- --------- --------- ----------------
   42.56    0.007379           0    121374           writev
   32.73    0.005674           0    617056           clock_gettime
   12.26    0.002125           0    121579           epoll_ctl
   11.72    0.002032           0    121492           read
    0.62    0.000108           0      1217           epoll_wait
  </code></pre>
  
  <p>The top syscall for <em>pipe</em> (<code>epoll_wait</code>) with 44% of the time is only 0.6% of
  the time for <em>buffer</em> (a 140x increase). While there is a large time
  discrepancy, the number of times <code>epoll_wait</code> is invoked is less lopsided with
  <em>pipe</em> calling <code>epoll_wait</code> ~8x more often. We can derive a couple bits of
  useful information from that statement, such that <em>pipe</em> calls <code>epoll_wait</code>
  constantly and an average, these calls are heavier than the <code>epoll_wait</code> for
  <em>buffer</em>.</p>
  
  <p>For <em>buffer</em>, the top syscall is <code>writev</code>, which is expected considering most
  of the time should be spent writing data to a socket.</p>
  
  <p>Logically the next step is to take a look at these <code>epoll_wait</code> statements
  with regular strace, which showed <em>buffer</em> always contained <code>epoll_wait</code> with
  100 events (representing the hundred connections used with <code>wrk</code>) and <em>pipe</em>
  had less than 100 most of the time.  Like so:</p>
  
  <p><em>pipe.js</em></p>
  
  <pre><code>epoll_wait(5, [.16 snip.], 1024, 0) = 16
  </code></pre>
  
  <p><em>buffer.js</em></p>
  
  <pre><code>epoll_wait(5, [.100 snip.], 1024, 0) = 100
  </code></pre>
  
  <p>Graphically:</p>
  
  <p><a href="https://i.stack.imgur.com/MiYsB.png" rel="noreferrer"><img src="https://i.stack.imgur.com/MiYsB.png" alt="buffer-pipe-events"></a></p>
  
  <p>This explains why there are more <code>epoll_wait</code> in <em>pipe</em>, as <code>epoll_wait</code>
  doesn't service all the connections in one event loop. The <code>epoll_wait</code> for
  zero events makes it look like the event loop is idle! All this doesn't explain
  why <code>epoll_wait</code> takes up more time for <em>pipe</em>, as from the man page it states
  that <code>epoll_wait</code> should return immediately:</p>
  
  <blockquote>
    <p>specifying a timeout equal to zero cause epoll_wait() to return immediately,
    even if no events are available.</p>
  </blockquote>
  
  <p>While the man page says the function returns immediately, can we confirm this? <code>strace -T</code> to the rescue:</p>
  
  <p><a href="https://i.stack.imgur.com/WoOJh.png" rel="noreferrer"><img src="https://i.stack.imgur.com/WoOJh.png" alt="buffer pipe events"></a></p>
  
  <p>Besides supporting that <em>buffer</em> has fewer calls, we can also see that nearly
  all calls took less than 100ns. <em>Pipe</em> has a much more interesting distribution
  showing that while most calls take under 100ns, a non-negligible amount take
  longer and land into the microsecond land.</p>
  
  <p>Strace did find another oddity, and that's with <code>writev</code>. The return value is
  the number of bytes written.</p>
  
  <p><em>pipe.js</em></p>
  
  <pre><code>writev(11, [{"HTTP/1.1 200 OK\r\nDate: Thu, 20 J"..., 109},
    {"\r\n", 2}, {"dddddddddd", 10}, {"\r\n", 2}], 4) = 123
  </code></pre>
  
  <p><em>buffer.js</em></p>
  
  <pre><code>writev(11, [{"HTTP/1.1 200 OK\r\nDate: Thu, 20 J"..., 109},
    {"\r\n", 2}, {"dddddddddd", 10}, {"\r\n", 2}, {"0\r\n\r\n", 5}], 5) = 128
  </code></pre>
  
  <p>Remember when I said that both output 128 bytes? Well, <code>writev</code> returned 123
  bytes for <em>pipe</em> and 128 for <em>buffer</em>. The five bytes difference for <em>pipe</em> is
  reconciled in a subsequent <code>write</code> call for each <code>writev</code>.</p>
  
  <pre><code>write(44, "0\r\n\r\n", 5)
  </code></pre>
  
  <p>And if I'm not mistaken, <code>write</code> syscalls are blocking.</p>
  
  <h3>Conclusion</h3>
  
  <p>If I have to make an educated guess, I would say that piping when the request
  is not finished causes <code>write</code> calls. These blocking calls significantly reduce
  the throughput partially through more frequent <code>epoll_wait</code> statements. Why
  <code>write</code> is called instead of a single <code>writev</code> that is seen in <em>buffer</em> is
  beyond me. Can someone explain why everything I saw is happening?</p>
  
  <p>The kicker? In the <a href="https://nodejs.org/en/docs/guides/anatomy-of-an-http-transaction/#echo-server-example" rel="noreferrer">official Node.js
  guide</a>
  you can see how the guide starts with the buffer implementation and then moves
  to pipe! If the pipe implementation is in the official guide there shouldn't be
  such a performance hit, right?</p>
  
  <p>Aside: Real world performance implications of this question should be minimal, as the question is quite contrived especially in regards to the functionality and the body side, though this doesn't mean this is any less of a useful question. Hypothetically, an answer could look like "Node.js uses <code>write</code> to allow for better performance under x situations (where x is a more real world use case)" </p>
  
  <hr>
  
  <p><sup>Disclosure: question copied and slightly modified from <a href="https://nbsoftsolutions.com/blog/investigation-into-the-inefficiencies-of-nodejs-http-streams" rel="noreferrer">my blog post</a> in the hopes this is a better avenue for getting this question answered</sup></p>
  
  <hr>
  
  <h3>July 31st 2017 EDIT</h3>
  
  <p>My initial hypothesis that writing the echoed body after the request stream has finished increases performance has been disproved by @robertklep with his <em>readable.js</em> (or <em>readable</em>) implementation:</p>
  
  <pre><code>const http   = require('http');
  const BUFSIZ = 2048;
  
  const handler = (req, res) =&gt; {
    req.on('readable', _ =&gt; {
      let chunk;
      while (null !== (chunk = req.read(BUFSIZ))) {
        res.write(chunk);
      }
    });
    req.on('end', () =&gt; {
      res.end();
    });
  };
  http.createServer(handler).listen(3001);
  </code></pre>
  
  <p><em>Readable</em> performed at the same level as <em>buffer</em> while writing data before the <code>end</code> event. If anything this makes me more confused because the only difference between <em>readable</em> and my initial poor man's pipe implementation is the difference between the <code>data</code> and <code>readable</code> event and yet that caused a 10x performance increase. But we know that the <code>data</code> event isn't inherently slow because we used it in our <em>buffer</em> code.</p>
  
  <p>For the curious, strace on <em>readable</em> reported <code>writev</code> outputs all 128 bytes output like <em>buffer</em></p>
  
  <p>This is perplexing!</p>