從零搭建 Node.js 企業級 Web 服務器（十三）：斷點調試與性能分析

時間  2020-08-07
標籤 搭建 node.js node 企業 web 服務器 十三 斷點 調試 性能 分析 欄目 Node.js 简体版
原文   原文鏈接

斷點調試

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

f37440bf31eb599135efeb171cc0fcdf6ff7fac8.jpg

性能分析

服務器的性能瓶頸根據應用場景不一樣一般不盡相同，但最多見的性能瓶頸主要出如今併發量上，其中，每秒請求數（簡稱 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：數據庫

0cba81803147903255fc64e107f582281ba4b666.jpg

對本身的服務器首頁發起 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）：

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'"
  },
  // ...
}

本章源碼

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 服務器（十三）：斷點調試與性能分析

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程