线上环境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行(见下图)

这两个函数均是须要遍历队列中的元素，工夫复杂度为O(n)，如果队列中的元素达到肯定数量级，会占用比拟高的cpu。依据以后现有的数据来看，能够揣测出以后队列的深度可能比拟大。

  1. 依据过后生产环境发现cpu高时dump下来的内存镜像，发现ConcurrenLinkedQueue中item为null的节点数居然高达约695万个，这一步也证实了第2点的揣测。

  2. 再联合jdk官网提供的bug清单，发现在jdk 8u40版本的存在一个ConcurrentLinkedQueue的bug：在特定的状况下，将对象通过remove()移除后，队列中仍会残留一个item值为null的节点。也就是说，将对象存入队列时，它会将对象封装为一个Node放入队列中，Node的item指向对象，在特定的状况下，通过remove()移除对象时，它只将itme的值置为null，但没有将node从队列中移除，导致队列的大小并没有变动 。而随着对象的增加，队列的大小将越来越大。jdk bug的详情请看：https://bugs.java.com/bugdata...

  1. 从现场的线程栈来看，发现afa平台配置的定时工作(日志清理)在每天凌晨1点调起来，会始终挂住交易线程，造成交易线程始终被占用不开释，可用的业务线程数每日递加，从而造成线程泄露。

    所有日志清理定时工作均是堵在了readBytes这个操作，一共发现23笔，依据启动工夫以及dump线程栈的工夫，剖析下来刚好对应每天启动一笔。

  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，但没有真正从队列中移除。

      而在执行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万个。
压测前

压测后

同时，RpcServer-IoWorker-30线程的cpu占用率已稳定上升到31.8%，察看过后的线程栈发现，线程正在执行ConcurrentLinkedQueue的size()办法，这点与生产环境的状况是统一的。

解决方案

  1. 降级jdk版本（次要）
  2. 优化交易，保障排查定时工作日志清理交易失常进行。（次要）
  3. 优化平台，在进行流控校验的逻辑中，弃用ConcurrentLinkedQueue的size()办法，采纳BlockingQueue或其余并发队列来实现。(主要问题，只有在交易线程长时间未开释的状况下才会呈现)
  4. 将rpc接入服务的流控性能下线；（实用于应急状况）

修复后压测验证

降级jdk版本到8u152后，优化日志清理交易，依照原来的压测计划进行压测。
压测前的内存堆栈如下所示:

压测5小时后