诊断 node.js 应用 CPU 占用过高的问题

node.js 应用使用 pm2 进行管理，采用 cluster 模式，每台服务器运行 16 个 node.js 实例。

应用的开销主要在网络上：

平均每个 node.js 实例要维持来自嵌入式设备的约 3K TLS 长连接，平均每秒会有 30 个来自客户端的 HTTP 短连接。

TLS 长连接上最多 45 秒会有一次心跳（发送 80 多字节，接收 400 多字节）。

系统信息

`CPU`

逻辑 CPU 数：24

# cat /proc/cpuinfo | grep name | cut -f2 -d: | uniq -c 
     24  Intel(R) Xeon(R) CPU E5-2620 v2 @ 2.10GHz

物理 CPU 数：2

# cat /proc/cpuinfo | grep 'physical id' | sort | uniq -c
     12 physical id : 0
     12 physical id : 1

每个物理 CPU 的核数：6

# cat /proc/cpuinfo | grep "cpu cores" | uniq | awk -F: '{print $2}'
 6

每个核超线程数：2

两个逻辑 CPU 具有相同的 core id 则超线程是打开的。

# cat /proc/cpuinfo | grep -E "physical id|core id" | sed -e ':a;N;$!ba;s/\ncore id\s*/       core id /g' | sort | uniq -c
      2 physical id : 0       core id : 0
      2 physical id : 0       core id : 1
      2 physical id : 0       core id : 2
      2 physical id : 0       core id : 3
      2 physical id : 0       core id : 4
      2 physical id : 0       core id : 5
      2 physical id : 1       core id : 0
      2 physical id : 1       core id : 1
      2 physical id : 1       core id : 2
      2 physical id : 1       core id : 3
      2 physical id : 1       core id : 4
      2 physical id : 1       core id : 5

参考：Linux CPU数量判断，通过/proc/cpuinfo._一沙一花_新浪博客

`内存`

64G 内存， 37.8G 空闲内存

# cat /proc/meminfo
MemTotal:       65916740 kB
MemFree:        39663756 kB
Buffers:          595424 kB
Cached:          7627876 kB
SwapCached:            0 kB
Active:         17368112 kB
Inactive:        6936088 kB
Active(anon):   16002524 kB
Inactive(anon):    80820 kB
Active(file):    1365588 kB
Inactive(file):  6855268 kB
Unevictable:          32 kB
Mlocked:              32 kB
SwapTotal:      20971512 kB
SwapFree:       20971512 kB
Dirty:              1896 kB
Writeback:             0 kB
AnonPages:      16081968 kB
Mapped:            19596 kB
Shmem:              1624 kB
Slab:            1087320 kB
SReclaimable:     756368 kB
SUnreclaim:       330952 kB
KernelStack:        5272 kB
PageTables:        64280 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:    53929880 kB
Committed_AS:   17348828 kB
VmallocTotal:   34359738367 kB
VmallocUsed:      436016 kB
VmallocChunk:   34324325464 kB
HardwareCorrupted:     0 kB
AnonHugePages:   2525184 kB
HugePages_Total:       0
HugePages_Free:        0
HugePages_Rsvd:        0
HugePages_Surp:        0
Hugepagesize:       2048 kB
DirectMap4k:        4096 kB
DirectMap2M:     2076672 kB
DirectMap1G:    65011712 kB

系统状态

top

