mysql慢查询导致502_MySQL Statement cancellation timer故障排查分享

1.现象

10月26日晚22:07，X服务的线上机器502，期间没有业务峰值、定时任务，外部服务依赖没有明显异常。

2.问题定位

服务502是nginx不能检测到后台健康server时抛出的提示，一般有3类原因。

·部署不规范导致后台进程全部处于killed、restarting或restart failed。

·网络等基础服务异常，nginx所在的机器无法正常连接到后台的业务服务器。

·业务进程中线程资源全部夯住，比如都在连接数据库或调用其他外部模块，从而无法响应来自nginx的健康检查请求。

2.1 常规排查

查看事故前后的线上指标，能够看到MySQL服务大概20分钟会有一次thread峰值，与系统出问题的时间相吻合：

第一反应是不是MySQL服务器上有定时任务或者慢查询。通过show processlist看到并没有慢查询，甚至更新写入数据的业务量还要小于平时。但同时能看到MySQL的lock数很有特点，应该有大量写操作持有锁。

但业务更新数据，持有锁是很正常的。看来这条路一时半会是没啥曙光了，于是换个思路，从业务现场入手。

2.2分析业务后台

分析Java的业务现场有三板斧，jstack jmap jstat。先jstack -l打印线程栈，发现了大量可疑的“MySQL Statementcancellation timer”。在同一台机器上该timer出现了56次，而合同的jetty线程池也不过区区100。如下：

那问题就来了。MySQL Statement cancellation timer是个什么鬼？

2.2.1什么是MySQL Statement cancellation timer

业务服务使用的MySQL Connector在做数据库操作比如开启事务时，需要先做一件事情–获取数据库连接，见com.mysql.jdbc.ConnectionImpl，代码如下：

2.2.2 产生大量timer的原因

通过底层代码机制很明显得出，起这个timer其实和502没有半毛钱关系，仅仅是MySQL底层的超时控制机制。为什么会有这么多的cancel timer呢？因为在业务线程里，数据库事务开启后迟迟没有flush。业务线程需要执行：开启事务->本地更新持久化对象->上传到云存储-->持久化到数据库。开启事务时即获取了数据库连接，启用了CancelTimer，但因为卡在获取云存储Container这个环节，导致一直无法提交到数据库，Timer也一直不能结束。

2.2.3云存储操作为何一直不结束

晚上22点时云存储进行了一次扩容升级，导致线上不稳定。X服务上传图片到云存储的请求响应极慢，导致图片保存事务统统被夯住。X系统的上传图片与基本信息保存到DB被耦合在同一事务，事务开启时占用了Connection，事务flush的时机需要等到图片上传完毕。而悲催的是，虽然业务确实使用了spring的事务管理器，但没有对save*操作设置超时，加上云存储服务还不支持设置主动超时，导致线程中事务永不超时，CancelTimer永不结束。业务代码如下。

2.3结论

业务应用将数据库更新操作和云存储传图操作放在同一个事务。当云存储发生异常时，因为缺少云存储操作的快速失败，并且缺少对整体事务的超时控制，导致整个应用被夯住，进而502。而数据库更新操作会开启MySQL端线程，并持有写锁，带来问题期间MySQL Lock和Thread指标峰值。

3. 解决

知道问题后，解决办法就很明确了。

·配置事务超时done。见事务管理器配置：

·常规RPC操作可通过设置http连接超时时间和重试次数等快速失败，云存储的操作(save和upload等)得通过业务端其他手段来控制超时–如上。

·业务解耦。将云存储图片上传与数据库更新操作解耦，开启在不同事务

·接入tair,云存储出问题后有切换方案

·合同与合作的事务管理器中为图片等RPC操作和数据库操作

4.其他声音

故事一般进行到这里就要结束了，但在查阅资料的过程中，听到了另外一个很大的声音，我们也了解下。见：http://bugs.mysql.com/bug.php?id=36565。大致意思是说，这是MySQL-Connector-Java的一个bug，在5.1.27版本以前MySQL Statement cancellation timer会导致Perm区Leak，内存泄漏后进而业务应用异常。在2010-2013年，StackOverFlow上确有不少案例是关于这个bug的讨论，如http://stackoverflow.com/questions/10615118/how-to-solve-memory-leak-problems，http://stackoverflow.com/questions/15632153/tomcat7-jdbc-datasource-this-is-very-likely-to-create-a-memory-leak。但我们这个案例不是因为MySQL这个bug引起。案发现场和事后我又做了多次模拟实验，始终无法触发Perm Leak，只有正常young gc。见：

5. 经验教训

#好的习惯可以避免这个问题的发生#

·为每一个数据库操作设置timeout

·数据库事务中如果有RPC等对外部模块的调用，需引入对RPC的快速失败机制，或将RPC与数据库事务解耦

·MySQL-Connector-java版本升级到5.1.27以上

===========

欢迎关注微信公众号：hellojavacases

关于此微信号：

分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test，以及和大家一起讨论一些Java问题或场景，这里只有Java细节的分享，没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。