11月
06

Node.js 应用性能调优

发表于 • 分类于 • 阅读次数:
字数统计: 3,075 • 阅读时长 ≈ 15 分钟

前提

Node.js是天才屌丝程序员Ryan Dahl于2009年发布，经过几年的发展，Node.js已经是成熟的JavaScript运行时了。用Node.js开发的应用被分发到世界各地的云主机上，随着公司的发展和壮大、应用PV和UV的剧增，如何保障Node.js应用的高性能是如今作为一个Node.js开发者必须面对的问题。

通过V8/Node自带的profiler能力

通过v8/Node的profiler能力，能够列出各函数的执行占比。

我们通过对一段经典简单的http服务的示例代码进行分析：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
// index.js
'use strict'

const Koa = require('koa');
const Router = require('koa-router');
const { etagger, timestamp, fetch } = require('./util')();
const server = new Koa();
const router = new Router();

router.get('/test', async function (ctx, next) {
  const content = await fetch(ctx.request.url);
  ctx.body = {data: content, url: ctx.request.url, ts: timestamp()};
  server.emit('after', ctx.body);
});

server.use(etagger().bind(server))
      .use(router.routes())
      .use(router.allowedMethods())

server.listen(3000);
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
48
49
50
51
52
53
54
55
56
57
// util.js
'use strict'

require('events').defaultMaxListeners = Infinity
const crypto = require('crypto')

module.exports = () => {
  const content = crypto.rng(5000).toString('hex')
  const ONE_MINUTE = 60000
  var last = Date.now()

  function timestamp () {
    var now = Date.now()
    if (now - last >= ONE_MINUTE) last = now
    return last
  }

  function etagger () {
    var cache = {}
    var afterEventAttached = false
    function attachAfterEvent (server) {
      if (attachAfterEvent === true) return
      afterEventAttached = true
      server.on('after', (result) => {
        const key = crypto.createHash('sha512')
          .update(result.url)
          .digest()
          .toString('hex')
        const etag = crypto.createHash('sha512')
          .update(JSON.stringify(result.data))
          .digest()
          .toString('hex')
        if (cache[key] !== etag) cache[key] = etag
      })
    }
    return async function (ctx, next) {
      attachAfterEvent(this);
      const key = crypto.createHash('sha512')
        .update(ctx.request.url)
        .digest()
        .toString('hex')
      if (key in cache) ctx.response.set('Etag', cache[key])
      ctx.response.set('Cache-Control', 'public, max-age=120')
      await next()
    }
  }

  function fetch (url) {
    return new Promise(resolve => {
      if (url !== '/test') resolve(Object.assign(Error('Not Found'), {statusCode: 404}))
      else resolve(content)
    });
  }

  return { timestamp, etagger, fetch }

}

这个例子响应/test路由，返回计算密集型处理的数据。

以--prof参数标识启动Node应用:

1
$ node --prof index.js

使用性能压测工具对接口http://127.0.0.1:3000/test进行压测，这里使用wrk，使用8个线程运行30秒的基准测试，并保持打开200个HTTP连接：

1
$ wrk -t8 -c200 -d30s http://127.0.0.1:3000/test

跑完基准测试，得到评估结果：

1
2
3
4
5
6
7
8
9
Running 30s test @ http://127.0.0.1:3000/test
  8 threads and 200 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   933.40ms  588.82ms   2.00s    56.50%
    Req/Sec    15.05     15.87   180.00     92.63%
  1012 requests in 30.07s, 10.00MB read
  Socket errors: connect 0, read 186, write 0, timeout 681
Requests/sec:     33.66
Transfer/sec:    340.71KB

从上面的接口评估结果可以看到，延迟平均有将近900ms，qps平均只有15.05，这是非常坏的结果。

