3
我有两台机器，一台“服务器”和一台“客户机”。两者都是带有NodeJS v5.8.0的CentOS6。具有并发性的NodeJS请求超时100
服务器运行下面的程序：
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，使请求“服务器”机得到“这是XML”字符串。这些数据被传送回“客户”的客户端。几乎就在
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
所以，问题不在于“服务器”处理请求太长，但与客户端的问题。
在5.8的NodeJS 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我的系统上的样子：
[email protected] 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
有什么可以为超时理由吗？
你最大的插座看起来不错，但尽量将keepalive设置为true，然后设置的环境变量UV_THREADPOOL_SIZE = 50，或4之间的某个值 - 128.我最近跑了与配置一些负载测试和客户端似乎工作最好与这些设置。 – aembke
它的工作原理！请把这个评论作为答案，我会接受它。如果你能解释这些设置的原因以及为什么默认值不好，那将是非常好的。非常感谢！ – rlib
没问题，只是现在更新。 – aembke