从零搭建 Node.js 企业级 Web 服务器（十三）：断点调试与性能分析
断点调试
Node.js 官方提供了断点调试机制，出于安全性考虑默认为关闭状态，能够经过 node 参数 --inspect 或 --inspect-brk 开启，配合 IDE 可以很是方便地调试代码，本章就上一章已完成的项目 host1-tech/nodejs-server-examples - 12-rpc 基于 Visual Studio Code 进行断点调试：html
$ 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（方法有不少种，此处再也不展开）：node
// .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 写入调试入口：git
// 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 进行断点调试：github
$ 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 测试：redis
$ 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。sql
如今再测试一下本身的服务器，docker
经过浏览器登陆获取 Cookie 中的会话 ID：数据库
对本身的服务器首页发起 RPS 测试：express
$ # 对本身的服务器首页发起 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 并写入启动入口：npm
$ 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'"
},
// ...
}
本章源码
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 服务器（十三）：断点调试与性能分析