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'" }, // ... }
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 服务器(十三):断点调试与性能分析