线上环境CPU使用率高排查笔记

线上环境CPU使用率高排查笔记 现象 生产环境上业务运行容器出现cpu使用率升高、业务交易执行速度慢,平台日志未打印异常信息。
现场数据

  1. jvm线程的cpu使用率(top -H)
  2. 线程栈
  3. 平台配置
  4. jdk版本信息
  5. 生产的jvm内存堆栈
分析思路
  1. 根据现场的同事描述,出现问题的是rpc服务调用(abs通过tci调用afa的rpc服务),同时该rpc服务配置了流控的功能,对于开启了流控的接入服务,在请求进来的时候,会去检查当前流量的大小,这一步会调用到concurrentLinkedQueue的size()方法。
  2. 根据线程cpu使用率及当前的线程栈,排查到cpu使用率异常时,cpu主要消耗concurrentLinkedQueue的size()和remove()方法上,对应的ConcuureLinkedQueue(jdk是8u40)源码行数分别是450行和490行(见下图)
    线上环境CPU使用率高排查笔记
    文章图片
线上环境CPU使用率高排查笔记
文章图片

这两个函数均是需要遍历队列中的元素,时间复杂度为O(n),如果队列中的元素达到一定数量级,会占用比较高的cpu。根据当前现有的数据来看,可以推测出当前队列的深度可能比较大。
  1. 根据当时生产环境发现cpu高时dump下来的内存镜像,发现ConcurrenLinkedQueue中item为null的节点数竟然高达约695万个,这一步也证实了第2点的推测。
    线上环境CPU使用率高排查笔记
    文章图片

  2. 再结合jdk官网提供的bug清单,发现在jdk 8u40版本的存在一个ConcurrentLinkedQueue的bug:在特定的情况下,将对象通过remove()移除后,队列中仍会残留一个item值为null的节点。也就是说,将对象存入队列时,它会将对象封装为一个Node放入队列中,Node的item指向对象,在特定的情况下,通过remove()移除对象时,它只将itme的值置为null,但没有将node从队列中移除,导致队列的大小并没有变化 。而随着对象的添加,队列的大小将越来越大。jdk bug的详情请看:https://bugs.java.com/bugdata...
线上环境CPU使用率高排查笔记
文章图片

  1. 从现场的线程栈来看,发现afa平台配置的定时任务(日志清理)在每天凌晨1点调起来,会一直挂住交易线程,造成交易线程一直被占用不释放,可用的业务线程数每日递减,从而造成线程泄露。
    所有日志清理定时任务均是堵在了readBytes这个操作,一共发现23笔,根据启动时间以及dump线程栈的时间,分析下来刚好对应每天启动一笔。
    线上环境CPU使用率高排查笔记
    文章图片

  2. 通过分析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,但没有真正从队列中移除。
      线上环境CPU使用率高排查笔记
      文章图片

      而在执行first()时,当head发现更新时,将会遍历后续item不为Null的节点作为头结节,这一步能够将item为null的节点移出队列,如果当前head节点没有被更新时,队列后续可能存在的item为Null的节点将会一直存放于队列中。

7、结合第4点和第5点来分析,发现由于定时清理日志的线程一直没有停止。因为只有交易执行完成并释放线程时,该线程对象才会从ConcurrentLinkedQueue队列中移除,其他线程执行时间较短的线程,都已经移出队列,从而它会更新成为队列头,但由于它始终挂住不释放,导致ConcurrentLinkedQueue的队列头一直不会更新。因此这会导致队列的item为null的节点数越来越高,所以在执行size()方法和remove()方法遍历队列时,造成占用cpu严重的情况。
结论 综上所述,由于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万个。
压测前
线上环境CPU使用率高排查笔记
文章图片

压测后
线上环境CPU使用率高排查笔记
文章图片

? 同时,RpcServer-IoWorker-30线程的cpu占用率已稳定上升到31.8%,观察当时的线程栈发现,线程正在执行ConcurrentLinkedQueue的size()方法,这点与生产环境的情况是一致的。
线上环境CPU使用率高排查笔记
文章图片

线上环境CPU使用率高排查笔记
文章图片

解决方案
  1. 升级jdk版本(主要)
  2. 优化交易,保证排查定时任务日志清理交易正常停止。(主要)
  3. 优化平台,在进行流控校验的逻辑中,弃用ConcurrentLinkedQueue的size()方法,采用BlockingQueue或其他并发队列来实现。(次要问题,只有在交易线程长时间未释放的情况下才会出现)
  4. 将rpc接入服务的流控功能下线;(适用于应急情况)
修复后压测验证 【线上环境CPU使用率高排查笔记】升级jdk版本到8u152后,优化日志清理交易,按照原来的压测方案进行压测。
压测前的内存堆栈如下所示:
线上环境CPU使用率高排查笔记
文章图片

压测5小时后
线上环境CPU使用率高排查笔记
文章图片

    推荐阅读