jstack 和 jmap 分析生产 CPU 100% 问题

第一次做 Java 生产环境的问题排查,借机学习了 jstack / jmap / MAT 等工具的使用,也对 MySQL 事务和锁的理解更进一步。

整个过程累计用了 10 个小时,大量的时间用在了读 jstack log 和 jmap dump 文件,由于缺乏经验,读了多遍仍然抓不住重点……期间,查过 quartz / hibernate / jackson,无果。

最后,综合业务日志、jstack、jmap 和 MySQL 锁,才找到了问题:

  • 大事务,for 循环查询多个表,随着数据量增长,Job 不能快速执行完成;
  • 任务执行慢导致任务并行,最终占用 10 个 Quartz Scheduler Worker 线程,导致 CPU 100%;
  • 任务并行导致 MySQL metadata lock

问题解决后,打开极客时间的《深入拆解 Java 虚拟机》《MySQL 实战 45 讲》两个专栏,核心的知识点在专栏中早已经讲过,遗憾的是忙于项目琐事没有及时阅读,否则也就是一二个小时的工作吧。

目前,问题仍然没有从根本上解决,代码的重构,就交给团队的年轻人吧。

1. 问题描述

5-21 16:29 登录阿里云后台发现 bp-doctor 服务器 CPU 100%,是 quartz.jar 导致的。

Quartz 有 3 个 Job

  • 5 分钟执行 医生任务;
  • 10 分钟执行 激活码任务;
  • 20 分钟执行 医院任务;

查看日志,医生任务 有很多的 CannotAcquireLockException 异常

Job DEFAULT.SyncCallbackJob threw an unhandled Exception: 
org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; 
...
nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement
...
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction

登录 MysQL 使用 SHOW PROCESSLIST 查看进程,没有发现死锁。把问题现象和日志发给团队,直到周五下班也没有收到反馈……

意外的是,虽然 Quartz 服务导致 CPU 100%,不仅它自己正常工作,其他几个服务也是一切正常 :)

2. 问题分析

2.1. 查找消耗 CPU 的进程 (Process)

top

quartz.jar

  • PID 2927
  • CPU% 196
  • MEM% 20.9

2.2. 查看进程 (Process) 中线程 (Thread) 占用情况

top -p 2927 -H

10 个线程执行了近 300 小时,Process Status 一直是 Running

  • PID 2956 ~ 2965
  • CPU% 20.5 ~ 23.2
  • MEM% 23.6

2.3. 导出 jstack 日志

jstack -l 2927 > jstack.log

PID 2956 ~ 2965 对应的是 Quartz Scheduler Worker 线程,初步判断和 Quartz 相关

"quartzScheduler_Worker-10" #31 prio=5 os_prio=0 tid=0x00007fd70ce54800 nid=0xb95 runnable [0x00007fd707efc000]
   java.lang.Thread.State: RUNNABLE
"quartzScheduler_Worker-9" #30 prio=5 os_prio=0 tid=0x00007fd70ce52800 nid=0xb94 runnable [0x00007fd707ffd000]
   java.lang.Thread.State: RUNNABLE
"quartzScheduler_Worker-8" #29 prio=5 os_prio=0 tid=0x00007fd70ce50800 nid=0xb93 runnable [0x00007fd71410f000]
   java.lang.Thread.State: RUNNABLE
"quartzScheduler_Worker-7" #28 prio=5 os_prio=0 tid=0x00007fd760e9e800 nid=0xb92 runnable [0x00007fd714210000]
   java.lang.Thread.State: RUNNABLE
"quartzScheduler_Worker-6" #27 prio=5 os_prio=0 tid=0x00007fd760e9c800 nid=0xb91 runnable [0x00007fd714311000]
   java.lang.Thread.State: RUNNABLE
"quartzScheduler_Worker-5" #26 prio=5 os_prio=0 tid=0x00007fd760e9b000 nid=0xb90 runnable [0x00007fd714412000]
   java.lang.Thread.State: RUNNABLE
"quartzScheduler_Worker-4" #25 prio=5 os_prio=0 tid=0x00007fd760e99000 nid=0xb8f runnable [0x00007fd714513000]
   java.lang.Thread.State: RUNNABLE
"quartzScheduler_Worker-3" #24 prio=5 os_prio=0 tid=0x00007fd760e2e800 nid=0xb8e runnable [0x00007fd714614000]
   java.lang.Thread.State: RUNNABLE
"quartzScheduler_Worker-2" #23 prio=5 os_prio=0 tid=0x00007fd70c982000 nid=0xb8d runnable [0x00007fd714715000]
   java.lang.Thread.State: RUNNABLE
"quartzScheduler_Worker-1" #22 prio=5 os_prio=0 tid=0x00007fd761751800 nid=0xb8c runnable [0x00007fd716374000]
   java.lang.Thread.State: RUNNABLE

10 个线程,主要是 3 段和 Spring Data JPA 相关的代码,难道是 Hibernate 5.2.16 的问题?

at com.sun.proxy.$Proxy134.findByMobile(Unknown Source)
at cc.gegee.tob.DoctorServiceImpl.lambda$analysisJinshujuDoctor$0(DoctorServiceImpl.java:120)

