线上环境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的节点将会一直存放于队列中。

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()方法，这点与生产环境的情况是一致的。

解决方案

升级jdk版本（主要）
优化交易，保证排查定时任务日志清理交易正常停止。（主要）
优化平台，在进行流控校验的逻辑中，弃用ConcurrentLinkedQueue的size()方法，采用BlockingQueue或其他并发队列来实现。(次要问题，只有在交易线程长时间未释放的情况下才会出现)
将rpc接入服务的流控功能下线；（适用于应急情况）

修复后压测验证

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

压测5小时后

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