诊断 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 │

分析

系统负荷正常

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

node.js 的 CPU 占用过高

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

    参见 vmstatr

  • 中断数偏多

    参见 vmstatin

    有可能是网络 I/O 数过多引起,参见 sariseg/s oseg/s 列。

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

  • 上下文切换较多

    参见 vmstatcs

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

  • 用户模式下 CPU 占用过高

    超过 50%

    参见 vmstatus

  • 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 )进一步减少。