从零搭建 Node.js 企业级 Web 服务器(十三):断点调试与性能分析

断点调试

Node.js 官方提供了断点调试机制,出于安全性考虑默认为关闭状态,可以通过 node 参数 --inspect--inspect-brk 开启,配合 IDE 能够非常方便地调试代码,本章就上一章已完成的项目 host1-tech/nodejs-server-examples - 12-rpc 基于 Visual Studio Code 进行断点调试:

$ mkdir .vscode # 新建 .vsocde 目录存放 vscode 工作空间级配置

$ tree -L 1 -a  # 展示包括 . 开头的全部目录内容结构
.
├── .dockerignore
├── .env
├── .env.local
├── .env.production.local
├── .npmrc
├── .sequelizerc
├── .vscode
├── Dockerfile
├── database
├── node_modules
├── package.json
├── public
├── scripts
├── src
└── yarn.lock

创建 .vscode/launch.json(方法有很多种,此处不再展开):

// .vscode/launch.json
{
  // Use IntelliSense to learn about possible attributes.
  // Hover to view descriptions of existing attributes.
  // For more information, visit: https://go.microsoft.com/fwlink/?linkid=830387
  "version": "0.2.0",
  "configurations": [
    {
      "name": "Attach by Process ID",
      "processId": "${command:PickProcess}",
      "request": "attach",
      "skipFiles": ["<node_internals>/**"],
      "type": "pwa-node"
    }
  ]
}

启动参数 --inspect--inspect-brk 都可以开启调试状态,相比而言,后者在 Node.js 程序启动时立即进入断点等待,给了开发者调试启动过程的机会,本章采用 --inspect-brk 写入调试入口:

// package.json
{
  "name": "13-debugging-and-profiling",
  "version": "1.0.0",
  "scripts": {
    "start": "node -r ./scripts/env src/server.js",
+    "start:inspect": "node --inspect-brk -r ./scripts/env src/server.js",
    "start:prod": "cross-env NODE_ENV=production node -r ./scripts/env src/server.js",
    "sequelize": "sequelize",
    "sequelize:prod": "cross-env NODE_ENV=production sequelize",
    "build:yup": "rollup node_modules/yup -o src/moulds/yup.js -p @rollup/plugin-node-resolve,@rollup/plugin-commonjs,rollup-plugin-terser -f umd -n 'yup'"
  },
  // ...
}

接下来通过 yarn start:inspect 启动程序并使用 Visual Studio Code 进行断点调试:

$ yarn start:inspect | yarn bunyan -o short
# ...
Debugger listening on ws://127.0.0.1:9229/35a82bee-093c-491d-9d54-4cca9a142cbf
For help, see: https://nodejs.org/en/docs/inspector

f37440bf31eb599135efeb171cc0fcdf6ff7fac8.jpg

性能分析

服务器的性能瓶颈根据应用场景不同通常不尽相同,但最常见的性能瓶颈主要出现在并发量上,其中,每秒请求数(简称 RPS)便是衡量并发量的主要指标,为了方便对照参考,先对淘宝首页进行 RPS 测试:

$ yarn add -D autocannon # 本地安装 RPS 测试工具 autocannon
# ...
info Direct dependencies
└─ autocannon@5.0.1
# ...

$ yarn autocannon https://www.taobao.com/ # 对淘宝首页发起 RPS 测试
# ...
Running 10s test @ https://www.taobao.com/
10 connections

┌─────────┬───────┬───────┬────────┬────────┬───────────┬──────────┬───────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5%  │ 99%    │ Avg       │ Stdev    │ Max       │
├─────────┼───────┼───────┼────────┼────────┼───────────┼──────────┼───────────┤
│ Latency │ 36 ms │ 90 ms │ 267 ms │ 523 ms │ 106.68 ms │ 70.25 ms │ 586.13 ms │
└─────────┴───────┴───────┴────────┴────────┴───────────┴──────────┴───────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev  │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼────────┼─────────┤
│ Req/Sec   │ 81      │ 81      │ 95      │ 99      │ 92.7    │ 5.18   │ 81      │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼────────┼─────────┤
│ Bytes/Sec │ 9.93 MB │ 9.93 MB │ 11.6 MB │ 12.1 MB │ 11.4 MB │ 636 kB │ 9.93 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴────────┴─────────┘