通过--prof标识得到一个v8的log文件：isolate-0x103001000-v8.log，该文件人眼难阅读：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
v8-version,6,8,275,32,-node.36,0
shared-library,/Users/ricky/.nvm/versions/node/v10.13.0/bin/node,0x100001000,0x100ccc35d,0
shared-library,/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation,0x7fff34051d70,0x7fff341f2217,148725760
shared-library,/usr/lib/libSystem.B.dylib,0x7fff5e59694c,0x7fff5e596b2e,148725760
shared-library,/usr/lib/libc++.1.dylib,0x7fff5e7f0950,0x7fff5e839236,148725760
shared-library,/usr/lib/libobjc.A.dylib,0x7fff6003dbc0,0x7fff6005ec52,148725760
shared-library,/usr/lib/libDiagnosticMessagesClient.dylib,0x7fff5e1e3f7b,0x7fff5e1e4956,148725760
shared-library,/usr/lib/libicucore.A.dylib,0x7fff5f4ab928,0x7fff5f698b46,148725760
shared-library,/usr/lib/libz.1.dylib,0x7fff60f20390,0x7fff60f2bbd5,148725760
shared-library,/usr/lib/libc++abi.dylib,0x7fff5e848da0,0x7fff5e857f00,148725760
shared-library,/usr/lib/system/libcache.dylib,0x7fff60fa2b30,0x7fff60fa556e,148725760
shared-library,/usr/lib/system/libcommonCrypto.dylib,0x7fff60fa7c14,0x7fff60fb0c7d,148725760
shared-library,/usr/lib/system/libcompiler_rt.dylib,0x7fff60fb2e8c,0x7fff60fb7a6e,148725760
...

通过--prof-process处理该文件：

1
$ node --prof-process isolate-0x103001000-v8.log > profile.txt

先查看总览部分：

1
2
3
4
5
6
7
[Summary]:
  ticks  total  nonlib   name
   660    2.4%    2.4%  JavaScript
 26749   96.6%   97.4%  C++
  1243    4.5%    4.5%  GC
   228    0.8%          Shared libraries
    49    0.2%          Unaccounted

可以看到，在收集的样本中有97%发生在C++代码中，再去看看C++代码中发生了什么事：

1
2
3
4
5
6
7
8
9
10
11
[C++]:
  ticks  total  nonlib   name
 12361   44.6%   45.0%  T node::crypto::Hash::HashUpdate(v8::FunctionCallbackInfo<v8::Value> const&)
  9659   34.9%   35.2%  T v8::internal::JsonStringifier::SerializeString(v8::internal::Handle<v8::internal::String>)
   850    3.1%    3.1%  T node::crypto::Hash::New(v8::FunctionCallbackInfo<v8::Value> const&)
   219    0.8%    0.8%  t sha512_block_data_order_avx2
   162    0.6%    0.6%  T __kernelrpc_mach_port_request_notification
   149    0.5%    0.5%  t _tiny_malloc_should_clear
   127    0.5%    0.5%  t _tiny_malloc_from_free_list
   101    0.4%    0.4%  t __malloc_initialize
...

排名前三的条目占用了83.3%的CPU时间和82.6%的栈调用。从这个输出可以看到HashUpdate函数占用了45%的CPU时间，从该函数看不出是由哪里的代码产生的问题，接下来看看[Bottom up (heavy) profile]部分, 这部分提供了每个函数的主要调用者的信息：

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
12361   44.6%  T node::crypto::Hash::HashUpdate(v8::FunctionCallbackInfo<v8::Value> const&)
  12361  100.0%    T v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
  12166   98.4%      LazyCompile: *server.on /Users/ricky/app/node/flamegraph/koa-test/util.js:23:26
  12049   99.0%        LazyCompile: *emit events.js:140:44
  12049  100.0%          LazyCompile: ~<anonymous> /Users/ricky/app/node/flamegraph/koa-test/index.js:9:36
  12049  100.0%            Builtin: AsyncFunctionAwaitResolveClosure
    129    1.0%      LazyCompile: *update internal/crypto/hash.js:52:40
    128   99.2%        LazyCompile: *server.on /Users/ricky/app/node/flamegraph/koa-test/util.js:23:26
    125   97.7%          LazyCompile: *emit events.js:140:44
    125  100.0%            LazyCompile: ~<anonymous> /Users/ricky/app/node/flamegraph/koa-test/index.js:9:36
      3    2.3%          LazyCompile: ~emit events.js:140:44
      3  100.0%            LazyCompile: ~<anonymous> /Users/ricky/app/node/flamegraph/koa-test/index.js:9:36

   9659   34.9%  T v8::internal::JsonStringifier::SerializeString(v8::internal::Handle<v8::internal::String>)
   9659  100.0%    T v8::internal::Builtin_JsonStringify(int, v8::internal::Object**, v8::internal::Isolate*)
   9594   99.3%      LazyCompile: *server.on /Users/ricky/app/node/flamegraph/koa-test/util.js:23:26
   9512   99.1%        LazyCompile: *emit events.js:140:44
   9512  100.0%          LazyCompile: ~<anonymous> /Users/ricky/app/node/flamegraph/koa-test/index.js:9:36
   9512  100.0%            Builtin: AsyncFunctionAwaitResolveClosure

    850    3.1%  T node::crypto::Hash::New(v8::FunctionCallbackInfo<v8::Value> const&)
    850  100.0%    T v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
    841   98.9%      LazyCompile: *server.on /Users/ricky/app/node/flamegraph/koa-test/util.js:23:26
    835   99.3%        LazyCompile: *emit events.js:140:44
    835  100.0%          LazyCompile: ~<anonymous> /Users/ricky/app/node/flamegraph/koa-test/index.js:9:36
    835  100.0%            Builtin: AsyncFunctionAwaitResolveClosure

