1.问题描述与解决
1.1 问题描述
6月28日上午11点25分左右，线上的服务突然有两百多个接口时延告警，赶紧翻看了下日志，日志内容如下：“spring事务管理器无法获得数据库连接....”，看了下线上系统，貌似还是可以返回的，不过RT巨慢，后台接口返回差不多要两秒的时间。
1.2 问题排查与解决
问题排查基本都是有个套路，先关注应用表现、然后看下系统资源、最后看用到的中间件的情况。我们这边有完整apm性能，只需要逐个去查看就行，如果运维系统不够成熟的话，建议收藏些常用的运维命令或脚本，方便快速定位问题。
从监控平台看来，从11点到11点30分的流量，稳定在800QPS，CPU使用率稳定在7-15%，ED区与OLD区内存正常，YG与FG次数并无显著飙升，跟平常无太大差别，但是延时告警依然是继续存在。直接抽出我的三十米长的“瑞士军刀”-arthas。从监控上看到获取数据库连接的时间居然有几秒之多!
trace org.springframework.jdbc.datasource.DataSourceTransactionManager doBegin "#cost>200"
既然是mysql获取连接慢了，那就看看这个过程究竟慢在哪里？应用与mysql服务实例是基于C/S 架构通信的，应用作为msyql客户端的存在，并通过tcp与mysql实例通信，针对于整个过程进行逐一去排查。是应用慢呢？还是网络慢？还是实例慢？
首先查看了下当前应用实例的数据库连接状况，发现都是连接池已达到最大连接数。
netstsat -an|grep 3307
登录到线上的mysql实例上查看了下可以看到连接大部分都是事务未提交的状态，那么这些连接有可能在执行大的事务。
select * from information_schema.processlist where id in ( select trx_mysql_thread_id from information_schema.INNODB_TRX );
查看了应用与客户端的连接情况，可以知道应用与mysql实例的连接都满了， 可能在执行一些慢sql或者大事务，导致连接一直在占用。于是拿出了tcpdump来监听下，看下这些连接的通信内容。在抓包之前，我们先了解下应用与mysql服务的通信过程。
其中mysql协议的具体内容就不做详细阐述了，运行
sudo tcpdump -i en0 -c 2000 host xxxx and port 3307 -A -nn -w test1.cap
tcpdump下来的内容可以用wireshark来分析下，主要有以下两种通信内容：对于第一种类型的SQL，分析发现都只有set autocommit=1语句，应用客户端没有继续发送任何SQL，直接过滤掉；第二种类型，是手动开启一个事务然后手动提交。
编号
commit类型
SQL序列类型
1
自动提交
1.set autocommit=1
2.SQL请求
2
手动提交
1.set autocommit=0
2.insert/update/delete/select请求
3.commit
应用又出现了获取数据库连接异常，马上找到对应时间戳下的通信内容，挑选了一个通信包，然后fllow stream查看整个事务的执行过程，以下是完整的通信过程。
11:50:33.891679 应用->mysql:....SELECT 1
11:50:33.893546 mysql->应用:..........def....1..?................1................
11:50:33:893574 应用->mysql: SET autocommit=0
11:50:33:893604 mysql->应用: Response OK
11:50:33:893750 应用->mysql:SELECT xxxx
11:50:33:895809 mysql->应用: Response OK
11:50:34:003618 应用->mysql:INSERT xxxx1
11:50:33:006572 mysql->应用: Response OK
11:50:33:008239 应用->mysql:INSERT xxxx2
11:50:33:010010 mysql->应用: Response OK
11:50:34:901349 应用->mysql: .........commit........
可以看出来，客户端sql的执行请求与回复过程是很快的，唯独这个commit差不多要将近1秒多的钟时间，从中推断出在执行sql请求过程中肯定参杂了耗时的操作，导致最后的commit命令发送很慢，这就导致了事务的延时很大。翻了下这个接口的逻辑代码，可以看到主要逻辑是保存记录+调用推送dubbo服务。
@Transactional
public void saveExamination(SaveExaminationQuery query, SaveExaminationQuery.Body body) {
................
ExaminationEntity examination = examinationConvert.toExaminationEntity(query, body);
//保存考试安排
Long id = examinationManager.saveExamination(examination);
//保存考场关系
exRoomRelManager.saveRels(planId, id, roomUids);
//pushCommand是属于外部的rpc服务
pushService.pushCommand(new RefreshDataCommand.ExaminationPlanCMD()
.sendTo(PushConstant.TARGET_TYPE.ROOM, roomUids));
}
顺着上面的思路，我们就在看执行sql与提交commit之间的发生事情，聚焦pushcommand接口，那我们重点关注下，再次祭出arthas，看下这个外部调用的情况。
trace com.mis.device.api.PushService pushCommand "#cost>200" 发现dubbo调用的rt居然也有1s之久
看样子是这个外部调用阻塞了事务的提交，上一个版本都是正常的。问了同事，解释说是加入了新的逻辑，会去缓存中捞一遍没有发送的命令，然后一起推送给设备，如果有些设备长时间未开机就会堆积大量的指令。。。巴拉巴拉说了一大堆，还是回滚服务版本吧，回滚后延时告警瞬间减少到正常水平，但代码依然是有问题的！
2.问题复盘
2.1 spring的事务机制
spring中的事务处理是在利用aop实现的，如果带了@Tracnsactional会去找相应的代理链路方法去执行。一般可简化为下面几个阶段
打开（借）连接 -> 设置事务特性参数 -> 执行原方法 -> 提交事务 -> 关闭（还）连接
如果在代理方法中包含了其他耗时方法或操作将直接影响整个事务执行的耗时。其中在事务特性参数中包括了，需要回滚的捕捉异常、事务的时间限制、事务的级别。这里只能介绍个spring事务执行的大概流程。
2.2 注意事项
数据库事务范围应该越小越好，尽量避免包括外部调用或其他的耗时的操作；如果需要保持事务与外部调用的一致性，建议使用异步化+重试+校验/恢复等措施保证；事务应设置合理的超时时间，避免连接占满。这次踩坑也直接触发了设备领域的推送服务的的异步化优化，尽最大可能降低调用耗时与推送的稳定性。
//@Transactional 取消整体范围的事务
public void saveExamination(SaveExaminationQuery query, SaveExaminationQuery.Body body) {
Long planId = CastUtil.castLong(query.getPlanId());
List roomUids = body.getClassroomUids();
ExaminationEntity examination = examinationConvert.toExaminationEntity(query, body);
//1.将事务放在mananger层,不将外部调用放入
//2.事务加入时间限制
Long id = examinationManager.saveExamination(examination, roomUids);
pushService.pushCommand(new RefreshDataCommand.ExaminationPlanCMD()
.sendTo(PushConstant.TARGET_TYPE.ROOM, roomUids));
}
3.小结
本篇通过对线上发生的一个连接池占满的事件，利用arthas/tcpdump等工具排查，定位到是因为事务执行慢是导致连接池占满的原因， 并从中对客户端与mysql的通信过程有一定的理解，最后还分析了spring事务的实现机制，避免以后再次踩坑。
参考资料:
