Node.js 性能调优之CPU篇(一)——perf+火焰图

Node.js 性能调优之CPU篇(一)——perf+火焰图

nswbmwnswbmw

火焰图(Flame Graph)想必大家都听过,它可以将 CPU 的使用情况可视化展示,能够直观地帮助我们了解到程序的性能瓶颈。通常要结合操作系统的性能分析工具(profiling tracer)使用。常见的有:

  • Linux: perf, eBPF, SystemTap, and ktap
  • Solaris, illumos, FreeBSD: DTrace
  • Mac OS X: DTrace and Instruments
  • Windows: Xperf.exe

perf

perf(也称perf_events)是 Linux kernal 自带的系统性能分析工具,能够进行函数级与指令级的热点查找。它基于事件采样原理,以性能事件为基础,支持针对处理器相关性能指标与操作系统相关性能指标的性能剖析,常用于性能瓶颈的查找与热点代码的定位。

我的测试机器:

$ uname -a
Linux shimo-develop 4.4.0-62-generic #83~14.04.1-Ubuntu SMP Wed Jan 18 18:10:30 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

注意:非 Linux 用户可以不用往下看了,目前只在 ubuntu 下测试通过。

安装 perf:
$ sudo apt-get install linux-tools-common
$ perf # 根据提示安装对应内核版本的 tools, 如下
$ sudo apt-get install linux-tools-4.4.0-62-generic

创建测试程序 test/app.js:

'use strict';

const crypto = require('crypto');
const express = require('express');
const app = express();

const users = {};

