本文主要记录了一次生产环境后台服务的性能分析过程,通过结合多种性能分析工具定位出系统的性能瓶颈并给出优化方案,将整个过程记录并总结如下。
在一次监控走查的过程中,发现一个后台服务的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进程。
上面的结果与我们的预期有些偏差,我们原本的设想是:启动4个worker进程,每个worker运行在一个CPU上,这样能将CPU资源最大程度利用,但是从监控的数据上来看只有一个CPU在工作,这就让人产生一种:找了四个人来干活,但是所有活都是一个人在做的感觉。基于此,我们提出如下问题:
在验证开始之前,我们先从node的master-worker多进程模型入手,做了一些理论假设:如果把整个API服务看作一个施工队,master就是包工头,主要负责监听某个端口接收网络请求,然后转发给worker;而worker负责处理每个网络请求并给出响应。我们预期的情况是:master应该均匀的把每个任务分配给worker,然后所有的worker并发的在多核上执行自己的任务,但是,如果master偏心,把所有的任务都分配给一个worker,导致其他worker手上都没有活干,这就有可能导致只有一个CPU忙的情况发生。基于这个假设,我们进行了如下验证:
通过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是否会“偏心”?
根据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的这种调度策略是否会导致多核资源无法利用呢?
master转发不均匀的猜想不成立,我们又有另一个猜想:cpu的调度策略就是让一个cpu玩命用,实在不够用了再使用下一个cpu,因此现在看到一个cpu繁忙其他cpu空闲可能是因为要处理的任务还不够多,任务多了,一个cpu顶不住,其他的cpu自然会来帮忙。基于这个假设,我们又通过压测平台做了一组压力测试,结果如下:
QPS 1000/s(如图6),只有一个核繁忙但极本到了极限,其他核都空闲
QPS 2300/s(如图7),第一个核顶不住,第二个核开始帮忙分担压力
QPS 4000/s(如图8),第二个核也顶不住,第三个核开始帮忙分担压力
QPS 5000/s(图9),第三个核也顶不住,第四个核开始帮忙分担压力
QPS 7000/s(图10),所有核的资源都耗尽,性能达到瓶颈
基于上面的压力测试结果,可以得出结论:在压力足够的情况下,TSP可以利用多核资源,服务器的资源没有浪费。
TSP的逻辑比较简单:就是给定一个project id(每个模块可以视为一个project,比如Account Health),查询对应的翻译,翻译数据存储在redis,因此,TSP的主逻辑就是从redis里面取一些数据,然后返回。redis的性能是很好的,而单机容器的qps只能达到7000,性能的瓶颈一定是在容器,性能是否还有优化的空间呢?这是一个比较复杂的问题,要想优化性能,首先要搞清楚cpu的时间都被用到哪里了。
通过top命令查看每个进程的资源消耗情况(如图11),通过耗时分布来分析cpu的时间都用到哪了,可以看出:对于cpu0来说,76.5%的时间用在user,6.4%的时间用在sy,这说明绝大多数的cpu时间都用在处理用户态的业务逻辑上,只有少量的CPU用来处理内核逻辑;由于wa(IO wait)不高,因此等待IO的时间也不长。
但是TSP的业务逻辑并不复杂,为什么会占用这么多cpu呢?有没有可能是网络IO过高导致cpu的时间都用在网络数据包的拷贝上了呢?
翻了一下飞哥的《深入理解Linux网络》,从网卡接收数据包的完整流程如下图所示:
当有数据包到达网卡的时候,首先是DMA把数据包拷贝到内存的RingBuffer,此过程不需要cpu参与,然后是内核线程通过软中断的形式将数据包送入协议栈进行处理,处理完成后由cpu将数据包从内核的缓冲区拷贝到用户的进程空间,这个过程是会消耗cpu时间的。但是,这个过程是内核线程处理的,如果cpu的时间都用到网络IO的处理,则sy/si的值应该很大才对,但是sy/si的值相比us并不高,因此,cpu的时间没有消耗在网络IO的处理上。
排除了网络IO占用cpu的可能,业务逻辑又不复杂,但是用户态cpu占用较高,因此推测可能是某些系统调用消耗了大量的cpu时间,因此,通过strace观察系统调用的情况,执行strace -cp pid
命令,查看worker进程内部使用了哪些系统调用,结果如下,
可以看到futex的系统调用占用了30.57% cpu时间,进一步通过strace -tt -s 2048 -p pid
分析futex是用在什么场景,如下图,
发现futex总是出现在日志打印之后,因此可以认为futex跟日志打印有很大关联。奇怪的是,从代码上看,日志打印是在worker进程中做的,为什么会跑到master中来打印了呢?经过网上搜索发现,log4js在cluster模式下,默认会将woker打印的日志传递给master进行打印,因此,浪费cpu时间的罪魁祸首找到了,频繁的日志打印使得日志信息从wokers向master频繁的传递,导致futex的调用量急剧上升,消耗了大量cpu实践。
可以看到,调用次数比较多的系统调用分别是:write、epoll_wait、epoll_ctl、read和futex,其中futex占比并不高,可以忽略。
去掉日志打印逻辑后,再观察master和woker的系统调用情况,看futex调用是否有减少。如下图,
可以看出futex的调用基本没有了。再通过压力测试来验证性能是否有改善,经测试发现峰值的QPS可以达到17500/s。
至此,文章开头提出的两个问题都给出了答案,收获如下:
原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。
如有侵权,请联系 cloudcommunity@tencent.com 删除。
原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。
如有侵权,请联系 cloudcommunity@tencent.com 删除。