记一次生产环境的性能分析过程

Summary

本文主要记录了一次生产环境后台服务的性能分析过程，通过结合多种性能分析工具定位出系统的性能瓶颈并给出优化方案，将整个过程记录并总结如下。

1 提出问题

1.1 监控数据走查

在一次监控走查的过程中，发现一个后台服务的CPU使用率指标有一些异常，不太符合我们的预期，我们观察生产环境的容器：容器配置是4核8G，但是只有单个cpu的占用比较高，经常达到90%以上，通过top命令我们可以看到cpu0的user和sy占比很高，但cpu1-3 user很低，说明cpu1-3比较空闲（如图1）。由于TSP是用node开发的，是典型的master-worker多进程模型（如图2），即每个容器里有一个master进程和多个worker进程，master进程负责接收请求并转发给worker进程，然后由worker进程进行逻辑处理并给出响应，所以，为了让CPU更充分的得到利用，在容器中启动了跟CPU数量相同的worker进程。

图1 单个cpu负载较高

图2 master-worker架构

上面的结果与我们的预期有些偏差，我们原本的设想是：启动4个worker进程，每个worker运行在一个CPU上，这样能将CPU资源最大程度利用，但是从监控的数据上来看只有一个CPU在工作，这就让人产生一种：找了四个人来干活，但是所有活都是一个人在做的感觉。基于此，我们提出如下问题：

• 问题1：TSP是否能很好的利用多核资源？
• 问题2：TSP的逻辑很简单，主逻辑就是到redis取了一个数据，目前单机到QPS 在7000/s，是否还有优化的空间？

2 验证TSP能否利用多核

2.1 理论假设

在验证开始之前，我们先从node的master-worker多进程模型入手，做了一些理论假设：如果把整个API服务看作一个施工队，master就是包工头，主要负责监听某个端口接收网络请求，然后转发给worker；而worker负责处理每个网络请求并给出响应。我们预期的情况是：master应该均匀的把每个任务分配给worker，然后所有的worker并发的在多核上执行自己的任务，但是，如果master偏心，把所有的任务都分配给一个worker，导致其他worker手上都没有活干，这就有可能导致只有一个CPU忙的情况发生。基于这个假设，我们进行了如下验证：

2.1 分析node的进程模型

通过ps -ef来查看进程之间的关系，如图3所示，35号进程是51、54、58、65进程的父进程，根据node的多进程架构可以知道35是master进程，其余4个是进程是35的子进程，也就是worker进程，也就是说，35在收到请求后会把请求转发给51、54、58、65。进一步通过netstat -tnpl查看TCP端口的监听情况（如图4），整个容器只有35号的node进程监听8080这个端口，进一步确定了35是master的身份。确认了“每个人”的身份后，在看下master是否会“偏心”？

图3 进程模型

图4 netstat结果

2.2 master的转发是否均衡

根据top的结果（如图5）可以看出，51、54、58、65的user值很接近（user表示进程在用户态运行的时间），都是17%～18%左右，如果master把请求都转发给一个worker，则其他worker因为手上没有活是不会被CPU调度的，既然4个worker的user差不多，说明这4个woker都在干活，因此，master对于网络请求的转发是均衡的。但问题又来了，既然4个worker手上都有任务，为什么不能并行的调度到4个cpu上执行呢，为什么非得调度到一个cpu上执行呢？cpu的这种调度策略是否会导致多核资源无法利用呢？

图5 master转发均衡

2.3 压力测试

master转发不均匀的猜想不成立，我们又有另一个猜想：cpu的调度策略就是让一个cpu玩命用，实在不够用了再使用下一个cpu，因此现在看到一个cpu繁忙其他cpu空闲可能是因为要处理的任务还不够多，任务多了，一个cpu顶不住，其他的cpu自然会来帮忙。基于这个假设，我们又通过压测平台做了一组压力测试，结果如下：

QPS 1000/s（如图6），只有一个核繁忙但极本到了极限，其他核都空闲

图6 单核打满其他核空闲

QPS 2300/s（如图7），第一个核顶不住，第二个核开始帮忙分担压力

图7 单核打满第二个核开始帮忙

QPS 4000/s（如图8），第二个核也顶不住，第三个核开始帮忙分担压力

图8 双核打满第三个核开始帮忙