Req/Bytes counts sampled once per second.

927 requests in 10.07s, 114 MB read

淘宝拥有一套非常完善的负载均衡策略,以上数据不能代表整个集群的并发量,但是一定程度上代表了单个容器的数值,RPS 均值 92.7。

现在再测试一下自己的服务器,

通过浏览器登录获取 Cookie 中的会话 ID:

0cba81803147903255fc64e107f582281ba4b666.jpg

对自己的服务器首页发起 RPS 测试:

$ # 对自己的服务器首页发起 RPS 测试
$ yarn autocannon -H 'Cookie: connect.sid=s%3AY2A4lo84OOtXCYgc3LRft03HtRaC4ieZ.kW%2BJlJIhSUQTOCxpREjtByDm8QmmA%2FPsNvddYQSP1fM' http://localhost:9000/
# ...
Running 10s test @ http://localhost:9000/
10 connections

┌─────────┬────────┬────────┬────────┬────────┬───────────┬──────────┬───────────┐
│ Stat    │ 2.5%   │ 50%    │ 97.5%  │ 99%    │ Avg       │ Stdev    │ Max       │
├─────────┼────────┼────────┼────────┼────────┼───────────┼──────────┼───────────┤
│ Latency │ 122 ms │ 197 ms │ 276 ms │ 306 ms │ 197.71 ms │ 38.14 ms │ 343.02 ms │
└─────────┴────────┴────────┴────────┴────────┴───────────┴──────────┴───────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev  │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼────────┼─────────┤
│ Req/Sec   │ 46      │ 46      │ 50      │ 57      │ 50.1    │ 2.92   │ 46      │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼────────┼─────────┤
│ Bytes/Sec │ 44.2 kB │ 44.2 kB │ 48.1 kB │ 54.8 kB │ 48.1 kB │ 2.8 kB │ 44.2 kB │
└───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴────────┴─────────┘

Req/Bytes counts sampled once per second.

501 requests in 10.06s, 481 kB read

发现 RPS 均值仅有 50.1,怀疑存在性能瓶颈。这里使用 0x 采集生成火焰图来定位问题,安装 0x 并写入启动入口:

$ yarn add -D 0x # 本地安装 0x
# ...
info Direct dependencies
└─ 0x@4.9.1
info All dependencies
# ...
// package.json
{
  "name": "13-debugging-and-profiling",
  "version": "1.0.0",
  "scripts": {
    "start": "node -r ./scripts/env src/server.js",
    "start:inspect": "node --inspect-brk -r ./scripts/env src/server.js",
+    "start:profile": "0x -- node -r ./scripts/env src/server.js",
    "start:prod": "cross-env NODE_ENV=production node -r ./scripts/env src/server.js",
    "sequelize": "sequelize",
    "sequelize:prod": "cross-env NODE_ENV=production sequelize",
    "build:yup": "rollup node_modules/yup -o src/moulds/yup.js -p @rollup/plugin-node-resolve,@rollup/plugin-commonjs,rollup-plugin-terser -f umd -n 'yup'"
  },
  // ...
}

通过 yarn start:profile 启动服务器并改用 60 秒测试 RPS,测试时间越长噪音越小:

# Tab 1
$ yarn start:profile | yarn bunyan -o short
🔥  Profiling
# ...
# Tab 2
$ # 对自己的服务器首页发起 RPS 测试
$ yarn autocannon -d 60 -H 'Cookie: connect.sid=s%3AY2A4lo84OOtXCYgc3LRft03HtRaC4ieZ.kW%2BJlJIhSUQTOCxpREjtByDm8QmmA%2FPsNvddYQSP1fM' http://localhost:9000/
# ...

关闭服务器并打开火焰图:

# Tab 1
$ yarn start:profile | yarn bunyan -o short
🔥  Profiling
# ...
^C
🔥  Waiting for subprocess to exit...
🔥  Flamegraph generated in ... 79929.0x/flamegraph.html

$ open 79929.0x/flamegraph.html # 用浏览器打开 *.0x 目录下的 flamegraph.html 文件