# top -n 1
top - 13:05:48 up 144 days, 20:52,  2 users,  load average: 2.86, 2.46, 2.78
Tasks: 476 total,  19 running, 457 sleeping,   0 stopped,   0 zombie
Cpu(s): 22.7%us,  1.2%sy,  0.0%ni, 75.0%id,  0.0%wa,  0.0%hi,  1.1%si,  0.0%st
Mem:  65916740k total, 26237540k used, 39679200k free,   595424k buffers
Swap: 20971512k total,        0k used, 20971512k free,  7614508k cached

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND          
191463 nobody    20   0 1884m 981m 9.8m R 83.3  1.5  12337:09 node /usr/local  
192063 nobody    20   0 1905m 1.0g 9.8m R 73.6  1.6  12320:35 node /usr/local  
194450 nobody    20   0 1842m 937m 9.8m R 62.0  1.5  12060:56 node /usr/local  
191515 nobody    20   0 1911m 1.0g 9.8m R 60.1  1.6  12308:13 node /usr/local  
190881 nobody    20   0 1862m 957m 9.8m R 52.3  1.5  12257:46 node /usr/local  
195178 nobody    20   0 1795m 891m 9.8m R 52.3  1.4  11647:01 node /usr/local  
193068 nobody    20   0 1873m 970m 9.8m R 50.4  1.5  12144:28 node /usr/local  
194523 nobody    20   0 1805m 902m 9.8m R 50.4  1.4  11948:57 node /usr/local  
190790 nobody    20   0 1857m 951m 9.8m R 48.4  1.5  12174:59 node /usr/local  
191609 nobody    20   0 1847m 945m 9.8m R 48.4  1.5  12203:47 node /usr/local  
192946 nobody    20   0 1898m 993m 9.8m R 48.4  1.5  12224:41 node /usr/local  
193029 nobody    20   0 1827m 924m 9.8m R 48.4  1.4  12291:51 node /usr/local  
195276 nobody    20   0 1786m 883m 9.8m R 48.4  1.4  11659:07 node /usr/local  
196001 nobody    20   0 1885m 981m 9.8m R 48.4  1.5  11428:22 node /usr/local  
193725 nobody    20   0 1884m 978m 9.8m R 46.5  1.5  12336:34 node /usr/local  
 80300 root      20   0  611m 454m 1152 R 44.6  0.7  26523:40 redis-server     
195944 nobody    20   0 1815m 912m 9.8m R 44.6  1.4  11353:21 node /usr/local

vmstat

# vmstat 1
|----+---+------+----------+--------+---------+----+----+----+-------+--------+-------+----+----+----+----+----|
|  r | b | swpd |     free |   buff |   cache | si | so | bi |    bo |     in |    cs | us | sy | id | wa | st |
|----+---+------+----------+--------+---------+----+----+----+-------+--------+-------+----+----+----+----+----|
| 17 | 0 |    0 | 39769884 | 595424 | 7523076 |  0 |  0 |  0 |    71 |      0 |     0 | 23 |  2 | 75 |  0 |  0 |
|  9 | 0 |    0 | 39763800 | 595424 | 7528200 |  0 |  0 |  0 |  5188 | 108347 | 21186 | 53 |  5 | 41 |  0 |  0 |
| 17 | 0 |    0 | 39758360 | 595424 | 7534084 |  0 |  0 |  0 |  5272 | 106375 | 24054 | 49 |  5 | 45 |  0 |  0 |
| 15 | 0 |    0 | 39753912 | 595424 | 7538236 |  0 |  0 |  0 |  5252 | 107669 | 23522 | 50 |  5 | 44 |  0 |  0 |
| 12 | 0 |    0 | 39747588 | 595424 | 7544612 |  0 |  0 |  0 |  5304 | 108452 | 24290 | 49 |  5 | 46 |  0 |  0 |
| 15 | 0 |    0 | 39742744 | 595424 | 7548076 |  0 |  0 |  0 |  5200 | 106615 | 25614 | 47 |  5 | 48 |  0 |  0 |
| 13 | 0 |    0 | 39738224 | 595424 | 7552712 |  0 |  0 |  0 |  5092 | 101642 | 25482 | 44 |  5 | 51 |  0 |  0 |
|  9 | 0 |    0 | 39734116 | 595424 | 7559024 |  0 |  0 |  0 |  5156 |  98440 | 25393 | 42 |  5 | 53 |  0 |  0 |
| 16 | 0 |    0 | 39729280 | 595424 | 7564076 |  0 |  0 |  0 |  5204 | 108933 | 23535 | 49 |  5 | 45 |  0 |  0 |
| 18 | 0 |    0 | 39722832 | 595424 | 7568280 |  0 |  0 |  0 |  5276 | 111563 | 23965 | 51 |  5 | 44 |  0 |  0 |
|----+---+------+----------+--------+---------+----+----+----+-------+--------+-------+----+----+----+----+----|

