Tcp delayed ack in nodejs with express

Question

I'm doing a stress test for nginx and I use nodejs backends. I found a delay with keepalive. I removed nginx from the test and I have the same problem.

I'm using:

• ApacheBench, Version 2.3
• Node v0.8.14.
• Ubuntu 12.04.1 LTS
• Express 3.0.3

The source code is:

var express = require('express');
var cluster = require('cluster');
var numCPUs = require('os').cpus().length;

if (cluster.isMaster) {
      for (var i = 0; i < numCPUs; i++) {
        cluster.fork();
      }

      cluster.on('exit', function(worker, code, signal) {
        console.log('worker ' + worker.process.pid + ' died');
      });
} else {
    var buffer = new Buffer(1048576);
    buffer.fill("a");
    var app = express();
    app.listen(8080);
    app.get('/test', function(req, res){
        setTimeout(function () {
            res.set('Content-Type', 'text/html');
            res.send(buffer.slice(0, req.query.size))
        }, req.query.delay);
    });
}

tcpdump example without keepalive: ab -c 1 -n 10 -r "172.16.76.253:8080/test?size=1024&delay=100"

10:58:59.403876 IP 172.16.180.47.57380 > 172.16.76.253.http-alt: Flags [P.], seq 1:122, ack 1, win 15, options [nop,nop,TS val 65479762 ecr 362284218], length 121
10:58:59.403961 IP 172.16.76.253.http-alt > 172.16.180.47.57380: Flags [.], ack 122, win 29, options [nop,nop,TS val 362284218 ecr 65479762], length 0
10:58:59.504631 IP 172.16.76.253.http-alt > 172.16.180.47.57380: Flags [P.], seq 1:146, ack 122, win 29, options [nop,nop,TS val 362284243 ecr 65479762], length 145
10:58:59.504890 IP 172.16.76.253.http-alt > 172.16.180.47.57380: Flags [FP.], seq 146:1170, ack 122, win 29, options [nop,nop,TS val 362284243 ecr 65479762], length 1024
10:58:59.505727 IP 172.16.180.47.57380 > 172.16.76.253.http-alt: Flags [.], ack 146, win 17, options [nop,nop,TS val 65479787 ecr 362284243], length 0
10:58:59.505741 IP 172.16.180.47.57380 > 172.16.76.253.http-alt: Flags [.], ack 1171, win 21, options [nop,nop,TS val 65479787 ecr 362284243], length 0

the ab results:

Server Hostname:        172.16.76.253
Server Port:            8080

Document Path:          /test?size=1024&delay=100
Document Length:        1024 bytes

Concurrency Level:      1
Time taken for tests:   1.025 seconds
Complete requests:      10
Failed requests:        0
Write errors:           0
Total transferred:      11690 bytes
HTML transferred:       10240 bytes
Requests per second:    9.75 [#/sec] (mean)
Time per request:       102.530 [ms] (mean)
Time per request:       102.530 [ms] (mean, across all concurrent requests)
Transfer rate:          11.13 [Kbytes/sec] received

Connection Times (ms)
          min  mean[+/-sd] median   max
Connect:        1    1   0.1      1       1
Processing:   101  102   0.5    102     102
Waiting:      101  102   0.5    102     102
Total:        102  102   0.6    103     103
WARNING: The median and mean for the total time are not within a normal deviation
    These results are probably not that reliable.

Percentage of the requests served within a certain time (ms)
  50%    103
  66%    103
  75%    103
  80%    103
  90%    103
  95%    103
  98%    103
  99%    103
 100%    103 (longest request)

tcpdump example with keepalive ab -c 1 -n 10 -k -r "172.16.76.253:8080/test?size=1024&delay=100"

11:00:12.567741 IP 172.16.180.47.57385 > 172.16.76.253.http-alt: Flags [P.], seq 1306:1451, ack 10567, win 26, options [nop,nop,TS val 65498053 ecr 362302509], length 145
11:00:12.567761 IP 172.16.76.253.http-alt > 172.16.180.47.57385: Flags [.], ack 1451, win 50, options [nop,nop,TS val 362302509 ecr 65498053], length 0
11:00:12.668837 IP 172.16.76.253.http-alt > 172.16.180.47.57385: Flags [P.], seq 10567:10717, ack 1451, win 50, options [nop,nop,TS val 362302534 ecr 65498053], length 150
11:00:12.706745 IP 172.16.180.47.57385 > 172.16.76.253.http-alt: Flags [.], ack 10717, win 26, options [nop,nop,TS val 65498088 ecr 362302534], length 0
11:00:12.706765 IP 172.16.76.253.http-alt > 172.16.180.47.57385: Flags [P.], seq 10717:11741, ack 1451, win 50, options [nop,nop,TS val 362302544 ecr 65498088], length 1024
11:00:12.707901 IP 172.16.180.47.57385 > 172.16.76.253.http-alt: Flags [F.], seq 1451, ack 11741, win 26, options [nop,nop,TS val 65498088 ecr 362302544], length 0
11:00:12.708141 IP 172.16.76.253.http-alt > 172.16.180.47.57385: Flags [F.], seq 11741, ack 1452, win 50, options [nop,nop,TS val 362302544 ecr 65498088], length 0

the ab results:

Server Hostname:        172.16.76.253
Server Port:            8080

Document Path:          /test?size=1024&delay=100
Document Length:        1024 bytes

Concurrency Level:      1
Time taken for tests:   1.361 seconds
Complete requests:      10
Failed requests:        0
Write errors:           0
Keep-Alive requests:    10
Total transferred:      11740 bytes
HTML transferred:       10240 bytes
Requests per second:    7.35 [#/sec] (mean)
Time per request:       136.073 [ms] (mean)
Time per request:       136.073 [ms] (mean, across all concurrent requests)
Transfer rate:          8.43 [Kbytes/sec] received

Connection Times (ms)
          min  mean[+/-sd] median   max
Connect:        0    0   0.3      0       1
Processing:   103  136  11.6    140     140
Waiting:      100  101   0.7    101     102
Total:        104  136  11.3    140     140

Percentage of the requests served within a certain time (ms)
  50%    140
  66%    140
  75%    140
  80%    140
  90%    140
  95%    140
  98%    140
  99%    140
 100%    140 (longest request)

nodejs sends response in two packets, one with header, one with data, and wait for ack after first packet.

I try to set sysctl net.ipv4.tcp_slow_start_after_idle=0 && sysctl net.ipv4.route.flush=1, but it didn't had any effect.

When using keepalive there is a 40ms extra delay. The question is: When does the extra 40ms come from? Maybe I'm doing wrong?

Answer 1

It Was a Bug. It Fixed here.

The issue was 4415

I changed res.send(buffer.slice(0, req.query.size)) by res.send(buffer.slice(0, req.query.size).toString()) as a workaround for this test.