火焰图是根据程序的栈的状态对出现函数的采样数据统计而得,宽度代表函数运行一次所需的时长、高度代表栈的层数、颜色深度代表函数在采样中出现的频率,因此宽度最长颜色最深的方块对性能影响最大。0x 生成的火焰图默认以 *~ 符号区别展示了 V8 优化过的函数与未优化的函数,通过点击 Merge 合并两者(0x 生成的火焰图界面详情参考 0x UI):

b515e414cbb2755575bfbdf823d65cf87c197482.jpg

分析发现 sequelize 的 Model#findOne 方法被 express-session 大量调用,推断可能是 connect-session-sequelize 作为 express-session 的 store 引起的,因此尝试以 redis 作为会话缓存进行优化:

$ yarn add redis connect-redis # 本地安装 redis、connect-redis
# ...
info Direct dependencies
├─ connect-redis@5.0.0
└─ redis@3.0.2
# ...

$ # 以镜像 redis:6.0.6 启动 redis 服务,命名为 redis6
$ docker run -p 6379:6379 -d --name redis6 redis:6.0.6
// src/config/index.js
// ...
const config = {
  // 默认配置
  default: {
    // ...
+
+    redisOptions: {
+      host: 'localhost',
+      port: 6379,
+    },
  },
  // ...
};
// ...
# .env
LOG_LEVEL='debug'

GRPC_TRACE='all'
GRPC_VERBOSITY='DEBUG'
+
+WITH_REDIS=1
// src/middlewares/session.js
const session = require('express-session');
const sessionSequelize = require('connect-session-sequelize');
+const redis = require('redis');
+const sessionRedis = require('connect-redis');
const { sequelize } = require('../models');
-const { sessionCookieSecret, sessionCookieMaxAge } = require('../config');
+const {
+  redisOptions,
+  sessionCookieSecret,
+  sessionCookieMaxAge,
+} = require('../config');
+const { name } = require('../../package.json');

module.exports = function sessionMiddleware() {
-  const SequelizeStore = sessionSequelize(session.Store);
-
-  const store = new SequelizeStore({
-    db: sequelize,
-    modelKey: 'Session',
-    tableName: 'session',
-  });
+  let store;
+
+  if (process.env.WITH_REDIS) {
+    const client = redis.createClient(redisOptions);
+    const RedisStore = sessionRedis(session);
+    store = new RedisStore({ client, prefix: name });
+  } else {
+    const SequelizeStore = sessionSequelize(session.Store);
+    store = new SequelizeStore({
+      db: sequelize,
+      modelKey: 'Session',
+      tableName: 'session',
+    });
+  }

  return session({
    secret: sessionCookieSecret,
    cookie: { maxAge: sessionCookieMaxAge },
    store,
    resave: false,
    proxy: true,
    saveUninitialized: false,
  });
};

再次测试 RPS:

c9d5411643c38d466ffdfa6b7fefff523eb97c71.jpg

$ # 对自己的服务器首页发起 RPS 测试
$ yarn autocannon -H 'Cookie: connect.sid=s%3As4C-tLD4Xf8q3zjmtQ3k4B62mTZZNzfw.OdVLDs08H1YCXyZXIBgRuzE%2FE%2FH1BwDH4ynxEBNlKkg' http://localhost:9000/
# ...
Running 10s test @ http://localhost:9000/
10 connections

┌─────────┬──────┬──────┬───────┬───────┬─────────┬─────────┬─────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%   │ Avg     │ Stdev   │ Max     │
├─────────┼──────┼──────┼───────┼───────┼─────────┼─────────┼─────────┤
│ Latency │ 6 ms │ 9 ms │ 18 ms │ 20 ms │ 9.35 ms │ 3.25 ms │ 34.4 ms │
└─────────┴──────┴──────┴───────┴───────┴─────────┴─────────┴─────────┘
┌───────────┬────────┬────────┬────────┬─────────┬─────────┬────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%   │ Avg     │ Stdev  │ Min    │
├───────────┼────────┼────────┼────────┼─────────┼─────────┼────────┼────────┤
│ Req/Sec   │ 720    │ 720    │ 1035   │ 1190    │ 1014.82 │ 160.17 │ 720    │
├───────────┼────────┼────────┼────────┼─────────┼─────────┼────────┼────────┤
│ Bytes/Sec │ 692 kB │ 692 kB │ 995 kB │ 1.14 MB │ 975 kB  │ 154 kB │ 692 kB │
└───────────┴────────┴────────┴────────┴─────────┴─────────┴────────┴────────┘