sar

# sar -n TCP 1
01:58:46 PM  active/s passive/s    iseg/s    oseg/s
01:58:47 PM      3.09    875.26  32375.26  33619.59
01:58:48 PM      0.00    575.25  27972.28  28961.39
01:58:49 PM      0.00    879.59  31104.08  31933.67
01:58:50 PM      1.02    743.88  30183.67  31516.33
01:58:51 PM      0.00    793.94  31734.34  32761.62
01:58:52 PM      0.00    571.88  28690.62  29415.62
01:58:53 PM      1.02   1004.08  33157.14  33673.47
01:58:54 PM      0.99    954.46  33315.84  34532.67
01:58:55 PM      1.00    910.00  33562.00  34338.00
01:58:56 PM      1.02    783.67  31754.08  32412.24

应用状态

ps

# ps waux | grep node
nobody   190790 61.0  1.4 1902228 974408 ?      Rl   Apr20 12154:57 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   190881 61.4  1.4 1907188 980800 ?      Rl   Apr20 12237:31 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   191463 61.8  1.5 1929392 1005164 ?     Sl   Apr20 12317:05 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   191515 61.7  1.5 1957252 1030472 ?     Rl   Apr20 12287:48 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   191609 61.1  1.4 1891508 967896 ?      Rl   Apr20 12183:27 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   192063 61.7  1.5 1951056 1025216 ?     Rl   Apr20 12300:27 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   192946 61.3  1.5 1943880 1017796 ?     Rl   Apr20 12204:24 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   193029 61.6  1.4 1871180 946732 ?      Rl   Apr20 12271:35 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   193068 60.9  1.5 1918404 993536 ?      Rl   Apr20 12124:33 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   193725 61.8  1.5 1929488 1001552 ?     Rl   Apr20 12316:31 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   194450 60.5  1.4 1887224 960012 ?      Sl   Apr20 12040:16 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   194523 59.9  1.4 1848960 924596 ?      Rl   Apr20 11928:46 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   195178 58.4  1.3 1838980 913052 ?      Rl   Apr20 11627:32 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   195276 58.5  1.3 1829848 905212 ?      Rl   Apr20 11639:08 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   195944 56.9  1.4 1859316 933892 ?      Rl   Apr20 11333:25 node /usr/local/xxx.xxxxxxxx.com/src/index.js
nobody   196001 57.3  1.5 1930348 1004912 ?     Rl   Apr20 11408:17 node /usr/local/xxx.xxxxxxxx.com/src/index.js

pm2

# pm2 desc xxx.xxxxxxxx.com | grep 'Loop delay'
│ Loop delay │ 1.96ms │
│ Loop delay │ 2.01ms │
│ Loop delay │ 2.04ms │
│ Loop delay │ 2.3ms  │
│ Loop delay │ 1.76ms │
│ Loop delay │ 1.97ms │
│ Loop delay │ 2.12ms │
│ Loop delay │ 1.98ms │
│ Loop delay │ 2.16ms │
│ Loop delay │ 1.98ms │
│ Loop delay │ 2.07ms │
│ Loop delay │ 1.88ms │
│ Loop delay │ 2.61ms │
│ Loop delay │ 1.84ms │
│ Loop delay │ 1.84ms │
│ Loop delay │ 1.88ms │

分析

系统负荷正常

top 的 load average 值远小于 CPU 核数，系统的 CPU 使用率为 25%，还有足够的空闲 CPU 资源。

node.js 的 CPU 占用过高

运行和等待 CPU 时间片的进程数偏高

参见 vmstat 的 r 列

中断数偏多

参见 vmstat 的 in 列

有可能是网络 I/O 数过多引起，参见 sar 的 iseg/s oseg/s 列。

中断数虽多，但并非瓶颈，参见 top 的 %hi 和 %si 值。

上下文切换较多

参见 vmstat 的 cs 列

