title: Where is a delay in an HTTP POST coming from?
body: <p>I am developing a web service on Ubuntu 14.04 in C++ using cpp-netlib in asynchronous mode. The service needs to respond to data sent over HTTP POST in the message body. I am observing poor performance when receiving input larger than 1K, and I want to fix that.</p>
  
  <p>If the data is relatively small, less than 1K, the server receives the data almost instantly. If the data is more than 1K, there is a roughly one second delay after the asynchronous read callback function is first invoked before the first chunk of actual data is presented to the callback. After the initial delay, the subsequent chunks arrive almost instantly.</p>
  
  <p>How can I eliminate this delay? Is it an artifact of using curl to post test data? How can I easily test the performance of curl for posting data?</p>
  
  <p>You can find minimal <a href="https://github.com/randallecook/asyncserver">source code</a> demonstrating the problem on github. Here's the command I use to post data to the server:</p>
  
  <pre><code>rcook$ curl -d @AsyncDaemon.h http://localhost:8787/foo
  </code></pre>
  
  <p>Here's an example of its output (annotated):</p>
  
  <pre><code>rcook$ ./async_daemon 
  1431387368.321863: AsyncDaemon constructor
  1431387368.322446: receive thread beginning
  
  *** It's waiting for a connection here.
  
  1431387371.536191: begin transaction 0 on thread 24050
  1431387371.536237: transaction 0 constructor
  1431387371.536273: received 1206 byte request for /foo from 127.0.0.1:49402
  1431387371.536312: invoked asynchronous read
  1431387371.536321: end transaction handler
  1431387371.536335: begin asynchronous read callback on thread 24050
  1431387371.536348: read 0 bytes
  1431387371.536386: invoked asynchronous read
  1431387371.536394: end asynchronous read callback
  
  *** The asynchronous read callback is invoked quickly, but gets no data.
  *** There is then a pause of just over one second before the asynchronous
  *** read callback is invoked again.
  
  1431387372.537203: begin asynchronous read callback on thread 24050
  1431387372.537253: read 1024 bytes
  1431387372.537307: invoked asynchronous read
  1431387372.537317: end asynchronous read callback
  
  *** There is no significant delay when reading the next chunk.
  
  1431387372.537429: begin asynchronous read callback on thread 24050
  1431387372.537469: read 182 bytes
  1431387372.537478: finished reading the body
  1431387372.537746: wrote response
  1431387372.537763: transaction 0 destructor
  1431387372.537772: end asynchronous read callback
  
  *** The server is then killed with a keyboard interrupt.
  
  ^C1431387375.382186: terminating with signal 2
  1431387375.382231: initiating shutdown
  1431387375.382241: stopping server
  1431387375.382363: server run finished
  1431387375.382423: receive thread ending
  1431387375.382522: AsyncDaemon destructor
  </code></pre>
  
  <p>As you can see, after the asynchronous read callback is invoked for the first time (and receives zero bytes of data, BTW), it requests another chunk of input. At this point there is a pause of just over one second before that input arrives, from 1431387371.536394 to 1431387372.537203 in this example. What's going on during that time? How can I eliminate that delay?</p>
  
  <p>I have done some research online, and run several experiments (synchronous vs. asynchronous mode with cpp-netlib (no effect), curl vs. libcurl (no effect)), but have not been able to find an answer.</p>
  
  <h2>Update: TCP Dump</h2>
  
  <p>Upon jxh's suggestion, I ran a tcp dump during a sample transaction:</p>
  
  <pre><code>00:28:01.304446 IP6 localhost.52265 &gt; localhost.8787: Flags [S], seq 3956487146, win 43690, options [mss 65476,sackOK,TS val 395479802 ecr 0,nop,wscale 7], length 0
  00:28:01.304461 IP6 localhost.8787 &gt; localhost.52265: Flags [R.], seq 0, ack 3956487147, win 0, length 0
  00:28:01.305014 IP localhost.49421 &gt; localhost.8787: Flags [S], seq 1668603425, win 43690, options [mss 65495,sackOK,TS val 395479803 ecr 0,nop,wscale 7], length 0
  00:28:01.305039 IP localhost.8787 &gt; localhost.49421: Flags [S.], seq 4010788604, ack 1668603426, win 43690, options [mss 65495,sackOK,TS val 395479803 ecr 395479803,nop,wscale 7], length 0
  00:28:01.305079 IP localhost.49421 &gt; localhost.8787: Flags [.], ack 1, win 342, options [nop,nop,TS val 395479803 ecr 395479803], length 0
  00:28:01.305185 IP localhost.49421 &gt; localhost.8787: Flags [P.], seq 1:176, ack 1, win 342, options [nop,nop,TS val 395479803 ecr 395479803], length 175
  00:28:01.305210 IP localhost.8787 &gt; localhost.49421: Flags [.], ack 176, win 350, options [nop,nop,TS val 395479803 ecr 395479803], length 0
  00:28:02.306555 IP localhost.49421 &gt; localhost.8787: Flags [P.], seq 176:1382, ack 1, win 342, options [nop,nop,TS val 395480053 ecr 395479803], length 1206
  00:28:02.306620 IP localhost.8787 &gt; localhost.49421: Flags [.], ack 1382, win 1373, options [nop,nop,TS val 395480053 ecr 395480053], length 0
  00:28:02.307223 IP localhost.8787 &gt; localhost.49421: Flags [P.], seq 1:52, ack 1382, win 1373, options [nop,nop,TS val 395480053 ecr 395480053], length 51
  00:28:02.307270 IP localhost.49421 &gt; localhost.8787: Flags [.], ack 52, win 342, options [nop,nop,TS val 395480053 ecr 395480053], length 0
  00:28:02.307494 IP localhost.8787 &gt; localhost.49421: Flags [P.], seq 52:66, ack 1382, win 1373, options [nop,nop,TS val 395480053 ecr 395480053], length 14
  00:28:02.307522 IP localhost.49421 &gt; localhost.8787: Flags [.], ack 66, win 342, options [nop,nop,TS val 395480053 ecr 395480053], length 0
  00:28:02.307765 IP localhost.8787 &gt; localhost.49421: Flags [F.], seq 66, ack 1382, win 1373, options [nop,nop,TS val 395480053 ecr 395480053], length 0
  00:28:02.307867 IP localhost.49421 &gt; localhost.8787: Flags [F.], seq 1382, ack 67, win 342, options [nop,nop,TS val 395480053 ecr 395480053], length 0
  00:28:02.307917 IP localhost.8787 &gt; localhost.49421: Flags [.], ack 1383, win 1373, options [nop,nop,TS val 395480053 ecr 395480053], length 0
  </code></pre>
  
  <p>I'm not very experienced with tcpdump, but it looks like 175 bytes flow to the server (HTTP headers?), then after a delay of a little over one second, 1206 bytes flow to the server, followed by a 51 byte chunk with minimal delay, followed by the server response.</p>
  
  <p>This tells me that the delay is being introduced on the client side, likely in curl. Does anyone know why?</p>