Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP

Loading…

Tcp delayed ack in nodejs with express #4415

Closed
matiasrege opened this Issue · 4 comments

3 participants

@matiasrege

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 <$Revision: 655654 $>
  • 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 = 3;

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?

It also posted on http://stackoverflow.com/questions/13882919/tcp-delayed-ack-in-nodejs-with-express

@bnoordhuis

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

You may have discovered a bug. I'll look into it.

@bnoordhuis bnoordhuis was assigned
@bnoordhuis

Okay, I know what's going on. node.js tries to pack the response headers and the (first chunk of) the response body into a single packet - but only if the body is a string. When it's a buffer, it falls back to the slow, two packet path.

It's not a regression, I've traced it back to at least the early v0.6 days but it's likely older than that. The fix may be pretty simple. I'll keep you posted.

@bcantrill bcantrill was assigned
@bnoordhuis bnoordhuis referenced this issue from a commit
Commit has since been removed from the repository and is no longer available.
@bnoordhuis bnoordhuis referenced this issue from a commit
Commit has since been removed from the repository and is no longer available.
@bnoordhuis bnoordhuis referenced this issue from a commit
Commit has since been removed from the repository and is no longer available.
@bnoordhuis bnoordhuis referenced this issue from a commit in bnoordhuis/node
@bnoordhuis bnoordhuis http: pack response body buffer in first tcp packet
Apply the same optimization to res.end(buf) that is applied to res.end(str).

Speeds up `node benchmark/http_simple_auto -k -c 1 -n 25000 buffer/1`
(non-chunked response body) by about 750x. That's not a typo.

Chunked responses:

  $ cat tmp/http-chunked-client.js
  // Run `node benchmark/http_simple` in another terminal.
  var http = require('http'), url = require('url');
  var options = url.parse('http://127.0.0.1:8000/buffer/1/1');
  options.agent = new http.Agent({ maxSockets: 1 });
  for (var i = 0; i < 25000; ++i) http.get(options);

Before:

  $ time out/Release/node tmp/http-chunked-client.js
  real    16m40.411s
  user    0m9.184s
  sys     0m0.604s

After:

  $ time out/Release/node tmp/http-chunked-client.js
  real    0m5.386s
  user    0m2.768s
  sys     0m0.728s

That's still a 185x speed-up.

Fixes #4415.
5a19c07
@bnoordhuis

Fixed in 5a19c07.

@bnoordhuis bnoordhuis closed this
@bnoordhuis bnoordhuis was assigned
@matiasrege

Thank!

Tests with the new version:

$> ab -c 1 -n 10 -k -r "172.16.76.253:8080/test?size=1024&delay=100"
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 172.16.76.253 (be patient).....done

Server Software:

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.028 seconds
Complete requests: 10
Failed requests: 0
Write errors: 0
Keep-Alive requests: 0
Total transferred: 11480 bytes
HTML transferred: 10240 bytes
Requests per second: 9.72 #/sec
Time per request: 102.847 ms
Time per request: 102.847 ms
Transfer rate: 10.90 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 1 1 0.1 1 1
Processing: 101 102 0.9 102 104
Waiting: 101 102 0.9 102 104
Total: 102 103 0.9 103 105

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.