并发数为 100 时 NodeJS 请求超时

Question

我有两台机器，一台“服务器”和一台“客户端”。两者都是 CentOS6 和 NodeJS v5.8.0。

服务器运行以下程序：

const AppPort = 8080;
var app = require('express')();
var logger = require('log4js').getLogger();
var onFinished = require('on-finished');
var uid = require('uid');

var reqCnt = 0;
var reqFin = 0;


app.get('/', function(req, res) {
  onFinished(req, function() {
    reqFin++;
    var ts2 = (new Date()).getTime();
    logger.info(`uid=${req.uid}, dt=${ts2-req.ts1}`);
  });
  req.ts1 = (new Date()).getTime();
  req.uid = uid();

  reqCnt++;
  logger.info(`ReqCnt=${reqCnt}, fins=${reqFin}`);
  res.send("This is XML");
});
app.listen(AppPort);

它的唯一目的是返回"This is XML"字符串并计算完成请求的时间。

在“客户端”机器上我运行以下程序：

const AppPort = 10000;
var onFinished = require('on-finished');
var async = require('async');
var request = require('request');
var logger = require('log4js').getLogger();
var app = require('express')();
var fs = require('fs');
var util = require('util');

url = "http://my-server";

var errCnt = 0;
var okCnt = 0;
var active2 = 0;

setInterval(function() {
  var errFrac = Math.floor(errCnt/(okCnt+errCnt)*100);
  logger.info(`${okCnt},${errCnt},${active2},${errFrac}`);
}, 1000);

app.get('/test', function(req,res) {
  onFinished(res, function() {
    active2--;
  });
  active2++;
  var ts1 = (new Date()).getTime();
  request(url, {timeout: 1000}, function(err, response, body ) {
    var ts2 = (new Date()).getTime();
    var dt = ts2-ts1;
    if ( err ) {
      errCnt += 1;
      logger.error(`Error: ${err}, dt=${dt}, errCnt=${errCnt}`);
      res.send(`Error: ${err}`);
    }
    else {
      okCnt += 1;
      logger.info(`OK: ${url}`);
      res.send(`OK: ${body}`);
    }
  });
});
var http = app.listen(AppPort);

logger.info(`Listening on ${AppPort}, pid=${process.pid}`);

该“客户端”代码自行侦听端口 10000，并向“服务器”计算机发出请求以获取“This is XML”字符串。该数据被传输回“客户”的客户。

我用 siege 对我的客户端代码进行负载测试：

siege -v -r 100 -c 100 http://my-client:10000/test 

我几乎立即开始收到 ETIMEOUT 错误：

[2016-03-15 18:17:05.155] [ERROR] [default] - Error: Error: ETIMEDOUT, dt=1028, errCnt=3
[2016-03-15 18:17:05.156] [ERROR] [default] - Error: Error: ETIMEDOUT, dt=1028, errCnt=4
[2016-03-15 18:17:05.156] [ERROR] [default] - Error: Error: ETIMEDOUT, dt=1027, errCnt=5
[2016-03-15 18:17:05.157] [ERROR] [default] - Error: Error: ETIMEDOUT, dt=1027, errCnt=6
[2016-03-15 18:17:05.157] [ERROR] [default] - Error: Error: ETIMEDOUT, dt=1027, errCnt=7
[2016-03-15 18:17:05.157] [ERROR] [default] - Error: Error: ETIMEDOUT, dt=1027, errCnt=8
[2016-03-15 18:17:05.158] [ERROR] [default] - Error: Error: ETIMEDOUT, dt=1027, errCnt=9
[2016-03-15 18:17:05.160] [ERROR] [default] - Error: Error: ETIMEDOUT, dt=1029, errCnt=10
[2016-03-15 18:17:05.160] [ERROR] [default] - Error: Error: ETIMEDOUT, dt=1028, errCnt=11
[2016-03-15 18:17:05.161] [ERROR] [default] - Error: Error: ETIMEDOUT, dt=1028, errCnt=12

此外，尽管出现的频率要低得多，但getaddrinfo也会出现错误：

Error: Error: getaddrinfo ENOTFOUND {my-server-domain-here}:8080, dt=2, errCnt=4478

但是，对“服务器”的所有请求都会在服务器本身上处理不到 3 毫秒（dt值）：