上下文切换数远小于中断数，正常。

用户模式下 CPU 占用过高

超过 50%

参见 vmstat 的 us 列
node.js 进程事件循环迟延小于 3ms

正常。应用目前还能够提供快速响应。
node.js 进程 CPU 占用过高

统计了一天平均占用 65%，高峰占用 85% 以上。

参见 ps 输出

应用本身是网络密集型，每 node.js 进程每秒钟处理 250 个请求，不存在 CPU 密集操作，这样高的 CPU 占用是不可接受的。

网络带宽占用正常

对外的网卡

上行 27Mbps，下行 66Mbps

主要是来自设备和客户端的流量。
对内的网卡

上行 18.7Mbps，下行 21.7Mbps

主要是内部通信流量（redis）。

磁盘访问较少

应用除了写少量日志外不访问磁盘。

结论

系统资源不存在瓶颈
系统当前的运行状况良好
node.js 应用的 CPU 占用偏高

需要对 node.js 应用进行性能分析及优化

node.js 应用性能分析

node.js 从 4.4.0 版本开始内置了 profiler， --prof 命令选项运行应用会在当前目录生成性能日志文件。

解读性能日志文件

# node --prof-process isolate-0x1d1e1b0-v8-10041.log
...
[Summary]:
   ticks  total  nonlib   name
    348    7.3%    7.6%  JavaScript
   4243   88.8%   92.4%  C++
     63    1.3%    1.4%  GC
    184    3.9%          Shared libraries
      2    0.0%          Unaccounted
...
 [C++ entry points]:
   ticks    cpp   total   name
    494   19.4%   10.3%  v8::internal::Runtime_DateCurrentTime(int, v8::internal::Object**, v8::internal::Isolate*)
...
   ticks parent  name
   1739   36.4%  syscall

    586   12.3%  __lll_lock_wait
    413   70.5%    v8::internal::Runtime_DateCurrentTime(int, v8::internal::Object**, v8::internal::Isolate*)
    398   96.4%      LazyCompile: *now native date.js:197:17
    305   76.6%        LazyCompile: *<anonymous> /usr/local/xxxxx.xxxxxxxx.com/src/models.js:43:30
...

最大头的时间花在系统调用上，通过 strace 工具统计 node.js 进程 10 秒钟的系统调用计数

12259 write
10501 read
 9261 epoll_ctl
 1564 epoll_wait
  503 close
  502 recvmsg
  502 getsockopt
  502 getsockname
  103 futex
   23 stat
    6 writev
    1 getpeername

系统调用主要进行网络 I/O ，如：与设备通信（TLS 长连接）、与客户端通信（HTTP 短连接）、与Redis通信（TCP 长连接）。

其它调用出现次数最多的是获取当前时间戳的函数 models.js:43：

function getTimestamp () {
    return Math.floor(Date.now() / 1000);
}

它会在很多地方被用到，如：当从 redis 收到一条订阅的消息时，会在消息中添加当前时间戳，方便后面处理。

可以通过缓存减少这部分开销：

function getTimestamp () {
    if (! getTimestamp._timestamp) {
        getTimestamp._timestamp = Math.floor(Date.now() / 1000);

        setInterval(function () {
            getTimestamp._timestamp = Math.floor(Date.now() / 1000);
        }, 1000).unref();
    }

    return getTimestamp._timestamp;
}
getTimestamp._timestamp = 0;

上面的代码，虽然调用次数相对较多，但并不耗 CPU，经过上面的优化后，总系统 CPU 占用只是略有减少。

关键的系统调用消耗难以再优化，在我们的应用中，node.js 单实例处理能力的上限：4K TLS 长连接（平均 CPU 占用 85%）。

最终决定，增加服务器上 node.js 进程的数量，node.js 最大连接数限制（ net.maxConnections ）进一步减少。

参考

理解Linux系统负荷 - 阮一峰的网络日志

Linux-Load Average解析(转) - java技术研究 - BlogJava

linux系统性能监控与优化（2）–cpu | 小鳄的笔记本

Easy profiling for Node.js Applications | Node.js