工作多年，第一次上手排查线上CPU飚高问题

最新推荐文章于 2024-06-17 09:15:00 发布

1024个为什么

最新推荐文章于 2024-06-17 09:15:00 发布

阅读量133

点赞数 2

本文链接：https://blog.csdn.net/jiuqianwan/article/details/134760330

版权

1、背景

收到 zabbix 持续报警

2、排查过程

2.1 先登录上报警机器，查看是哪个服务进程占用 CPU

使用 top 命令查看占用 CPU 最高的进程ID

Tasks: 188 total,   1 running, 187 sleeping,   0 stopped,   0 zombie
Cpu(s): 62.3%us,  5.7%sy,  0.0%ni, 31.7%id,  0.0%wa,  0.0%hi,  0.3%si,  0.0%st
Mem:  32880856k total, 32639624k used,   241232k free,    96144k buffers
Swap:        0k total,        0k used,        0k free, 13855080k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                                                                                                                                                                        
34869 work      20   0 4807m 1.3g  13m S 199.3  4.1 766:45.54 java

2.2 查看是哪个服务

ps -ef| grep 34869

2.3 确定业务场景

确定服务后，发现是个几乎废弃的服务，应该没有访问量才对，看日志也没有请求，最后的请求仅仅是一个后台页面的首页分页查询，大概判断是非核心业务，不会有什么影响，可以慢慢继续排查了

2.4 继续查看是哪个线程最耗CPU

top -p 34869

发现一直在新建线程，每次都是新建的线程在霸占着 CPU

2.5 查看进程的栈信息

tips：线程号是十进制数字，而栈信息里的是十六进制，需要转换一下才能定位到。

比如栈信息中的 nid=0x18b9 ，对应的线程号是 6329

jstack 34869

Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.92-b14 mixed mode):

"pool-22-thread-233" #948 prio=5 os_prio=0 tid=0x00007f564000d000 nid=0x18b9 waiting on condition [0x00007f55df635000]
   java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for  <0x00000000e1bb8178> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1066)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)

"MySQL Statement Cancellation Timer" #931 daemon prio=5 os_prio=0 tid=0x00007f5608042800 nid=0x6833 in Object.wait() [0x00007f55df936000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.util.TimerThread.mainLoop(Timer.java:552)
- locked <0x00000000e5a86920> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)

"MySQL Statement Cancellation Timer" #930 daemon prio=5 os_prio=0 tid=0x00007f561403e000 nid=0x6832 in Object.wait() [0x00007f55e6ae0000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.util.TimerThread.mainLoop(Timer.java:552)
- locked <0x00000000e5a88b38> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)

"MySQL Statement Cancellation Timer" #929 daemon prio=5 os_prio=0 tid=0x00007f5614013800 nid=0x6831 in Object.wait() [0x00007f55df134000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.util.TimerThread.mainLoop(Timer.java:552)
- locked <0x00000000e5a87eb8> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)

"MySQL Statement Cancellation Timer" #915 daemon prio=5 os_prio=0 tid=0x00007f566c063000 nid=0x8597 in Object.wait() [0x00007f55f0683000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.util.TimerThread.mainLoop(Timer.java:552)
- locked <0x00000000e569c0c0> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)

......

发现有很多进程都处在 TIMED_WAITING 状态，还有 parking 的，一直在自旋，怪不得 CPU 飚高。

但根据栈信息，好像也没办法直接定位到问题原因，从网上查阅了一些文章，大概可以推测出是 MySQL 的线程释放 statement 时一直在等待。

具体等待什么？栈顶的线程也看不出是哪块业务的线程。

2.6 继续查看 GC 情况吧

jstat -gc 34869
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
 64.0   64.0   0.0    0.0   524160.0 356505.1  524288.0   216779.1  62336.0 59707.0 7040.0 6554.2    450   20.800 5731  2120.602 2141.402

发现 FGC 已经快 6000 次了，短短几十分钟这次数太反常了。

2.7 那就继续查看堆信息，看看是哪个对象触发了 FGC

[readonly@***]$ jmap -histo 34869

 num     #instances         #bytes  class name