QPS 5000/s（图9），第三个核也顶不住，第四个核开始帮忙分担压力

图9 三核打满第四个核开始帮忙

QPS 7000/s（图10），所有核的资源都耗尽，性能达到瓶颈

图10 机器资源耗尽性能达到极限

基于上面的压力测试结果，可以得出结论：在压力足够的情况下，TSP可以利用多核资源，服务器的资源没有浪费。

3 性能是否还有优化空间

3.1 性能瓶颈

TSP的逻辑比较简单：就是给定一个project id（每个模块可以视为一个project，比如Account Health），查询对应的翻译，翻译数据存储在redis，因此，TSP的主逻辑就是从redis里面取一些数据，然后返回。redis的性能是很好的，而单机容器的qps只能达到7000，性能的瓶颈一定是在容器，性能是否还有优化的空间呢？这是一个比较复杂的问题，要想优化性能，首先要搞清楚cpu的时间都被用到哪里了。

3.2 CPU的时间分布

通过top命令查看每个进程的资源消耗情况（如图11），通过耗时分布来分析cpu的时间都用到哪了，可以看出：对于cpu0来说，76.5%的时间用在user，6.4%的时间用在sy，这说明绝大多数的cpu时间都用在处理用户态的业务逻辑上，只有少量的CPU用来处理内核逻辑；由于wa（IO wait）不高，因此等待IO的时间也不长。

图11 top执行结果

但是TSP的业务逻辑并不复杂，为什么会占用这么多cpu呢？有没有可能是网络IO过高导致cpu的时间都用在网络数据包的拷贝上了呢？

3.3 cpu时间是否消耗在网络IO的处理上

翻了一下飞哥的《深入理解Linux网络》，从网卡接收数据包的完整流程如下图所示：

图12 网卡收包流程

当有数据包到达网卡的时候，首先是DMA把数据包拷贝到内存的RingBuffer，此过程不需要cpu参与，然后是内核线程通过软中断的形式将数据包送入协议栈进行处理，处理完成后由cpu将数据包从内核的缓冲区拷贝到用户的进程空间，这个过程是会消耗cpu时间的。但是，这个过程是内核线程处理的，如果cpu的时间都用到网络IO的处理，则sy/si的值应该很大才对，但是sy/si的值相比us并不高，因此，cpu的时间没有消耗在网络IO的处理上。

3.4 分析系统调用

排除了网络IO占用cpu的可能，业务逻辑又不复杂，但是用户态cpu占用较高，因此推测可能是某些系统调用消耗了大量的cpu时间，因此，通过strace观察系统调用的情况，执行strace -cp pid命令，查看worker进程内部使用了哪些系统调用，结果如下，

图13 master进程的系统调用统计

可以看到futex的系统调用占用了30.57% cpu时间，进一步通过strace -tt -s 2048 -p pid分析futex是用在什么场景，如下图，

图14 futex的使用情况

发现futex总是出现在日志打印之后，因此可以认为futex跟日志打印有很大关联。奇怪的是，从代码上看，日志打印是在worker进程中做的，为什么会跑到master中来打印了呢？经过网上搜索发现，log4js在cluster模式下，默认会将woker打印的日志传递给master进行打印，因此，浪费cpu时间的罪魁祸首找到了，频繁的日志打印使得日志信息从wokers向master频繁的传递，导致futex的调用量急剧上升，消耗了大量cpu实践。

图15 worker进程的系统调用统计

可以看到，调用次数比较多的系统调用分别是：write、epoll_wait、epoll_ctl、read和futex，其中futex占比并不高，可以忽略。

3.5 去掉日志打印

去掉日志打印逻辑后，再观察master和woker的系统调用情况，看futex调用是否有减少。如下图，

图16 去掉打日志逻辑系统调用统计

可以看出futex的调用基本没有了。再通过压力测试来验证性能是否有改善，经测试发现峰值的QPS可以达到17500/s。

4 小结

至此，文章开头提出的两个问题都给出了答案，收获如下：

• 对于NodeJS这种多进程架构，至少要启动跟cpu数量相同的进程数，这样才能较好的利用多核资源；
• 深层次的性能优化需要从底层入手，结合多种性能分析工具，如top、htop、pidstat、strace、perf等，才能挖掘出性能优化的点；
• 面对一些棘手的技术问题多查资料多讨论，集体的智慧是无穷的。