第一次做 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

意外的是，虽然 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

mysql 锁表 Waiting for table metadata lock

4.2. 极客时间

深入拆解 Java 虚拟机

30 Java 虚拟机的监控及诊断工具（命令行篇）
31 Java 虚拟机的监控及诊断工具（GUI 篇）

MySQL 实战 45 讲

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

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