在上面的每个调用栈中，看到每个函数占用父类的百分比：

  1. util.js:23:26(server.on)占用了Builtin_HandleApiCall函数98%的时间，Builtin_HandleApiCall函数占用了HashUpdate函数100%的时间
  2. util.js:23:26(server.on)占用了Builtin_JsonStringify函数99%的时间，Builtin_JsonStringify函数占用了SerializeString函数100%的时间
  3. util.js:23:26(server.on)占用了Builtin_HandleApiCall函数98%的时间，Builtin_HandleApiCall函数占用了New函数100%的时间

综合上面的百分比可以看到util.js中的server.on是我们此次优化的目标。再看到util.js中，结合上面的信息，热点代码出现在events上，先看下面的代码：

1
require('events').defaultMaxListeners = Infinity

这里设置了events的默认最大句柄数是1e309, 如果不修改默认配置，Node.js配置的events的默认最大句柄数是10, 也就是一个实例只能监听同一个事件10次。把这行代码注释掉，然后以--trace-warnings标识启动应用，该标识可以打印进程警告的堆栈跟踪：

1
$ node --trace-warnings index.js

再次进行压测，可以看到警告信息：

1
2
3
4
5
6
7
8
9
10
11
(node:11356) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 after listeners added. Use emitter.setMaxListeners() to increase limit
    at _addListener (events.js:243:17)
    at Application.addListener (events.js:259:10)
    at attachAfterEvent (/Users/ricky/app/node/flamegraph/koa-test/util.js:23:14)
    at Application.<anonymous> (/Users/ricky/app/node/flamegraph/koa-test/util.js:36:7)
    at dispatch (/Users/ricky/app/node/flamegraph/koa-test/node_modules/koa-compose/index.js:42:32)
    at /Users/ricky/app/node/flamegraph/koa-test/node_modules/koa-compose/index.js:34:12
    at Application.handleRequest (/Users/ricky/app/node/flamegraph/koa-test/node_modules/koa/lib/application.js:151:12)
    at Server.handleRequest (/Users/ricky/app/node/flamegraph/koa-test/node_modules/koa/lib/application.js:133:19)
    at Server.emit (events.js:182:13)
    at parserOnIncoming (_http_server.js:652:12)

句柄达到了11个，可以知道代码中有大量发生server.on监听事件的行为。

查看代码中逻辑，看到了一个问题：

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
function etagger () {
    var cache = {}
    var afterEventAttached = false
    function attachAfterEvent (server) {
      if (attachAfterEvent === true) return // 应该是afterEventAttached
      afterEventAttached = true
      server.on('after', (result) => {
        const key = crypto.createHash('sha512')
          .update(result.url)
          .digest()
          .toString('hex')
        const etag = crypto.createHash('sha512')
          .update(JSON.stringify(result.data))
          .digest()
          .toString('hex')
        if (cache[key] !== etag) cache[key] = etag
      })
    }
    return async function (ctx, next) {
      attachAfterEvent(this);
      const key = crypto.createHash('sha512')
        .update(ctx.request.url)
        .digest()
        .toString('hex')
      if (key in cache) ctx.response.set('Etag', cache[key])
      ctx.response.set('Cache-Control', 'public, max-age=120')
      await next()
    }
  }

看到有个条件永远满足，所以每次请求就会产生一次server.on("after", () => {})，解决这个bug：

