线上环境CPU使用率高排查笔记
线上环境CPU使用率高排查笔记
现象
生产环境上业务运行容器出现cpu使用率升高、业务交易执行速度慢,平台日志未打印异常信息。
现场数据
- jvm线程的cpu使用率(top -H)
- 线程栈
- 平台配置
- jdk版本信息
- 生产的jvm内存堆栈
- 根据现场的同事描述,出现问题的是rpc服务调用(abs通过tci调用afa的rpc服务),同时该rpc服务配置了流控的功能,对于开启了流控的接入服务,在请求进来的时候,会去检查当前流量的大小,这一步会调用到concurrentLinkedQueue的size()方法。
- 根据线程cpu使用率及当前的线程栈,排查到cpu使用率异常时,cpu主要消耗concurrentLinkedQueue的size()和remove()方法上,对应的ConcuureLinkedQueue(jdk是8u40)源码行数分别是450行和490行(见下图)
文章图片
文章图片
这两个函数均是需要遍历队列中的元素,时间复杂度为O(n),如果队列中的元素达到一定数量级,会占用比较高的cpu。根据当前现有的数据来看,可以推测出当前队列的深度可能比较大。
- 根据当时生产环境发现cpu高时dump下来的内存镜像,发现ConcurrenLinkedQueue中item为null的节点数竟然高达约695万个,这一步也证实了第2点的推测。
文章图片
- 再结合jdk官网提供的bug清单,发现在jdk 8u40版本的存在一个ConcurrentLinkedQueue的bug:在特定的情况下,将对象通过remove()移除后,队列中仍会残留一个item值为null的节点。也就是说,将对象存入队列时,它会将对象封装为一个Node放入队列中,Node的item指向对象,在特定的情况下,通过remove()移除对象时,它只将itme的值置为null,但没有将node从队列中移除,导致队列的大小并没有变化 。而随着对象的添加,队列的大小将越来越大。jdk bug的详情请看:https://bugs.java.com/bugdata...
文章图片
- 从现场的线程栈来看,发现afa平台配置的定时任务(日志清理)在每天凌晨1点调起来,会一直挂住交易线程,造成交易线程一直被占用不释放,可用的业务线程数每日递减,从而造成线程泄露。
所有日志清理定时任务均是堵在了readBytes这个操作,一共发现23笔,根据启动时间以及dump线程栈的时间,分析下来刚好对应每天启动一笔。
文章图片
- 通过分析jdk源码,发现在另一种情况下,ConcurrentLinkedQueue在通过remove()移除对象时,也会造成node不会真正从队列中移除的问题。首先,ConcurrentLinkedQueue将node从对象中移除只发生在两个位置,一个是调用remove()方法,另一个是调用first()方法。
- 在执行remove()时,队列移除是通过cas操作去执行,在并发较高的情况下,当相邻的两个元素被移除时,可能会有一个item为null的node没有被删除掉,从而造成泄露。
比如:队列中A,B,C,D4个节点,当同时删除B,C两个节点,在高并发的情况下,两个并发线程同时走到下图495行的位置时,此时线程1获取到A,B,C三个的引用,线程2获取 B,C,D三个节点的引用,这时候继续往向走,线程1删除后,A的netxt指向C,线程2删除后,B的next指向D,由于A是头节点,B的节点没有被引用(由于线程1的执行),所以最终队列会变成了A->C->D的情况,这个时间就造成了C的item为null,但没有真正从队列中移除。
文章图片
而在执行first()时,当head发现更新时,将会遍历后续item不为Null的节点作为头结节,这一步能够将item为null的节点移出队列,如果当前head节点没有被更新时,队列后续可能存在的item为Null的节点将会一直存放于队列中。
- 在执行remove()时,队列移除是通过cas操作去执行,在并发较高的情况下,当相邻的两个元素被移除时,可能会有一个item为null的node没有被删除掉,从而造成泄露。
结论 综上所述,由于jdk 8u40的bug导致ConcurrentLinkedQueue的队列存在大量item为null的节点,再刚好碰巧日志清理交易一直未退出使得ConcurrentLinkedQueue的头节点一直不会更新,从而导致size()以及remove()在遍历时速度慢,消耗cpu高。
复现 提供与生产环境上相同afa配置以及相同jdk版本的测试环境,准备一个长时间挂住业务线程的交易,以及若干短耗时交易。
平台启动后,先启动挂住线程的交易,然后通过loadrunner测试计划持续压测短耗时交易,在压力与时间足够下,能够重现cpu高以及业务交易吞吐量低的情况。
验证 由于itme为null的节点泄漏的条件比较苛刻,在高并发下,可能1秒只会有一两笔出现一个节点泄露,所以需要通过比较长时间的压测才能完全重现当时的场景。不过,还有另一种方法,在压测过程中,通过每隔十、二十分钟打印一次内存镜像,将内存镜像拿出来分析,通过Eclipse的Memory analyze tool工具的oql语言搜索itme为空的node数,进行对比,就能够发现item为null的节点数的增长速率。
下图为压测三天后dump下来的内存镜像,发现压测前跟压测后两次镜像中,item为null的节点数增加了约268万个。
压测前
文章图片
压测后
文章图片
? 同时,RpcServer-IoWorker-30线程的cpu占用率已稳定上升到31.8%,观察当时的线程栈发现,线程正在执行ConcurrentLinkedQueue的size()方法,这点与生产环境的情况是一致的。
文章图片
文章图片
解决方案
- 升级jdk版本(主要)
- 优化交易,保证排查定时任务日志清理交易正常停止。(主要)
- 优化平台,在进行流控校验的逻辑中,弃用ConcurrentLinkedQueue的size()方法,采用BlockingQueue或其他并发队列来实现。(次要问题,只有在交易线程长时间未释放的情况下才会出现)
- 将rpc接入服务的流控功能下线;(适用于应急情况)
压测前的内存堆栈如下所示:
文章图片
压测5小时后
文章图片
推荐阅读
- 人生感悟记#环境仪器宋庆国成长记#072
- 六步搭建ES6语法环境
- 52岁李若彤秀马甲线上热搜,凭什么啊()
- 自我修养--基础知识
- iOS,打Framework静态库
- 游族网络|游族网络 002 -
- win10环境|win10环境 python3.6安装pycrypto-2.6.1的问题
- 《月线上的一笔(一段熊牛的历程,如何看大盘系列》目录)
- Python|Win10下 Python开发环境搭建(PyCharm + Anaconda) && 环境变量配置 && 常用工具安装配置
- Caffe在Windows10下CPU版本的安装(cpu+anaconda3+vs2013+pycaffe)