0%

一次node进程cpu负载高问题的处理

1 node进程负载高的问题

  • 线上有个用node开发的uhost-manager的服务。每个set内会有多台物理机,每台物理机(宿主机)上存在着1台或者多台虚拟机。uhost-manager里有个定时逻辑:每隔30s,从MongoDB里拉取所有的虚拟机的记录,数量为2000多台;将位于同一台宿主机上的虚拟机资源,包括cpu、内存、磁盘容量等,做个sum,将sum再填入对应宿主机(共200多台)的记录里,表示已经被占用的资源。
  • 由于计算量大,和代码写得差,导致在该定时的计算任务执行时,会把占用的cpu单核打满;如果uhost-manager此时又有其他接口被调用时,就会出现响应慢的问题,导致调用方的服务也响应慢,甚至会因超时导致服务接口不可用。

这个单核打满持续的时间短,在1s左右。

2 问题的解决

为了解决这个问题,带来两个要思考的问题:

  • 解决方法 –> 怎么改进代码
  • 怎么衡量改进的效果 –>
    因为负载高的时间短,统计实时cpu负载,想到的命令只有top,但top命令本身无法做到统计,加入单核打满时间从1秒降到0.9秒,是无法凭肉眼感知的;像ps、vmstat等,也都不满足统计某个进程的实时负载

2.1 统计进程占用的cpu运行时间

/proc//stat该文件包含了某一进程所有的活动的信息,该文件中的所有值都是从系统启动开始累计到当前时刻。

1
2
# cat /proc/17273/stat
17273 (node) R 1369 17273 17273 0 -1 4218880 12446677 0 2 0 380634 40519 0 0 20 0 6 0 3525562392 964878336 38584 18446744073709551615 4194304 5593643 140724209068064 140400647923040 140400819234755 0 0 4096 16898 0 0 0 17 1 0 0 3 0 0 7692288 7703720 35180544 140724209071315 140724209071434 140724209071434 140724209074154 0

这样看非常不直观,通过网上找的一段小代码procstat[1],以人类可读的方式显示。

1
2
3
4
5
6
7
8
9
10
11
[root@172-30-38-65 uhost-manager.logs]# procstat 17273
pid: 17273
tcomm: (node)
...
utime: 3818.830000
stime: 406.260000
cutime: 0.000000
cstime: 0.000000
...
start_time: 07.13 03:00 (77599.65s)
...

进程的总Cpu时间processCpuTime = utime + stime + cutime + cstime,该值包括其所有线程的cpu时间[2]。注:这里统计出来的单位不是s,是相对于clock ticks来说的[3]。

我们的衡量手段为统计一段时间内新增的该进程的cpu时间;该值越小,表示运行时间越短。

具体步骤如下:

  • 以其他端口,再起一个uhost-manager服务,防止被其他服务调用;
  • 另外,定时任务里只保留定时更新宿主机占用资源的接口( smi_update_host_resource )。
  • 为了使统计的cpu占用时间长一点,smi改成每5秒执行一次;总共统计60s。查看新增的cpu时间,processCpuTime_60s - processCpuTime_0s。

2.2 解决方法

为了解决,需要知道消耗cpu性能的环节在哪些步骤上,好进一步优化。

2.2.1 perf

1
perf top -g -p 26642 -d 1  #此时uhost-manager pid为26642

这里看起来不直观,并不能看清楚是哪个操作引起的。

2.2.2 FlameGraph

火焰图的方式比较直观,这里测试下效果。

  • 采集脚本: perf record -F 99 -p 26642 -g – sleep 60

参数说明如下:

采集频率(ms) 进程pid 调用记录 记录时长
-F 99 -p 26642 -g –sleep 60
  • 进程对应的符号表perf-pid.map权限设置:$chown root /tmp/perf-pid.map。

踩过的坑!!!是为了消除下面这个问题的

1
2
File /tmp/perf-PID.map not owned by current user or root, ignoring it (use -f to override).
Failed to open /tmp/perf-PID.map, continuing without symbols
  • FlameGraph使用方式如下:
1
2
3
4
5
git clone https://github.com/brendangregg/FlameGraph.git
cd FlameGraph
perf script -i perf.data &> perf.unfold # 以下几个命令都是在FlameGraph目录下执行的
perl stackcollapse-perf.pl perf.unfold &> perf.folded
perl flamegraph.pl perf.folded > perf.svg
  • 火焰图效果

火焰图中看到libv8.so.3.14.5是消耗cpu最多的,但底下的方块(父函数)是unknown,所以还是无法知晓是哪里调用的。

火焰图形状对应关系

形状 含义
每一个平面方块 一个函数在栈中的位置(也称一个栈帧)
Y轴 栈的深度(也叫栈的帧数)
X轴 表示总的样例,不过它们左右顺序没有特殊含义
每个平面方块的宽度 方块的宽度标示CPU使用时间或者说相对父函数而言使用CPU的比率,越宽代表占用CPU的时间越长,或者使用CPU很频繁

2.2.3 原始的分析代码方式(肉眼看)

以上手段不起作用后,只能逐行分析代码,看哪里可能消耗的cpu多,然后优化掉。

原始的消耗时间

先按照2.1中的采集uhost-manager进程在60s内消耗的cpu时间,为10.65。这里的时间采集是5次测量,然后取平均值。

lean

从MongoDB里读取数据时,用到mongoose的模块。使用lean可以加快查询速度。

The lean option tells Mongoose to skip hydrating the result documents. This makes queries faster and less memory intensive, but the result documents are plain old JavaScript objects (POJOs), not Mongoose documents.

If you’re executing a query and sending the results without modification to, say, an Express response, you should use lean. In general, if you do not modify the query results and do not use custom getters, you should use lean(). If you modify the query results or rely on features like getters or transforms, you should not use lean().

测试下来结果为6.5,降低了40%左右,效果明显。

减少无用的重复执行的语句

修改之后,测试下来结果为5.3。

减少日志打印

减少量大的无用的日志打印后,测试下来结果为1.9。所以日志打印的cpu消耗在原始基础上占了32%,即(5.3-1.9)/10.65。

1
2
3
4
5
// 每台虚机打印下vcpu的个数,>2000
GLOBAL.logger.info(_vcpus);

// 每台宿主机打印下host_id, >200
GLOBAL.logger.info("[SMI]check:", host_ids[i]);

3 优化效果

经过优化后,消耗时间是1.9 clock ticks,相对于原来的10.65 clock ticks,减少了82.16%。

单核峰值CPU消耗为70%左右,且持续时间很短,为100ms左右。

参考链接

  1. procstat - displays linux proc stat (/proc/pid/stat) in human-readable format
  2. Linux环境下进程的CPU占用率
  3. Linux Programmer’s Manual PROC(5)
  4. NodeJS 性能优化之 CPU 看图篇
  5. Linux性能调优工具perf的使用
  6. 某个应用的 CPU 使用率居然达到 100%,我该怎么办?
  7. Faster Mongoose Queries With Lean