at com.sun.proxy.$Proxy141.findByFormCodeAndSerialNumber(Unknown Source)
at cc.gegee.tob.DoctorServiceImpl.lambda$analysisJinshujuDoctor$0(DoctorServiceImpl.java:126)

at com.sun.proxy.$Proxy139.findOne(Unknown Source)
at cc.gegee.tob.DoctorServiceImpl.lambda$analysisJinshujuDoctor$0(DoctorServiceImpl.java:138)

2.4. jmap 生成内存镜像

jmap -dump::live,format=b,file=dump.hprof 2927

dump.hprof 文件大小 356.2MB,压缩后下载到本机。

2.5. MAT (Memory Analyzer Tool) 分析

Dominator Tree

Class Name                                                           | Shallow Heap | Retained Heap | Percentage
-----------------------------------------------------------------------------------------------------------------
org.hibernate.internal.SessionImpl @ 0x8fdd1d90                      |          160 |     5,239,024 |      2.13%
org.hibernate.engine.internal.StatefulPersistenceContext @ 0x86286e58|          104 |    10,393,288 |      4.23%
-----------------------------------------------------------------------------------------------------------------

Leak Suspects

quartzScheduler_Worker-1
  at com.fasterxml.jackson.core.io.SegmentedStringWriter.getAndClear(); (SegmentedStringWriter.java:83)
  at com.fasterxml.jackson.databind.ObjectMapper.writeValueAsString(); (ObjectMapper.java:3213)
  at cc.gegee.core.JsonUtils.asText(); (JsonUtils.java:91)
  at cc.gegee.tob.JinshujuServiceImpl.setTags() (JinshujuServiceImpl.java:56)
  at cc.gegee.tob.quartz.job.SyncCallbackJob.executeInternal() (SyncCallbackJob.java:30)

3. 解决方案

3.1. 治标一:MySQL 杀进程

3.1.1. 查询进程

SHOW PROCESSLIST;

还是没有发现锁 :(

3.1.2. 查询事务

SELECT * FROM information_schema.innodb_trx;

有 7 个 READ COMMITTED 锁,杀进程

kill 6273386;
kill 6272633;
kill 6272106;
kill 6271866;
kill 6271198;
kill 6270679;
kill 6270678;

CPU 和 MEM 立刻降下来了,10 个 Quartz Scheduler Worker 线程都恢复了正常!

然而……5 分钟后……CPU 又 100% 了……

3.2. 治标二:修改 Java 代码

  • 主表有 5,394 条数据;
  • 服务层的实现,是在 for 中循环操作 3 张表,累计 5,394 * 3 = 16,182 次查询,导致 Job 不能在 300 秒内完成;
  • 第 1 个 Job 未完成,第 2 个 Job 开始执行,因此出现了 CannotAcquireLockException;如此反复,导致 10 个 Quartz Scheduler Worker 线程都在执行 SyncCallbackJob
  • 重构前用时 529,171ms,重构后用时 75,193ms,提升了大约 7 倍;

3.2.1. 重构前

SyncCallbackJob.java

@Slf4j
public class SyncCallbackJob extends QuartzJobBean {
}

DoctorServiceImpl.java

@Slf4j
@Service
public class DoctorServiceImpl implements DoctorService {
    @Override
    @Transactional
    public void analysisJinshujuDoctor(boolean fullFlag) {
        jinshujuGroupDoctorRepository.findAll().forEach(
                jsj -> {
                    doctorRepository.findByMobile(); // 120
                    uploadProtocolRepository.findByFormCodeAndSerialNumber(); // 126
                    hospitalRepository.findOne(); // 138
                }
        );
    }
}

3.2.2. 重构后

SyncCallbackJob.java

  • 禁止 QuartzJob 并发执行
@Slf4j
@DisallowConcurrentExecution
public class SyncCallbackJob extends QuartzJobBean {
}

DoctorServiceImpl.java

  • 大事务拆成小事务
@Slf4j
@Service
public class DoctorServiceImpl implements DoctorService {
    @Override
    public void analysisJinshujuDoctor() {
        jinshujuGroupDoctorRepository.findAll().forEach(
                jsj -> {
                    groupDoctor();
                }
        );
    }

    @Transactional
    private void innerAnalysis() {
        doctorRepository.findByMobile(); // 120
        uploadProtocolRepository.findByFormCodeAndSerialNumber(); // 126
        hospitalRepository.findOne(); // 138
    }
}

3.3. 治本

具体的实现方案交给团队里的年轻人吧。

4. 参考资料

4.1. Google 搜索

jstack / jmap / MAT

MySQL

4.2. 极客时间

深入拆解 Java 虚拟机

  • 30 Java 虚拟机的监控及诊断工具(命令行篇)
  • 31 Java 虚拟机的监控及诊断工具(GUI 篇)

MySQL 实战 45 讲

  • 06 全局锁和表锁:给表加个字段怎么有这么多阻碍?
  • 07 行锁功过:怎么减少行锁对性能的影响?