1
2
// if (attachAfterEvent === true) return
if (afterEventAttached === true) return

再次进行压测，得到评估结果：

1
2
3
4
5
6
7
8
9
Running 30s test @ http://127.0.0.1:3000/test
  8 threads and 200 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    34.93ms    7.02ms 206.34ms   92.51%
    Req/Sec   722.16    109.92     1.39k    79.91%
  172565 requests in 30.10s, 1.67GB read
  Socket errors: connect 0, read 25, write 4, timeout 0
Requests/sec:   5733.90
Transfer/sec:     56.68MB

qps平均值增加了48倍，延迟平均值减少了23倍！后面还有一些优化空间，比如：

  1. JSON.stringify
  2. crypto.createHash
  3. crypto.rng

这几个API都是CPU计算大户，换另外种实现方式可以将qps再次增加几倍。

通过火焰图可视化分析

火焰图（flamegraph）是brendangregg处理MySQL性能问题时发明的。它利用常规的剖析器/示踪器得到的文本产生可视化，允许快速准确地识别最频繁的代码路径, 可以更快的找出热点代码和调用堆栈之间的关系。恢复上面代码原来的样子，我们使用0x(github@davidmarkclements)这个工具进行分析，它可以通过分析CPU profile文件生成svg火焰图。

举个例子说明火焰图的调用堆栈，伪代码如下：

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
function a() {
  if (条件) {
    b();
  } else {
    c();
  }
}

function b() {
  d();
}

function c() {
  if (条件) {
    e();
  } else {
    f();
  }
}

function d() {}

function e() {}

function f() {}

对应的火焰图如下：

7

以下命令启动应用：

1
2
$ 0x -o index.js
🔥  Profiling

然后用wrk进行压测：

1
$ wrk -t8 -c200 -d30s http://127.0.0.1:3000/test

评估报告参考第一次压测结果。然后ctrl + c退出当前进程, 等待分析并生成火焰图：

1

横轴表示抽样数，宽度越大表示该函数的抽取次数越多，也就是占用CPU总时间越多。每一层表示一个调用栈一个函数，调用栈越深火焰越高，每一层的父类在下一层。一个出现平顶的火焰图表示有可能瓶颈就是出现在最顶层的函数上。

*表示经过v8优化的代码，~表示未经过优化的代码，如果优化状态对我们不重要，可以点击merge按钮合并：

2

可以看到server.on占用了大部分的CPU时间。现在开启的分析结果是app、依赖包、和node核心，现在点击v8和cpp开启内置的模块调用栈：

3

Node.js的JSON解析器是直接用了v8的json引擎，所以看不到js的函数调用，只是看到了c++的调用函数SerializeString，现在试着把JSON.stringify去掉：

1
2
3
4
5
6
7
8
9
10
11
server.on('after', (req, res) => {
     const key = crypto.createHash('sha512')
          .update(result.url)
          .digest()
          .toString('hex')
        const etag = crypto.createHash('sha512')
          .update(result.data)
          .digest()
          .toString('hex')
        if (cache[key] !== etag) cache[key] = etag
})

再次压测，得到的火焰图如下：

4

可以看到平顶的情况已经好很多了，但是更突出了一个问题，emit函数成为了热点代码, 原因可能就是events的句柄太多，去掉require('events').defaultMaxListeners = Infinity这一行代码，检查代码并修复一处bug:

1
2
if (afterEventAttached === true) return
// if (attachAfterEvent === true) return

再次压测，得到的评估报告：

1
2
3
4
5
6
7
8
9
Running 30s test @ http://127.0.0.1:3000/test
  8 threads and 200 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    23.16ms    8.36ms 218.06ms   95.75%
    Req/Sec     1.11k   191.79     2.08k    93.37%
  265424 requests in 30.10s, 2.53GB read
  Socket errors: connect 0, read 27, write 3, timeout 0
Requests/sec:   8818.89
Transfer/sec:     86.04MB

得到的火焰图：

5

该火焰图表示已经改善了巨大的平顶的函数了，现在的热点代码是在node核心的定时器上了，现在得到的火焰图已经修复了最大的问题区域了，当然还是可以继续优化下去，直到火焰图的平顶函数越来越少。

在github上查看

分享到：
Disqus 加载中...

如果长时间无法加载，请针对 disq.us | disquscdn.com | disqus.com 启用代理