----------------------------------------------
   1:       5894792      188633344  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node
   2:       2268135      110053784  [C
   3:       3170895       76101480  java.lang.String
   4:       1152248       46089920  java.math.BigDecimal
   5:        576088       46087040  com.daojia.jz.accounting.entity.FundsRequestRecord
   6:       1728310       41479440  java.time.LocalDateTime
   7:       1728306       41479344  java.time.LocalDate
   8:       1170002       28080048  java.lang.Long
   9:       1743179       27890864  java.lang.Integer
  10:       1152083       27649992  java.time.LocalTime
  11:         77455       25319784  [B
  12:        204145        9822696  [Ljava.lang.Object;
  13:         42548        8187512  [I
  14:         82647        5289408  java.util.concurrent.ConcurrentHashMap
  15:         99291        4999072  [Ljava.lang.String;
  16:        108879        3484128  org.apache.ibatis.reflection.property.PropertyTokenizer
  17:         97281        3112992  java.util.concurrent.ConcurrentHashMap$Node
  18:         26970        2589120  sun.util.calendar.Gregorian$Date
  19:         35884        1722432  java.nio.HeapByteBuffer
  20:         34121        1637808  java.nio.HeapCharBuffer
  21:         32396        1555008  java.util.HashMap
  22:         81223        1299568  com.daojia.spat.dsfmngr.collector.contract.util.AtomicLongMap
  23:         10562        1188960  java.lang.Class
  24:         36091        1154912  java.io.ObjectStreamClass$WeakClassKey
  25:         13051        1148488  java.lang.reflect.Method
  26:         27956         894592  java.util.HashMap$Node
  27:         13445         860480  java.text.DateFormatSymbols
  28:         34763         834312  java.util.Date
  29:           258         750128  [Ljava.util.concurrent.ConcurrentHashMap$Node;
  ......

好了，到这里一眼就能看到业务相关的一个对象 FundsRequestRecord ，其他相邻的几个都是对象里属性对应的类型。

8、定位问题点

根据堆栈信息，再加上业务日志，很快就定位到了问题代码，还真是分页查询的锅。

private int fundsRequestRecordCount(FundsRequestRecordListQueryDto queryDto) {
        ...
        List<FundsRequestRecord> fundsRequestRecords = fundsRequestRecordMapper.selectByExample(example);
        log.info("查询资金请求记录总条数, result listSize:{}, cost {} ms", fundsRequestRecords.size(), System.currentTimeMillis() - start);

        return CollectionUtils.isEmpty(fundsRequestRecords) ? 0 : fundsRequestRecords.size();
    }

查总条数，不是用 count，而是把所有记录都查出来，取 size 当 count 用，我竟一时无语...

堆信息里的对象数 576088 正好和表里的记录条数一致。

到这里按说可以结案了，先重启服务，让 CPU 降下来，后面把 SQL 改了就行。

疑问

但脑海中还有很多疑问没有解决。

1）为什么没报堆溢出？

从堆信息中大概可以估算已占用的空间有 800 M 左右，而 JVM 配置是 1G，所以没有先报出堆溢出，如果配 512 M，或者表里的数据再多 20W 条，就会报出来了。

2）MySQL Statement Cancellation Timer 是做什么的，一直又在等什么？

简单来说，MySQL 每次执行查询，都会开一个守护线程，来监控 MySQL 任务的执行情况，用于兜底保证查询超时后能够强制关闭查询。

具体可以参考下面这篇博客

https://blog.csdn.net/qq_42025719/article/details/106586557

我看了代码中没有指定连接属性 enableQueryTimeouts 的。

那只能是默认的连接属性就会触发，翻看源码和官网文档，默认值一样，会触发 CancelTimer 。

com.mysql.jdbc.ConnectionPropertiesImpl
    
private BooleanConnectionProperty enableQueryTimeouts = new BooleanConnectionProperty("enableQueryTimeouts", true,
            Messages.getString("ConnectionProperties.enableQueryTimeouts"), "5.0.6", PERFORMANCE_CATEGORY, Integer.MIN_VALUE);

https://dev.mysql.com/doc/connector-j/en/connector-j-reference-configuration-properties.html

由于查回全表数据，SQL 耗时 20s 左右，先触发了 FGC，其他线程就要排队了，当然也包含这些守护线程，所以当前的 statement 就不会被关闭。

3）为什么查询都结束了，FGC 没有把对象回收了，而且还一直回收不了？

这个和上面的问题相互构成“死循环“了。

因为 statement 没有被关闭，查回的 ResultSet 就一直被这个 statement 持有，而 CancelTimer Task 又一直获取不到 CPU 资源，来执行它自己释放连接的逻辑，就形成了死循环，所以就没办法回收对象了。

最后一个疑问，最占内存的为什么是 AQS 的 Node 实例，各方查找没有找到原因，求教了解的小伙伴。

num     #instances         #bytes  class name
----------------------------------------------
   1:       5894792      188633344  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node

扯两句

剑走偏锋，要么奇效，要么奇坑。

原创不易，多多关注，一键三连，感谢支持！