关于javascript:从零搭建-Nodejs-企业级-Web-服务器十三断点调试与性能分析

24次阅读

共计 12496 个字符，预计需要花费 32 分钟才能阅读完成。

断点调试

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 服务器（十三）：断点调试与性能剖析

正文完
javascript
发表至： javascript
2020-08-06
 0
关于javascript:JavaScript-原型链详解
关于javascript:jQuery
关于javascript:typeScriptkoa2eslint搭建完整nodejs开发环境自建脚手架
关于javascript:借助-Proxy-刨析数组方法的底层逻辑-实现最原生的-splice-方法