产线应用升级时CPU异常飙升问题记录

写这篇文章其实说来惭愧,组长从2月份的时候就跟我提过说咱们应用在上线的时候会有CPU异常飙升的情况,之前也跟着看过几次,一直没有确定的结论,曾经监控时看到升级过程中YGC次数偏高,推测是否是YGC导致,现象入下图,突刺的时间点正好是升级时间.

推测是不是新生代设置小了

找运维要了JVM启动参数

-Xms6g -Xmx6g -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:+UseParNewGC -XX:ParallelGCThreads=8 -XX:+UseConcMarkSweepGC -XX:CMSInitiatingPermOccupancyFraction=70 -XX:+UseCMSCompactAtFullCollection -XX:+UnlockExperimentalVMOptions -XX:+UseCGroupMemoryLimitForHeap  -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/dumpoom.prof

记忆中NewRatio=2是默认的,但通过监控看图发现新生代的实际内存占用对不上,于是找运维通过命令行参数查看实例内存分步情况

jmap -heap pid 

Attaching to process ID 6, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.242-b08

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 6442450944 (6144.0MB)
   NewSize                  = 697892864 (665.5625MB)
   MaxNewSize               = 697892864 (665.5625MB)
   OldSize                  = 5744558080 (5478.4375MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 536870912 (512.0MB)
   CompressedClassSpaceSize = 528482304 (504.0MB)
   MaxMetaspaceSize         = 536870912 (512.0MB)
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 628162560 (599.0625MB)
   used     = 550504976 (525.0024566650391MB)
   free     = 77657584 (74.06004333496094MB)
   87.63734279228612% used
Eden Space:
   capacity = 558432256 (532.5625MB)
   used     = 542857760 (517.7095031738281MB)
   free     = 15574496 (14.852996826171875MB)
   97.21103216501878% used
From Space:
   capacity = 69730304 (66.5MB)
   used     = 7647216 (7.2929534912109375MB)
   free     = 62083088 (59.20704650878906MB)
   10.966847355204417% used
To Space:
   capacity = 69730304 (66.5MB)
   used     = 0 (0.0MB)
   free     = 69730304 (66.5MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 5744558080 (5478.4375MB)
   used     = 4791414320 (4569.448776245117MB)
   free     = 953143760 (908.9887237548828MB)
   83.40788365743184% used


75661 interned Strings occupying 9071264 bytes.

发现数值跟监控看到的一致,新老分代的比例没有按照1:2来分配,也摸不着头脑不知道为啥这个磨人参数没生效,于是找运维手动加了这个参数

-XX:NewRatio=2 

再通过jmap heap pid查看发现比例正常了

Attaching to process ID 6, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.242-b08

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 6442450944 (6144.0MB)
   NewSize                  = 2147483648 (2048.0MB)
   MaxNewSize               = 2147483648 (2048.0MB)
   OldSize                  = 4294967296 (4096.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 536870912 (512.0MB)
   CompressedClassSpaceSize = 528482304 (504.0MB)
   MaxMetaspaceSize         = 536870912 (512.0MB)
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 1932787712 (1843.25MB)
   used     = 476983584 (454.8869934082031MB)
   free     = 1455804128 (1388.3630065917969MB)
   24.67852941316713% used
Eden Space:
   capacity = 1718091776 (1638.5MB)
   used     = 361182592 (344.4505615234375MB)
   free     = 1356909184 (1294.0494384765625MB)
   21.022310742962315% used
From Space:
   capacity = 214695936 (204.75MB)
   used     = 115800992 (110.43643188476562MB)
   free     = 98894944 (94.31356811523438MB)
   53.9372072697268% used
To Space:
   capacity = 214695936 (204.75MB)
   used     = 0 (0.0MB)
   free     = 214695936 (204.75MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 4294967296 (4096.0MB)
   used     = 127424296 (121.52127838134766MB)
   free     = 4167543000 (3974.4787216186523MB)
   2.9668280854821205% used

66384 interned Strings occupying 7469656 bytes

 再升级的过程中YGC频率也下降了,虽然降的不多,但个人理解这个范围应该属于正常范围.

 但CPU飙升的问题还是没解决,于是推测会不会是应用切换过程中应用切换导致原调用失败重试引发的http请求数量翻倍,从而拉高了CPU,但反过来想想,也不应该是直接原因.服务正常运行期间CPU使用率基本都不到10%.于是又没有了方向.

最近快618了,线上实例都进行了扩容,现有实例配置4个容器,单节点6C8G.前两天系统升级,结果好巧不巧,收到其他中心的报障了.对应的接口调用直接Read Time Out了,这下没辙了,混是混不过去了.

 先说一下具体场景:就绪检查和健康检查分别是240s和360s.滚动升级过程中等节点健康检查通过后接入流量,在流量打进来的一瞬间,CPU噌的就上去了,如果CPU使用率持续在高点,节点就自动重启了(关于这块的重启机制不太理解,可能有偏差,应该是跟K8S相关).具体现象如下图:

流量情况如下

在看监控数据的时候发现线程统计数据很诡异,分别看了升级过程中和第二天的线程统计情况

 为啥升级过程中会有这么多守护线程数,趋于平稳后守护线程数又降下来了呢?于是找运维dump了一份该节点两个时间段的jstack日志

jstack -l pid >jstack.log

 拿到gceasy.io上分析了一下

结合Tomcat相关理解,这个TIMED_WAITING的线程是tomcat维护的线程池里的线程,当有HTTP请求过来时会从线程池里分配线程执行对应的请求.

分析下来应该是实例就绪后流量接入的瞬间,请求处理还伴随部分资源初始化的时间,导致tomcat初始化的线程来不及处理接入进来的流量,于是疯狂的创建线程,达到tomcat的线程池最大线程数.

看了下代码中设置的参数

server:
  tomcat:
    uri-encoding: UTF-8
    max-threads: 1000
    min-spare-threads: 30
  connection-timeout: 5000
  servlet:
    context-path: /

 解释一下tomcat相关连接的配置参数

# 最大工作线程数
max-threads: 1000
# 最小工作线程数 tomcat启动时的初始化的线程数
min-spare-threads: 100
# 最大连接等待数
accept-count: 1000

于是在测试环境调整了对应的参数

server:
  tomcat:
    uri-encoding: UTF-8
    # 最大工作线程数
    max-threads: 500
    # 最小工作线程数 tomcat启动时的初始化的线程数
    min-spare-threads: 100
    # 最大连接等待数
    accept-count: 1000
  connection-timeout: 5000
  servlet:
    context-path: /

经过压测,模拟应用升级流量接入的过程,发现CPU的指标下来了.各个接口的TP99都维持在合理的范围内

基本判定是因为Tomcat连接池配置问题,导致流量接入时线程不够处理请求,CPU疯狂创建tomcat工作线程,以及上下文频繁切换导致的CPU指标异常. 

这是今天上线的CPU指标情况,CPU使用率相较之前明细下来了,就是18:25的那个高点来的让人有点措手不及,可能还有其他没考虑到的点吧.跟业务上下游确认了一下,暂时没出现前两天的报障情况,此事暂时告一段落,后续再继续跟进这块.

 

写在最后的话:若各位大佬看到文中有不对的地方,欢迎留言讨论,共同进步!

彩蛋:gceasy.io分析报告中关于http线程数的那一栏,states中RUNNABLE的个数看了好几个分析报告,发现都是3,

可结合文章 tomcat之NIO模型（NioEndpoint）及Connector相关配置 深入学习一下

参考文章

SpringBoot内嵌tomcat调优

实战Springboot内置Tomcat配置调优