踩坑日志 - 记录一次因Druid 1.1.22版本Bug造成服务性能受损的排查过程

最新推荐文章于 2023-11-17 15:04:31 发布

Enda Lin

最新推荐文章于 2023-11-17 15:04:31 发布

阅读量2.6k

点赞数 5

分类专栏：踩坑日志 JAVA 文章标签： java

本文链接：https://blog.csdn.net/BTBO_/article/details/117632093

版权

JAVA 同时被 2 个专栏收录

3 篇文章 0 订阅

订阅专栏

踩坑日志

1 篇文章 1 订阅

订阅专栏

现象

某个下午，某个服务的测试环境突然出现大量接口延时告警，从监控上看，接口p99耗时基本都达到了5s以上，而且接口延时越来越长

企业微信截图_383676f3-8e13-416b-b429-b3bb3158bf86.png
随着业务方的不断超时重试，数据库线程被打满，等待线程数飙高，大量线程阻塞

企业微信截图_f16d7a6b-3f10-4382-8800-48a45f01213a.png

初步排查过程

1、通过APM链路监控，我们发现所有链路的主要耗时都集中在了DataSource#getConnection这个过程中

企业微信截图_b4cb118d-3cea-4980-8057-dc618e4bd959.png

2、初步怀疑，可能是因为存在SQL 慢查询导致，但后来发现根因并不在此，因为监控显示，当时最慢的SQL99线是56.99ms，qps低于0.01（基本可以排除SQL慢查询这个原因）

3、GC分析：半个小时有289次GC，最长的的STW是280ms（在执行垃圾回收时，Java应用程序中除了垃圾回收器线程之外其他所有线程都被挂起，意味着在此期间，用户正常工作的线程全部被暂停下来，当初怀疑STW280ms影响到了DataSource#getConnection，但事实并不是，因为STW大于100ms到占比只有1.73%，比例不高）

企业微信截图_f91b8d75-60c4-48cb-8246-043cf5ca85fa.png

企业微信截图_54a82d3d-0a08-4cd1-b766-42f799be2115.png

4、接口QPS分析：在服务单实例的前提下，测试同学在循环跑用例导致这3个接口的请求数均达 3000次/min，平均1s要处理3000/60=50个请求，而线上这3个接口的平均耗时 20~30ms，当时有怀疑这三个接口的请求负载影响到其它接口相关线程的正常运作，但是这个并不能解释Java线程等待MySQL连接耗时如此之长
企业微信截图_f66c4e65-5e24-45a3-a124-70e9a6e4e115.png

初步解决措施： 随着电话被打爆、微信被业务疯狂轰炸，为了尽快先解决问题，我们尝试扩展容器到三台，问题得到奇迹般缓解

进一步排查

1、在初步的分析中，总结出的初步结论是因为单实例下单个接口3000次/min次请求影响到了其他接口的正常查询，但是这并不能解释DataSource#getConnection耗时长的问题，因此需要进一步排查问题，深究原因

2、为了复现问题，我使用Jmeter以3000qpm来请求当时问题出现时，耗时最长的两个接口，但是问题没有复现，接口响应速度很快，平均响应时间都在10ms以内
企业微信截图_0da68c6d-2e02-4757-ba4f-050925066925.png

3、为了进一步复现问题，我还原Apollo配置到服务异常的时间点（这个时候发现Druid 的配置test-on-borrow和test-on-return并修改成了false，后面发现这两个配置的修改成为的问题修复的关键），然后重启Jmeter，问题重现，DataSource#getConnection长达3s

企业微信截图_821169a6-1e32-458d-a3dd-4b62e653e5b9.png

4、使用Arthas 追查DataSource#getConnection的调用链路，分析其链路耗时，命令：trace com.alibaba.druid.pool.DruidDataSource getConnection ‘#cost > 100’ -n 5

企业微信截图_3bb6b276-8241-4017-81d9-820b054bab33.png

通过一层层分析，我们最终来到了com.alibaba.druid.util.MySqlUtils#getLastPacketReceivedTimeMs这个方法

企业微信截图_9d827865-1ba3-473b-8704-0e07b6179c77.png

结合对代码的分析，我们发现在Druid 1.1.22版本的源码中，存在对com.mysql.jdbc.MySQLConnection类的加载，而当前我们当前使用的mysql-connector 8.x版本中是不存在这个类的（8.x 使用的是com.mysql.cj.MysqlConnection），导致com.alibaba.druid.util.Utils#loadClass会频繁地对一个不存在的类进行加载，影响服务的整体性能（根因）

在Druid中已经有人针对该问题提交过Issue，并且被官方标记为Bug，详见：com.alibaba:druid:1.1.20 MysqlUtils写死了mysql-connector-java 5.1版本的MySQLConnection类加载，导致线程阻塞，性能受限
该Bug 在1.2.1版本中被修复，修复相关的提交号详见：commit ef2f87b6: 在使用mysql-connector 8.X时，修复检测连接有效性无对应的class

企业微信截图_99c348e9-e91f-4e2e-b837-1ad113212749.png

5、在第3点中，我们提到：Druid 的配置test-on-borrow和test-on-return修改成了false，后面发现这两个配置的修改成为的问题修复的关键。

原因在于： 当testOnBorrow和testOnReturn 为True时，都会调用方法this.testConnectionInternal，而this.testConnectionInternal包含了对com.alibaba.druid.util.MySqlUtils#getLastPacketReceivedTimeMs这个方法的调用，然后触发了在第4点中提到的Bug，感兴趣的同学可以翻阅一下源码

企业微信截图_d6ffe783-cea2-4616-81da-4aa93594af5b.png

总结

问题根因：Druid 1.1.22版本会对一个不存在的com.mysql.jdbc.MySQLConnection类进行重复加载，导致线程阻塞，性能受限
优化项：
- Mysql的官方建议将配置 test-on-borrow 和 test-on-return 设置为false，详见：DruidDataSource参考配置
- 如果使用的是mysql-connector 8.x，建议将Druid版本升级到1.2.1以上