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

Z时代
2024-01-10
分类：技术分享

断点调试

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

性能分析

服务器的性能瓶颈根据应用场景不同通常不尽相同，但最常见的性能瓶颈主要出现在并发量上，其中，每秒请求数（简称 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：

对自己的服务器首页发起 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）：

分析发现 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：

$ # 对自己的服务器首页发起 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'" }, // ...

}