Req/Bytes counts sampled once per second.

11k requests in 11.04s, 10.7 MB read

发现 RPS 均值提升到了 1003.89,表明推断正确。现在再使用 Node.js 内置的 cluster 机制提高 CPU 利用率进一步优化,此处注意合理设置 worker 数量,如果 worker 数量过高会因为操作系统过于频繁的调度反而降低性能:

# .env
LOG_LEVEL='debug'

GRPC_TRACE='all'
GRPC_VERBOSITY='DEBUG'

WITH_REDIS=1
+
+CLUSTERING=2
// src/server.js
+const os = require('os');
+const cluster = require('cluster');
const express = require('express');
const { resolve } = require('path');
const { promisify } = require('util');
const initMiddlewares = require('./middlewares');
const initControllers = require('./controllers');
const initSchedules = require('./schedules');
const initRpc = require('./rpc');
const logger = require('./utils/logger');

// ...
async function bootstrap() {
  // ...
}
// ...

-bootstrap();
+const useCluster = Boolean(process.env.CLUSTERING);
+
+if (useCluster && cluster.isMaster) {
+  const forkCount = parseInt(process.env.CLUSTERING) || os.cpus().length;
+
+  for (let i = 0, n = forkCount; i < n; i++) {
+    cluster.fork();
+  }
+
+  cluster.on('online', (worker) => {
+    logger.info(`> Worker ${worker.process.pid} is running`);
+  });
+
+  cluster.on('exit', (worker) => {
+    logger.info(`> Worker ${worker.process.pid} exited`);
+    process.exit(worker.process.exitCode);
+  });
+} else {
+  bootstrap();
+}

再次测试 RPS:

$ # 对自己的服务器首页发起 RPS 测试
$ yarn autocannon -H 'Cookie: connect.sid=s%3As4C-tLD4Xf8q3zjmtQ3k4B62mTZZNzfw.OdVLDs08H1YCXyZXIBgRuzE%2FE%2FH1BwDH4ynxEBNlKkg' http://localhost:9000/
# ...
Running 10s test @ http://localhost:9000/
10 connections

┌─────────┬──────┬──────┬───────┬───────┬─────────┬─────────┬──────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%   │ Avg     │ Stdev   │ Max      │
├─────────┼──────┼──────┼───────┼───────┼─────────┼─────────┼──────────┤
│ Latency │ 4 ms │ 7 ms │ 14 ms │ 17 ms │ 7.77 ms │ 2.74 ms │ 44.46 ms │
└─────────┴──────┴──────┴───────┴───────┴─────────┴─────────┴──────────┘
┌───────────┬────────┬────────┬─────────┬─────────┬─────────┬────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%     │ 97.5%   │ Avg     │ Stdev  │ Min    │
├───────────┼────────┼────────┼─────────┼─────────┼─────────┼────────┼────────┤
│ Req/Sec   │ 1009   │ 1009   │ 1209    │ 1430    │ 1208.41 │ 117.95 │ 1009   │
├───────────┼────────┼────────┼─────────┼─────────┼─────────┼────────┼────────┤
│ Bytes/Sec │ 970 kB │ 970 kB │ 1.16 MB │ 1.38 MB │ 1.16 MB │ 114 kB │ 970 kB │
└───────────┴────────┴────────┴─────────┴─────────┴─────────┴────────┴────────┘

Req/Bytes counts sampled once per second.

12k requests in 10.04s, 11.6 MB read

发现 RPS 均值已经达到 1208.41,并发量已稳达千级,符合期望。接下来再看一看数据库查询接口的 RPS 情况,测试 /api/shop

