关于javascript:从零搭建-Nodejs-企业级-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-4cca9a142cbfFor 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.1info 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,+    },  },  // ...};// ...

# .envLOG_LEVEL='debug'GRPC_TRACE='all'GRPC_VERBOSITY='DEBUG'++WITH_REDIS=1

// src/middlewares/session.jsconst 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 数量过高会因为操作系统过于频繁的调度反而升高性能：

# .envLOG_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/shop10 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

断点调试

性能剖析

本章源码

更多浏览