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

头像
乌柏木
    2.2k10
    发布于
    中国
     

    断点调试

    Node.js 官方提供了断点调试机制，出于安全性考虑默认为关闭状态，可以通过 node 参数 --inspect 或 --inspect-brk 开启，配合 IDE 能够非常方便地调试代码，本章就上一章已完成的项目 licg9999/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'"
  },
  // ...
}

    本章源码

    licg9999/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 服务器（十五）：总结与展望

    javascriptnode.js前端后端服务器
    本作品系原创，采用《署名-非商业性使用-禁止演绎 4.0 国际》许可协议
    avatar

    认真写点好代码。

    2.2k 声望
    1.1k 粉丝
    0 条评论
    得票最新
    推荐阅读
    Transpile Webpack Plugin：让 Webpack 按照源文件的目录结构输出
    作为 Web 开发者，你是否也纠结过如何用 Webpack 做文件转译？就像 Babel CLI 转译文件那样按照源文件的目录结构输出？如果有，那么这篇文章就是为你而写，我们一起瞧一瞧怎么做吧。

    乌柏木赞 5阅读 932

    正则表达式实例
    收集在业务中经常使用的正则表达式实例，方便以后进行查找，减少工作量。常用正则表达式实例1. 校验基本日期格式 {代码...} {代码...} 2. 校验密码强度密码的强度必须是包含大小写字母和数字的组合，不能使用特殊...

    寒青赞 57阅读 8.7k评论 11

    JavaScript有用的代码片段和trick
    平时工作过程中可以用到的实用代码集棉。判断对象否为空 {代码...} 浮点数取整 {代码...} 注意：前三种方法只适用于32个位整数，对于负数的处理上和Math.floor是不同的。 {代码...} 生成6位数字验证码 {代码...} ...

    jenemy赞 49阅读 7.4k评论 12

    再也不学AJAX了！（二）使用AJAX ① XMLHttpRequest
    「再也不学 AJAX 了」是一个以 AJAX 为主题的系列文章，希望读者通过阅读本系列文章，能够对 AJAX 技术有更加深入的认识和理解，从此能够再也不用专门学习 AJAX。本篇文章为该系列的第二篇，最近更新于 2023 年 1...

    libinfs赞 42阅读 7k评论 12

    封面图
    CSS 绘制一只思否猫
    欢迎关注我的公众号：前端侦探练习 CSS 有一个比较有趣的方式，就是发挥想象，绘制各式各样的图案，比如来绘制一只思否猫？思否猫，SegmentFault 思否的吉祥物，是一只独一无二、特立独行、热爱自由的(&gt;^ω^&lt...

    XboxYan赞 48阅读 3.4k评论 14

    封面图
    「多图预警」完美实现一个@功能
    一天产品大大向 boss 汇报完研发成果和产品业绩产出，若有所思的走出来，劲直向我走过来，嘴角微微上扬。产品大大：boss 对我们的研发成果挺满意的，balabala...（内心 OS：不听，讲重点）产品大大：咱们的客服 I...

    wuwhs赞 32阅读 3.6k评论 5

    封面图
    还在用 JS 做节流吗？CSS 也可以防止按钮重复点击
    举个例子：一个保存按钮，为了避免重复提交或者服务器考虑，往往需要对点击行为做一定的限制，比如只允许每300ms提交一次，这时候我想大部分同学都会到网上直接拷贝一段throttle函数，或者直接引用lodash工具库

    XboxYan赞 35阅读 2.7k评论 2

    封面图
    avatar

    认真写点好代码。

    2.2k 声望
    1.1k 粉丝
    宣传栏
    3121