[2016-03-15 18:19:13.847] [INFO] [default] - uid=66ohx90, dt=1
[2016-03-15 18:19:13.862] [INFO] [default] - ReqCnt=5632, fins=5631
[2016-03-15 18:19:13.862] [INFO] [default] - uid=j8mpxdm, dt=0
[2016-03-15 18:19:13.865] [INFO] [default] - ReqCnt=5633, fins=5632
[2016-03-15 18:19:13.866] [INFO] [default] - uid=xcetqyj, dt=1
[2016-03-15 18:19:13.877] [INFO] [default] - ReqCnt=5634, fins=5633
[2016-03-15 18:19:13.877] [INFO] [default] - uid=i5qnbit, dt=0
[2016-03-15 18:19:13.895] [INFO] [default] - ReqCnt=5635, fins=5634
[2016-03-15 18:19:13.895] [INFO] [default] - uid=hpdmxpg, dt=1
[2016-03-15 18:19:13.930] [INFO] [default] - ReqCnt=5636, fins=5635
[2016-03-15 18:19:13.930] [INFO] [default] - uid=8g3t8md, dt=0
[2016-03-15 18:19:13.934] [INFO] [default] - ReqCnt=5637, fins=5636
[2016-03-15 18:19:13.934] [INFO] [default] - uid=8rwkad6, dt=0
[2016-03-15 18:19:14.163] [INFO] [default] - ReqCnt=5638, fins=5637
[2016-03-15 18:19:14.165] [INFO] [default] - uid=1sh2frd, dt=2
[2016-03-15 18:19:14.169] [INFO] [default] - ReqCnt=5639, fins=5638
[2016-03-15 18:19:14.170] [INFO] [default] - uid=comn76k, dt=1
[2016-03-15 18:19:14.174] [INFO] [default] - ReqCnt=5640, fins=5639
[2016-03-15 18:19:14.174] [INFO] [default] - uid=gj9e0fm, dt=0
[2016-03-15 18:19:14.693] [INFO] [default] - ReqCnt=5641, fins=5640
[2016-03-15 18:19:14.693] [INFO] [default] - uid=x0yw66n, dt=0
[2016-03-15 18:19:14.713] [INFO] [default] - ReqCnt=5642, fins=5641
[2016-03-15 18:19:14.714] [INFO] [default] - uid=e2cumjv, dt=1
[2016-03-15 18:19:14.734] [INFO] [default] - ReqCnt=5643, fins=5642
[2016-03-15 18:19:14.735] [INFO] [default] - uid=34e0ohl, dt=1
[2016-03-15 18:19:14.747] [INFO] [default] - ReqCnt=5644, fins=5643
[2016-03-15 18:19:14.749] [INFO] [default] - uid=34aau79, dt=2

所以，问题不是“服务器”处理请求的时间太长，而是客户端有问题。

在 NodeJS 5.8 中，globalAgent如下所示：

console.log(require('http.globalAgent'))

Agent {
  domain: null,
  _events: { free: [Function] },
  _eventsCount: 1,
  _maxListeners: undefined,
  defaultPort: 80,
  protocol: 'http:',
  options: { path: null },
  requests: {},
  sockets: {},
  freeSockets: {},
  keepAliveMsecs: 1000,
  keepAlive: false,
  maxSockets: Infinity,
  maxFreeSockets: 256 }

ulimits在我的系统上看起来像：

root@njs testreq]# ulimit -all
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 128211
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 200000
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 10240
cpu time               (seconds, -t) unlimited
max user processes              (-u) 128211
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

超时的原因可能是什么？

Answer 1

最近运行一些负载测试时，我遇到了类似的错误，但是我看到了多个 EADDRINUSE 错误，而不是 ETIMEDOUT 错误。当时我正在使用以下 HTTP 代理配置更改来运行测试。

{
    maxSockets: 256,
    keepAlive: false
}

事实证明，这种配置浪费了大量周期，有意在单个请求后关闭每个连接，并且 EADDRINUSE 错误是由于临时端口耗尽而导致的。

对于我的测试，我仍然使用版本 0.12.9，所以我不确定这是否仍然适用于 >= 4.x 的版本，但核心 HTTP 库将在可能的情况下根据主机/端口/协议自动维护与服务器的连接。这可以大大减少客户端和服务器上的负载，但如果客户端池太小而无法处理出站请求的速率，也可能导致请求堆积。最好的配置是尽可能保持活动连接，但仍然有足够大的连接池来快速处理每个出站请求。

此外，Node.js 构建在libuv之上，它实现了事件循环接口。不管怎样，核心 Node.js 库实现的几乎所有异步操作都会与 libuv 交互。为了实现这种类型的接口，libuv 将使用几种不同策略之一，其中之一是线程池。该线程池的默认大小为 4，最大为 128。

这里重要的一点是，任何对线程池的调用getaddrinfo都getnameinfo将使用线程池，这意味着无论 HTTP 连接池的大小如何，DNS 查询和网络堆栈中较低层的一些操作都将根据线程池大小进行序列化。可以通过将环境变量设置UV_THREADPOOL_SIZE为 4 - 128 范围内的值来更改线程池大小。

对于我的测试，理想的设置是UV_THREADPOOL_SIZE=50使用以下 HTTP 代理配置。

{
    maxSockets: 256,
    keepAlive: true
}

这个答案提供了有关何时以及如何使用 libuv 的更多信息。