app.get('/newUser', function (req, res) {
  let username = req.query.username || '';
  let password = req.query.password || '';

  username = username.replace(/[!@#$%^&*]/g, '');

  if (!username || !password || users.username) {
    return res.sendStatus(400);
  }

  let salt = crypto.randomBytes(128).toString('base64');
  let hash = crypto.pbkdf2Sync(password, salt, 10000, 512);

  users[username] = {
    salt: salt,
    hash: hash
  };

  res.sendStatus(200);
});

app.get('/auth', function (req, res) {
  let username = req.query.username || '';
  let password = req.query.password || '';

  username = username.replace(/[!@#$%^&*]/g, '');

  if (!username || !password || !users[username]) {
    return res.sendStatus(400);
  }

  let hash = crypto.pbkdf2Sync(password, users[username].salt, 10000, 512);

  if (users[username].hash.toString() === hash.toString()) {
    res.sendStatus(200);
  } else {
    res.sendStatus(401);
  }
});

app.listen(3000);

添加 --perf_basic_prof(或者--perf-basic-prof)参数运行此程序,对应会生成一个 /tmp/perf-PID.map 的文件。如下:


$ node --perf_basic_prof test/app.js &
[1] 22486
$ tail /tmp/perf-22486.map
49f3fada560 418 RegExp:\bCHILD_PROCESS\b
49f3fada9e0 2ce Stub:FastNewContextStub
49f3fadad20 1494 Function:~ internal/child_process.js:1
49f3fadc220 9c Script:~internal/child_process.js
49f3fadc320 3cc Function:~ internal/socket_list.js:1
49f3fadc760 9c Script:~internal/socket_list.js
49f3fadc860 f Stub:BinaryOpICWithAllocationSiteStub(ADD_CreateAllocationMementos:String*String->String)
49f3fadc8e0 60 Handler:domain
49f3fadc9a0 44 Handler:_events

三列依次为:16进制符号地址(symbol addresses)、大小(sizes)和符号名(symbol names)。perf 会尝试查找 /tmp/perf-PID.map 文件,用来做符号转换,即把16进制符号地址转换成人能读懂的符号名。类似于前端的 .map 文件,做了一个映射。

注意:--perf_basic_prof 在 node@0.11.13 引入,所以确保 node 大于此版本。


注意:--perf_basic_prof_only_functions 参数也可以,但我尝试后发现生成的火焰图信息不全,后来还是改用 --perf_basic_prof。用 --perf_basic_prof 会导致 map 文件一直增大,原因可能是符号(symbols)不断变换地址导致的,用 --perf_basic_prof_only_functions 可以缓解这个问题,这个还是要读者自己去尝试。

然后 clone 用来生成火焰图的工具,放到与 test 平级的目录下:

$ git clone http://github.com/brendangregg/FlameGraph

在运行 perf 前,我们先用 ab 模拟压力访问:

$ curl "http://localhost:3000/newUser?username=shimo&password=123456"
$ ab -k -c 20 -n 250 "http://localhost:3000/auth?username=shimo&password=123456"

结果用了 56s:

Server Software:
Server Hostname:        localhost
Server Port:            3000

Document Path:          /auth?username=shimo&password=123456
Document Length:        2 bytes

Concurrency Level:      10
Time taken for tests:   55.857 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      51500 bytes
HTML transferred:       500 bytes
Requests per second:    4.48 [#/sec] (mean)
Time per request:       2234.261 [ms] (mean)
Time per request:       223.426 [ms] (mean, across all concurrent requests)
Transfer rate:          0.90 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       0
Processing:   269 2195 226.9   2220    2423
Waiting:      269 2195 226.9   2220    2423
Total:        269 2195 226.8   2220    2423

Percentage of the requests served within a certain time (ms)
  50%   2220
  66%   2252
  75%   2265
  80%   2272
  90%   2293
  95%   2307
  98%   2372
  99%   2378
 100%   2423 (longest request)

新开另一个窗口,在 ab 压测之后立即运行 perf record:


$ sudo perf record -F 99 -p 22486 -g -- sleep 60
$ sudo chown root /tmp/perf-22486.map
$ sudo perf script > test_out.perf
$ ./FlameGraph/stackcollapse-perf.pl --kernel < ./test_out.perf | ./FlameGraph/flamegraph.pl --color=js --hash> ./test_out.svg
有几点需要解释一下:
  • perf record
    • -F 指定了采样频率
    • -p 指定进程的 pid
    • -g 启用 call-graph 记录
    • -- sleep 60 指定记录 60s
  • sudo chown root /tmp/perf-22486.map
    • 将 map 文件更改为 root 权限,否则会报这个错:
      File /tmp/perf-PID.map not owned by current user or root, ignoring it (use -f to override).
      Failed to open /tmp/perf-PID.map, continuing without symbols
      
  • perf record 会将记录的信息保存到当前执行目录的 perf.data 文件里,用 perf script 将信息 dump 到 test_out.perf
  • --color=js 指定生成针对 js 配色的 svg,即:green == JS, aqua == built-ins, yellow == C++, red == system (native user-level, and kernel)

将 test_out.svg 用 rsync 或者其他工具同步到本机。用浏览器打开,如下所示:


理解火焰图

火焰图含义:

  • 每一个小块代表了一个函数在栈中的位置(即一个栈帧)
  • Y 轴代表了栈的深度(栈上的帧数),顶端的小块显示了占据 CPU 的函数。每个小块下面是它的祖先(即父函数),就像我们经常提的 js 调用栈
  • X 轴表示总的样例群体。它不像绝大多数图表那样从左到右表示时间的流逝,它们的左右顺序没有特殊含义(仅仅是按照字母表顺序排列)
  • 小块的宽度表示 CPU 使用时间或者说相对父函数而言使用 CPU 的比率(基于所有样例),越宽代表占用 CPU 的时间越长,或者使用 CPU 很频繁
  • 如果采取多线程并发运行取样,取样数量会超过运行时间

从上图可以看出:最上的绿色小块(即 js 代码)指向 tset/app.js:30 行,即 app.get('/auth') 这个路由,再往上看,蓝色小块(built-in 代码)可以看到 crypto.js 的 pbkdf2Sync 函数占据所有的宽度,即占据了 app.get('/auth') 几乎所有的 CPU 时间。

解决方法:将同步改为异步,即将 crypto.pbkdf2Sync 改为 crypto.pbkdf2,如下所示:

app.get('/auth', function auth(req, res) {
  let username = req.query.username || '';
  let password = req.query.password || '';

  username = username.replace(/[!@#$%^&*]/g, '');

  if (!username || !password || !users[username]) {
    return res.sendStatus(400);
  }

  crypto.pbkdf2(password, users[username].salt, 10000, 512, function(err, hash) {
    if (users[username].hash.toString() === hash.toString()) {
      res.sendStatus(200);
    } else {
      res.sendStatus(401);
    }
  });
});

用 ab 重新压测,结果用了 20s:

Server Software:
Server Hostname:        localhost
Server Port:            3000

Document Path:          /auth?username=shimo&password=123456
Document Length:        2 bytes

Concurrency Level:      20
Time taken for tests:   19.738 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      51500 bytes
HTML transferred:       500 bytes
Requests per second:    12.67 [#/sec] (mean)
Time per request:       1579.001 [ms] (mean)
Time per request:       78.950 [ms] (mean, across all concurrent requests)
Transfer rate:          2.55 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.2      0       1
Processing:   247 1522 284.6   1525    2188
Waiting:      247 1522 284.5   1525    2188
Total:        247 1522 284.4   1525    2188

Percentage of the requests served within a certain time (ms)
  50%   1525
  66%   1625
  75%   1679
  80%   1715
  90%   1869
  95%   1940
  98%   1991
  99%   2036
 100%   2188 (longest request)

重新生成的火焰图如下:

可以看出:在左侧只有极窄的栈可以看到 js 的代码,红色的部分我们不关心也无法优化。那为什么异步比同步的 rps 要高呢?从上图中可以看出,其实底层是 libuv 起了多个线程做计算任务,这里就不再深入介绍。

svg 火焰图其他小技巧:

  1. 点击任意一个小块可以『展开』,即被点击的小块宽度变宽,它的子函数也按比例变宽,方便查看。
  2. 可点击 svg 右上角的 search 按钮。高亮想要搜索的关键词,在有目的查找某个函数时比较有用。

彩蛋:封面图是石墨线上 api 采样 1h 数据产生的火焰图。

红蓝差分火焰图

虽然我们有了火焰图,但要处理性能回退问题,就要在修改代码前后的火焰图之间,不断切换对比,来找出问题所在。于是 Brendan D. Gregg 又发明了红蓝差分火焰图(red/blue differential flame graphs)。
如上所示:红色表示增长,蓝色表示衰减。

红蓝差分火焰图工作原理:

  1. 抓取修改前的栈 profile1 文件
  2. 抓取修改后的栈 profile2 文件
  3. 使用 profile2 来生成火焰图(这样栈帧的宽度就是以 profile2 文件为基准的)
  4. 使用 “2 - 1” 的差异来对火焰图重新上色。上色的原则是,如果栈帧在 profile2 中出现出现的次数更多,则标为红色,否则标为蓝色。色彩是根据修改前后的差异来填充的。

这样,通过红蓝差分火焰图,我们可以清楚地看到系统性能差异之处。

生成红蓝差分火焰图:

  1. 修改代码前:
    $ sudo perf record -F 99 -p PID -g -- sleep 60
    $ sudo chown root /tmp/perf-PID.map
    $ sudo perf script > test_out.stacks1
    
  2. 修改代码后:
    $ sudo perf record -F 99 -p PID -g -- sleep 60
    $ sudo chown root /tmp/perf-PID.map
    $ sudo perf script > test_out.stacks2
    
  3. 将 profile 文件进行折叠(fold), 再生成差分火焰图:
    $ ./FlameGraph/stackcollapse-perf.pl ./test_out.stacks1 > test_out.folded1
    $ ./FlameGraph/stackcollapse-perf.pl ./test_out.stacks2 > test_out.folded2
    $ ./FlameGraph/difffolded.pl test_out.folded1 test_out.folded2 | ./FlameGraph/flamegraph.pl > test_diff2.svg
    

不足之处:如果一个代码执行路径完全消失了,那么在火焰图中就找不到地方来标注蓝色。你只能看到当前的 CPU 使用情况,而不知道为什么会变成这样。

一个办法是,生成一个相反的差分火焰图,即基于 profile1 生成 “1 - 2” 的差分火焰图。对应命令如下:

$ ./FlameGraph/difffolded.pl test_out.folded2 test_out.folded1 | ./FlameGraph/flamegraph.pl --negate > test_diff1.svg

--negate 用于颠倒红/蓝配色。最终我们得到:

  • test_diff1.svg: 宽度是以修改前 profile 文件为基准,颜色表明将要发生的情况
  • test_diff2.svg: 宽度是以修改后 profile 文件为基准,颜色表明已经发生的情况

结论:红蓝差分火焰图可能只在代码变化不大的情况下使用效果明显,代码变化多了效果可能并不明显。上面的测试用例,生成的红蓝差分火焰图并没有卵用。。

eBPF+BCC

eBPF(enhanced Berkeley Packet Filter)- Linux eBPF Tracing Tools

BCC(BPF Compiler Collection)- iovisor/bcc

eBPF 是近几年新兴的 Linux 内核级分析工具,更安全更强大。有兴趣的读者可以持续关注 Brendan D. Gregg 的博客。


参考链接

推荐阅读

动态追踪技术漫谈 Brendan D. Gregg
文章被以下专栏收录
1 条评论
推荐阅读