Gist & Cookbook ...

小目标:每天能够提交一行代码 ...

狠扣代码的细节,性能提升40倍:Node程序性能分析和优化(第一弹)

吴亮's Avatar 2017-10-28

  1. 1. 基础工作
    1. 1.1. 系统一般会受哪些方面影响?
    2. 1.2. 性能分析的一般步骤
    3. 1.3. 从代码细节实现入手,解决性能问题的一般思路
    4. 1.4. 我们的基础工作
  2. 2. 开始干活了 …
    1. 2.1. 测试基准值
    2. 2.2. 分析一:第一次V8 profiling结果分析
    3. 2.3. 分析二:都是babel-register惹的祸
    4. 2.4. 分析三:真正的优化开始了,活用babel
    5. 2.5. 分析四:map vs object
    6. 2.6. 分析五:努力争取将各个函数都优化到极致
      1. 2.6.1. 细节优化一:没必要Node环境上加载针对es5/6/7的polyfill
      2. 2.6.2. 细节优化二:Date的格式化输出
        1. 2.6.2.1. new Date().getTime()vsDate.now()
        2. 2.6.2.2. Date格式化的库的选择
      3. 2.6.3. 细节优化三:字符串拼接的优化
      4. 2.6.4. 细节优化四:针对生产环境的一些优化
      5. 2.6.5. 细节优化点五:一些基本原则
    7. 2.7. 分析六:express相关
    8. 2.8. 分析六:明明说是40倍,为啥才是32倍呢?标题党?
      1. 2.8.1. 我们的1.x版本和2.0版本优化了哪些?
  3. 3. 总结

本文从代码细节入手,一步一步分析 Top-Calls,并且如何解决。

我们的Node程序都实在太慢了,完全看不出它所谓的性能优势。

基础工作

系统一般会受哪些方面影响?

对于一般的系统,性能问题主要会受以下几部分影响:

  • 代码实现问题
  • 架构问题:比如是不是可以通过加一个缓存系统(比如:redis来提升查询效率)
  • 所依赖的系统存在系统问题:比如我们目前重度依赖的MySQL,这些系统的负载是不是已经很重了

我们这次是从第一点:代码实现 的角度来狠扣细节,一块一块代码来修改

性能分析的一般步骤

根据以往的经验,分析性能问题的一般步骤:

  • 使用性能测试工具(比如jmeter)来评估性能,得到一个基础值
  • 使用Profiler工具来剖析哪块代码最耗时
  • 针对最耗时的代码,做优化
  • 重复上述三步,直到性能达到预期未知

从代码细节实现入手,解决性能问题的一般思路

这个其实是一个技巧性问题,可以持续总结

我们的基础工作

  • 因为Node是单进程的,因此我们性能评估时,可以就先测试单个Node进程的;最终上线前,可以再起多个进程做整体的性能评估
  • 因为我们也是HTTP服务,因此性能测试工具我们就采用jmeter
  • Profiler工具,貌似只能选择v8-profiler,具体怎么使用可以执行Google,我比较偷懒,直接使用WebStorm里的 V8 Profiling

开始干活了 …

测试基准值

我们的Web框架是自己实现在自己实现了一套 依赖注入 机制的基础上,使用express作为基础的HTTP Server,差不多就是 SpringMVC for Node,取名为 guice-web V2。因此可以先做一个框架本身和express之间的性能对比:

性能指标guice-web V2express
QPS321390

这块express我加了几个所需要的中间件,因此性能结果比官方值低

得到这个性能查询结果让我很惊愕,guice-web V2性能竟然只有express的 1/43

不过没事,我们下面来看看性能究竟耗在哪儿了?

分析一:第一次V8 profiling结果分析

使用v8 profiling可以得到如下结果:

profiling结果会按函数的调用次数将代码中的函数从高到低排序,从这种图中可以看出,消耗我们最多的竟然是 fs.readSync

这个结果让我很意外,因为我感觉代码中压根没有读文件的,尤其还是同步读文件的,但为啥会有这个结果呢?

继续看旁边的 Bottom-UP,这个是将函数整个调用栈从外到里的展示出来:

从上述这张图其实就可以比较方便地分析出来,其实是node的 require 调用的是 fs.readSync,于是我想起来了,有些代码require没有写到文件的头部,而是写到函数内的 。这个主要是我对Node模块的加载机制理解有问题,我以为Node编译时会把所有require语句都提前,但其实不会。

另外,写个demo再证明一下刚才说的逻辑:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
// require在文件头部
require('http');
require('https');
require('child_process');
require('cluster');
require('fs');
require('crypto');
require('net');
require('events');
require('zlib');
require('util');

function f() {}

var startTime = new Date().getTime();

f();
var endTime = new Date().getTime();

console.log(endTime - startTime)
// 得到结果0
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
// require在函数中
function f() {
require('http');
require('https');
require('child_process');
require('cluster');
require('fs');
require('crypto');
require('net');
require('events');
require('zlib');
require('util');
}

var startTime = new Date().getTime();

f();
var endTime = new Date().getTime();

console.log(endTime - startTime);
// 得到39

这下彻底说明了问题了。

不过node本身会对require做缓存,应该虽然这块require被调用的次数多,并且还是同步IO的,但却成不了性能瓶颈。

我们接着往下分析

分析二:都是babel-register惹的祸

我们再看看刚才的Top-Calls,发现很多都是 source-map 什么的,这个是什么鬼?

细想一下,于是明白了,因为代码大量使用了ES6/ES7的语法,依赖 babel 的转换,但为了之前开发方便,不想每次都编译,我直接在入口文件 require('babel-register')。原本想着其实没为啥,感觉反正是程序启动时babel就转换了所有文件,但忘了它需要跟踪堆栈了。于是把入口文件的require('babel-register')去掉后,babel转换后,测试babel转换后的性能,得到如下结果:

QPS直接从32提升到50+,提升快一倍了。

即使这样,比我预想得还慢很多,我的目标至少是 express 的一半。

分析三:真正的优化开始了,活用babel

以上两块分析和改动,都是很小的调优,没有涉及到系统本身的筋骨。我们继续分析:我们可以看到,top的是 error-stack-parser.js 这个文件,这个源于我引入的error-stack-parser

为什么我要引入这个依赖?

我写了一个日志输出模块,但日志输出模块中我期望的输出格式是:

日期(YYYYMMDD)LEVEL APP_NAME message (in fileName:lineNumber)

这其中日期(YYYYMMDD)、fileName、lineNumber都是变量,其中的fileName和lineNumber怎么获取?

参考baryon/tracer 中的做法,通过 (new Error()).stack 中来解析得到。另外,为了解析方便,我引入了error-stack-parser来方便解析,而error-stack-parser是使用正则表达式来解析,超慢的!!!

问题的原因是找到了,但如何解决?

最简单的办法当然是不输出fileName和lineNumber,但这个不是我想要的。

另外一个办法,自然是哪儿输入log,哪儿就传入fileName和lineNumber,node有__filename 这种预置变量,但却没__line 这种,并且,如果要求每个输出log的地方都要从logger.debug("msg")改成:logger.debug(__filename, __line, "msg"),其实也不太适合,没有logger模块是这么要求使用者的。

我想起以前写C++时,日志的输出都是封装成一个宏,比如:

1
2
#define LOG_INFO(format, args...) {                            \
logger->log(alog::LOG_LEVEL_INFO, __FILE__, __LINE__, __FUNCTION__, format, ##args);}

那么我能不能也改成这般呢?

babel是个好东西,它可以让我们自创各种语法,于是我们可以利用babel,将代码从logger.debug("msg")改成:__LOG_DEBUG__(logger, "msg"),然后经过babel转换后,变成logger.debug({fileName: "filename", lineNumber: 12}, "msg")

下面我们来实现这个babel插件:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
const path = require('path');

const LOG_PATTERN = /__LOG_(\w+)__/;

module.exports = ({types}) => {
const void0Expression = types.unaryExpression('void', types.numericLiteral(0), true);

let transformLog = (nodePath, state) => {
let calleeName = nodePath.node.callee.name;
let matched = LOG_PATTERN.exec(calleeName);
let methodName = matched[1].toLowerCase();
let filePath = path.resolve(state.file.opts.filename);
let startLineNumber = nodePath.node.loc.start.line;
let calleeInstance = "";
if (nodePath.node.arguments[0].type **= "MemberExpression") {
calleeInstance = nodePath.node.arguments[0].object.name + "." + nodePath.node.arguments[0].property.name
}
else {
calleeInstance = nodePath.node.arguments[0].name;
}

let calleeExpression = types.identifier(calleeInstance + "." + methodName);
let logBasic = types.identifier(JSON.stringify({
lineNumber: startLineNumber,
fileName: filePath
}));
let calleeArguments = [
logBasic
];
for (const arg of nodePath.node.arguments.slice(1)) {
calleeArguments.push(arg);
}
let joinedCallExpression = types.callExpression(calleeExpression, calleeArguments);
nodePath.replaceWith(joinedCallExpression);
};

return {
visitor: {
CallExpression: function(nodePath, state) {
let calleeName = nodePath.node.callee.name;
if (LOG_PATTERN.test(calleeName)) {
transformLog(nodePath, state);
}
}
}
};
};

经过这个插件转换:

1
__LOG_DEBUG__(self.logger, 'got instance: %s', name);

转成成了

1
self.logger.debug({"lineNumber":224,"fileName":"/Users/wuliang/zone/node-guice/src/v2/Guice2.js"}, 'got instance: %s', name);

好了,我们再测试一下性能:

QPS基本上达到300+,比之前提升了10倍了

分析四:map vs object

上述的性能测试结果非常可喜,但距离我的目标还有很大距离,我们继续分析 Top-Calls

我们可以看到,除了logger外,另外一个消耗大头就是Guice2.js中的getInstance,这个是因为我整个框架重度依赖我自己写的依赖注入框架Guice,而这个getInstance是其中取对象的方法。

在这个依赖注入中,有一个instancePool是保存所有绑定信息,另外一个instanceCache是缓存对象的,以便实现Singleton。之前这两个属性都是普通的object:{},那我们就拿这个{}入手,改成Map试试性能。

jsperf有一个关于map和object的性能对比测试,大家可以跑一下看看:es6-map-vs-object-properties。从这上面可以看出,Map还是有一定性能优势的,于是我们把instancePoolinstanceCache都改成Map

测试一下性能,还是挺可喜的:

性能明显比之前提升了不少,最低时刻也和上一个场景持平,顶峰竟然可以到800+了

分析五:努力争取将各个函数都优化到极致

到了上述成果后,我整体性能排查到了一定的瓶颈,感觉大头都已经优化了,那么我们就看看细节上还有那些可以优化的

细节优化一:没必要Node环境上加载针对es5/6/7的polyfill

因为我们的不少基础模块都是可以跨平台(Node和浏览器)使用的,因此为了解决浏览器兼容性问题,都引入了es5-shimes6-shimes7-shim。理论上这些polyfill都会根据运行环境来觉得是不是要polyfill;但下面这个结果颠覆了我:

竟然使用了es5-shim里面的Date!

看一下es5-shim中的实现,es5-shim.js:1413,可以看到它有个doesNotParseY2KNewYear || acceptsInvalidDates || !supportsExtendedYears的判断,那我估计连Node都不符合它对Date的定义吧。

解决办法倒好办,在Node环境上,果断放弃es5-shimes6-shimes7-shim

细节优化二:Date的格式化输出

这块有两个点可以优化:

  • new Date().getTime() vs Date.now()
  • Date格式化的库的选择

new Date().getTime()vsDate.now()

这块在jsperf已经有了TestCase:date-now-vs-new-date,一跑就可以看出,Date.now()的性能优势相当明显

Date格式化的库的选择

Date格式化的选择真的非常多,比如moment、比如比moment小巧很多的fecha

我之前都是采用fecha的,但经过性能测试下来,最后选择了带缓存的speed-date

为什么呢?

因为我这边对Date的格式化主要是在输出请求的originalUrl上,并且我们的系统流量非常大,因此缓存同一时间的格式化阶段收益就比较明显了。

细节优化三:字符串拼接的优化

因为一个曾经的C++开发,对sprintf的偏好可能是与生俱来的。因此我其实并不喜欢直接的string相加,或者es6中的template literals

其实Node已经自带util.format方法了,但我之前竟然一直忽略了这个方法,而使用了alexei/sprintf.js,但后来发现,竟然还是util.format最快,可以看如下的性能结果:

https://github.com/andrasq/node-qprintf#benchmark

另外,这块其实还有一个小优化点,经过babel转换后的代码,有些代码是这般的"ke" + "ys",这块我加了一个babel插件:laysent/babel-plugin-transform-string-join来针对这种情况进行优化,直接让它变成:"keys"

细节优化四:针对生产环境的一些优化

比如在我的日志库中,我们对日志的date、level等信息都做了彩色输出(写JS都就可以搞这些,呵呵);但彩色输出其实在生产环境没啥用,因为生产环境日志都是写到一个文件中的,一般的模块都会做istty的判断,以决定要不要彩色输出。因此这个判断在生产环境上就成了一个负担。

解决办法:加一个启动时的环境变量,比如NODE_ENV=production,来屏蔽这个彩色输出。

细节优化点五:一些基本原则

剩余一些基本的原则,和Node无关:

  • 把能提前初始化的变量尽量以前初始化,虽然浪费点内存
  • 把函数中跳出判断尽量提前

分析六:express相关

有一个隐含的优化点突然被我发现,因为我们对所有请求头都加上了CORS,之前的代码是:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
app.use(function (request, response, next) {
response.header(
'Access-Control-Allow-Origin',
request.headers.origin
);
response.header(
'Access-Control-Allow-Headers',
'Content-Type, Access-Control-Allow-Headers, Authorization, X-Requested-With'
);
response.header(
'Access-Control-Allow-Methods',
'GET,HEAD,POST,PUT,DELETE,OPTIONS'
);
response.header('Access-Control-Allow-Credentials', 'true');
next();
});

当我改成:

1
2
3
4
5
6
7
8
9
response.header({
'Access-Control-Allow-Origin': request.headers.origin,
'Access-Control-Allow-Headers':
'Content-Type, Access-Control-Allow-Headers, Authorization, X-Requested-With',
'Access-Control-Allow-Methods':
'GET,HEAD,POST,PUT,DELETE,OPTIONS',
'Access-Control-Allow-Credentials': 'true'
});
next();

性能竟然又提升了不少,经过上述分析五和分析六的优化,最终测试结果:

上述这图只是某些点的QPS,我分析jmeter的日志,QPS达到: 680,已经比之前的32倍,成果杠杠的!

分析六:明明说是40倍,为啥才是32倍呢?标题党?

我这边对比的框架guice-web已经我们的2.0版本,但目前我们线上用的还是1.x版本,1.x版本的QPS只有17,比2.0版本还慢不少,因此从1.x版本的17到2.0版本的32到经过优化后的680,40倍的差距啊

我们的1.x版本和2.0版本优化了哪些?

涉及性能的点有:

  • 1.x版本大量使用了kriskowal/q作为Promise库,但经过profiling分析,这个库性能实在不咋地
  • 不盲目使用promise:之前为了通用,大量方法都使用了promise,但事实上,这种做法过于盲目,非常影响性能,还是应该合理使用
  • 也不要盲目使用 process.nextTick:这个也一样,因为它会把任务放到下一个轮询上去了,盲目使用,就会造成明明这会可以做的事情,却偏偏往后才做,并且因为你无法预估队列中的任务的时间消耗。

总结

这块我们就针对代码中的诸多细节做了优化,总结一下包含以下几个点:

  • 尽可能少用正则表达式:v8对正则表达式的执行那是相当慢,后续我想试试看,写个语法解析器来替代正则表达式,可能会快点
  • 活用转换和编译
  • 选择适合的数据结构
  • 对依赖库的选择要做好调研
  • 合理使用promise和process.nextTick,能不放到下一个时间轮询中就尽量不那么做

其实可以做优化的点还很多(比如for … of 中await的问题),后面我们再继续总结。

本文作者 : 吴亮
本文使用 署名-非商业性使用-相同方式共享 4.0 国际 (CC BY-NC-SA 4.0) 协议
本文链接 : https://www.wuliang.me/node-performance-optimizing/

本文最后更新于 天前,文中所描述的信息可能已发生改变