$ # 对自己的服务器 /api/shop 发起 RPS 测试
$ yarn autocannon -H 'Cookie: connect.sid=s%3ArGA44wXyem3dChGhc4PTIgAnyUJ8Dj2N.7hd9jyemRgD8CskqEUSjTGSSl%2FguJsKaAdienAyO7O8' http://localhost:9000/api/shop
# ...
Running 10s test @ http://localhost:9000/api/shop
10 connections

┌─────────┬───────┬───────┬───────┬───────┬──────────┬────────┬──────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5% │ 99%   │ Avg      │ Stdev  │ Max      │
├─────────┼───────┼───────┼───────┼───────┼──────────┼────────┼──────────┤
│ Latency │ 15 ms │ 23 ms │ 41 ms │ 46 ms │ 24.18 ms │ 6.7 ms │ 85.78 ms │
└─────────┴───────┴───────┴───────┴───────┴──────────┴────────┴──────────┘
┌───────────┬────────┬────────┬────────┬────────┬────────┬─────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%  │ Avg    │ Stdev   │ Min    │
├───────────┼────────┼────────┼────────┼────────┼────────┼─────────┼────────┤
│ Req/Sec   │ 361    │ 361    │ 399    │ 441    │ 404.9  │ 26.06   │ 361    │
├───────────┼────────┼────────┼────────┼────────┼────────┼─────────┼────────┤
│ Bytes/Sec │ 312 kB │ 312 kB │ 345 kB │ 381 kB │ 349 kB │ 22.5 kB │ 312 kB │
└───────────┴────────┴────────┴────────┴────────┴────────┴─────────┴────────┘

Req/Bytes counts sampled once per second.

4k requests in 10.05s, 3.49 MB read

/api/shop 的 RPS 均值为 404.9,已经接近单个 sqlite 数据库所能提供的并发上限,符合期望。

考虑到 Node.js 的 cluster 机制在调试与分析时会带来许多不便,找到对应的启动入口使用环境变量关闭 cluster 机制:

// package.json
{
  "name": "13-debugging-and-profiling",
  "version": "1.0.0",
  "scripts": {
    "start": "node -r ./scripts/env src/server.js",
-    "start:inspect": "node --inspect-brk -r ./scripts/env src/server.js",
+    "start:inspect": "cross-env CLUSTERING='' node --inspect-brk -r ./scripts/env src/server.js",
-    "start:profile": "0x -- node -r ./scripts/env src/server.js",
+    "start:profile": "cross-env CLUSTERING='' 0x -- node -r ./scripts/env src/server.js",
    "start:prod": "cross-env NODE_ENV=production node -r ./scripts/env src/server.js",
    "sequelize": "sequelize",
    "sequelize:prod": "cross-env NODE_ENV=production sequelize",
    "build:yup": "rollup node_modules/yup -o src/moulds/yup.js -p @rollup/plugin-node-resolve,@rollup/plugin-commonjs,rollup-plugin-terser -f umd -n 'yup'"
  },
  // ...
}

本章源码

host1-tech/nodejs-server-examples - 13-debugging-and-profiling

更多阅读

从零搭建 Node.js 企业级 Web 服务器(零):静态服务
从零搭建 Node.js 企业级 Web 服务器(一):接口与分层
从零搭建 Node.js 企业级 Web 服务器(二):校验
从零搭建 Node.js 企业级 Web 服务器(三):中间件
从零搭建 Node.js 企业级 Web 服务器(四):异常处理
从零搭建 Node.js 企业级 Web 服务器(五):数据库访问
从零搭建 Node.js 企业级 Web 服务器(六):会话
从零搭建 Node.js 企业级 Web 服务器(七):认证登录
从零搭建 Node.js 企业级 Web 服务器(八):网络安全
从零搭建 Node.js 企业级 Web 服务器(九):配置项
从零搭建 Node.js 企业级 Web 服务器(十):日志
从零搭建 Node.js 企业级 Web 服务器(十一):定时任务
从零搭建 Node.js 企业级 Web 服务器(十二):远程调用
从零搭建 Node.js 企业级 Web 服务器(十三):断点调试与性能分析
从零搭建 Node.js 企业级 Web 服务器(十四):自动化测试
从零搭建 Node.js 企业级 Web 服务器(十五):总结与展望

阅读 1.1k

推荐阅读