URL
date
slug
status
tags
summary
type
背景
生产环境收到一则告警通知如下：
可以看到，是数据库连接池满了，无法创建数据库连接了。而我们针对这种场景配置的策略是快速失败，所以会直接报错。
这类异常很容易产生大面积故障，看到之后也是第一时间介入排查。
排查
先查找报错来源，发现只有一台实例有报错（总共有10台）
那么可能是这台实例的问题，并不是代码或者数据库实例的问题。我们又通过当时数据库的负载来验证了这一猜想。（说明一下，整点的升高是由于其他业务，我们这个实例里有很多个库，很多业务共用的）
那么问题一下子就聚焦到10.11.25.176这台机器上了。我们来看看那个点这台机器到底经历了什么？
看了下，这台机器同时段的请求数、消费消息数量均未高于其他机器。所以，排除是请求量大导致的。如果不是请求多，那只能是请求慢了。我们来看看对应时段这台机器上的请求rt：
确实都在18:00:40这个时间点左右，并且rt都还挺高的，我们拿对应的traceId和thread去找一下，看看慢在哪里：
2024-03-05 18:00:40,312 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-192|522] dubbo.accesslog.com.zhu.school.provider.StudentRelativesProvider:: [DUBBO] [2024-03-05 18:00:40] notify-service(10.20.1.158:49480) -> school-service(10.11.25.176:20880) - com.zhu.school.provider.StudentRelativesProvider:1.0.0 findCommonRelativesByStudentIdAndSchoolId(java.lang.Long,java.lang.Long) [1148821,165071], dubbo version: 2.6.5-wireless-1, current host: 10.11.25.176 2024-03-05 18:00:41,081 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-192|522] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686176 connect cost:768 ms 2024-03-05 18:00:41,130 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-192|522] org.apache.tomcat.jdbc.pool.PooledConnection[school]:: connect cost:815 ms, PooledConnection{createTm=1709632840312, seq=35, age=815, poolName='school'} 2024-03-05 18:00:41,130 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-192|522] org.apache.tomcat.jdbc.pool.ConnectionPool[school]:: connection not enough, create one:PooledConnection{createTm=1709632840312, seq=35, age=818, poolName='school'}, current size:2, wanted size:3, busy size:1, idle size:0 2024-03-05 18:00:41,132 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-192|522] dubbo.provider.resultlog.com.zhu.school.provider.StudentRelativesProvider.findCommonRelativesByStudentIdAndSchoolId:: version:1.0.0, serviceName:com.zhu.school.provider.StudentRelativesProvider, methodName:findCommonRelativesByStudentIdAndSchoolId, paramTypes:["java.lang.Long","java.lang.Long"], params:[1148821,165071], attachments:{"path":"com.zhu.school.provider.StudentRelativesProvider","input":"383","dubboApplication":"notify-service","dubbo":"2.0.2","interface":"com.zhu.school.provider.StudentRelativesProvider","version":"1.0.0","W-traceId":"65e6ed489a8277280479a55e","timeout":"1000"}, cost:820, result:{"value":"ignored"}
耗时主要在创建数据库连接上，耗时了
768ms。我们找了其他耗时长的请求发现都是耗在创建数据库连接上（我们有一个mysql-connector层面的Interceptor，会打印所有建立数据库连接和关闭数据库连接的日志）：[dev@school-service-q7tw6 logs]$ grep "onLifeInterceptor" school-service.log-2024-03-05-18 2024-03-05 18:00:40,249 INFO 65e6ecfc9e3f9c218b1464c7 [DubboServerHandler-10.11.25.176:20880-190|520] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5681909 closed 2024-03-05 18:00:40,253 INFO 65e6ed48e504f320473bf1c9 [tomcat-web-6|335] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5681907 closed 2024-03-05 18:00:40,273 INFO 65e6ed4828327b6f72a1a0ab [DubboServerHandler-10.11.25.176:20880-190|520] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5681910 closed 2024-03-05 18:00:40,296 INFO 65e6ed48a0edd3097964319f [DubboServerHandler-10.11.25.176:20880-190|520] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5681911 closed 2024-03-05 18:00:40,304 INFO 65e6ed48a0edd3097964319f [DubboServerHandler-10.11.25.176:20880-190|520] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5681905 closed 2024-03-05 18:00:40,305 INFO 65e6ed37e504f320473bee68 [DubboServerHandler-10.11.25.176:20880-192|522] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5681908 closed 2024-03-05 18:00:40,311 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-192|522] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5681906 closed 2024-03-05 18:00:40,312 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-190|520] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5681904 closed 2024-03-05 18:00:40,312 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-196|526] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5680171 closed 2024-03-05 18:00:40,314 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-190|520] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5679204 closed 2024-03-05 18:00:41,081 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-192|522] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686176 connect cost:768 ms 2024-03-05 18:00:41,082 INFO 65e6ed489e3f9c218b147295 [DubboServerHandler-10.11.25.176:20880-124|418] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686186 connect cost:211 ms 2024-03-05 18:00:41,082 INFO 65e6ed489d899a2924336ac2 [DubboServerHandler-10.11.25.176:20880-118|412] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686179 connect cost:167 ms 2024-03-05 18:00:41,082 INFO 65e6ed488aeb653bca03d9ba [tomcat-web-13|3803] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686181 connect cost:178 ms 2024-03-05 18:00:41,082 INFO 65e6ed483af9bf5d417f1744 [tomcat-web-12|3802] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686190 connect cost:249 ms 2024-03-05 18:00:41,082 INFO 65e6ed484cc4c02bce40032e [DubboServerHandler-10.11.25.176:20880-114|408] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686174 connect cost:145 ms 2024-03-05 18:00:41,082 INFO 65e6ed481c2e264a37c29da3 [DubboServerHandler-10.11.25.176:20880-121|415] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686184 connect cost:184 ms 2024-03-05 18:00:41,082 INFO 65e6ed48a0edd309796431b9 [DubboServerHandler-10.11.25.176:20880-120|414] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686182 connect cost:181 ms 2024-03-05 18:00:41,083 INFO 65e6ed4861ef7c135cefb413 [DubboServerHandler-10.11.25.176:20880-132|432] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686196 connect cost:317 ms 2024-03-05 18:00:41,084 INFO 65e6ed484c723c6267a28be2 [DubboServerHandler-10.11.25.176:20880-123|417] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686185 connect cost:205 ms 2024-03-05 18:00:41,085 INFO 65e6ed48e0b29e67768f72c6 [DubboServerHandler-10.11.25.176:20880-122|416] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686183 connect cost:205 ms 2024-03-05 18:00:41,085 INFO 65e6ed489e3f9c218b147284 [DubboServerHandler-10.11.25.176:20880-155|476] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686224 connect cost:569 ms 2024-03-05 18:00:41,085 INFO 65e6ed48f1271c2314700cce [DubboServerHandler-10.11.25.176:20880-119|413] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686180 connect cost:175 ms 2024-03-05 18:00:41,085 INFO 65e6ed488aeb653bca03d9bc [DubboServerHandler-10.11.25.176:20880-116|410] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686178 connect cost:158 ms 2024-03-05 18:00:41,086 INFO 65e6ed480991712b16c82e63 [tomcat-web-5|322] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686225 connect cost:576 ms 2024-03-05 18:00:41,086 INFO 65e6ed489e3f9c218b147286 [DubboServerHandler-10.11.25.176:20880-152|465] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686221 connect cost:544 ms 2024-03-05 18:00:41,086 INFO 65e6ed48a0edd309796431ab [DubboServerHandler-10.11.25.176:20880-153|466] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686222 connect cost:545 ms 2024-03-05 18:00:41,087 INFO 65e6ed485721aa2f484b411f [tomcat-web-0|236] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686208 connect cost:396 ms 2024-03-05 18:00:41,087 INFO 65e6ed480991712b16c82e78 [DubboServerHandler-10.11.25.176:20880-117|411] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686177 connect cost:162 ms 2024-03-05 18:00:41,087 INFO 65e6ed488aeb653bca03d994 [tomcat-web-4|309] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686239 connect cost:660 ms 2024-03-05 18:00:41,087 INFO 65e6ed484cc4c02bce400326 [DubboServerHandler-10.11.25.176:20880-130|430] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686194 connect cost:272 ms 2024-03-05 18:00:41,087 INFO 65e6ed4861ef7c135cefb414 [tomcat-web-1|242] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686204 connect cost:355 ms 2024-03-05 18:00:41,087 INFO 65e6ed485eb2620670ac9958 [DubboServerHandler-10.11.25.176:20880-146|459] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686214 connect cost:448 ms 2024-03-05 18:00:41,088 INFO 65e6ed488aeb653bca03d9a4 [DubboServerHandler-10.11.25.176:20880-154|475] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686223 connect cost:549 ms 2024-03-05 18:00:41,088 INFO 65e6ed488aeb653bca03d9a3 [DubboServerHandler-10.11.25.176:20880-151|464] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686220 connect cost:544 ms 2024-03-05 18:00:41,088 INFO 65e6ed481c2e264a37c29d89 [DubboServerHandler-10.11.25.176:20880-170|495] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686242 connect cost:676 ms 2024-03-05 18:00:41,088 INFO 65e6ed484baf5b05db582df5 [DubboServerHandler-10.11.25.176:20880-171|496] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686243 connect cost:680 ms 2024-03-05 18:00:41,088 INFO 65e6ed480991712b16c82e73 [DubboServerHandler-10.11.25.176:20880-134|434] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686197 connect cost:322 ms 2024-03-05 18:00:41,088 INFO 65e6ed489e3f9c218b14727a [DubboServerHandler-10.11.25.176:20880-172|498] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686244 connect cost:684 ms 2024-03-05 18:00:41,088 INFO 65e6ed485eb2620670ac9968 [tomcat-web-11|3801] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686192 connect cost:259 ms 2024-03-05 18:00:41,088 INFO 65e6ed48f1271c2314700cb3 [tomcat-web-6|335] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686250 connect cost:716 ms 2024-03-05 18:00:41,089 INFO 65e6ed484cc4c02bce400312 [tomcat-web-7|337] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686233 connect cost:629 ms 2024-03-05 18:00:41,089 INFO 65e6ed480991712b16c82e6d [DubboServerHandler-10.11.25.176:20880-139|450] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686205 connect cost:360 ms 2024-03-05 18:00:41,089 INFO 65e6ed481c2e264a37c29d91 [tomcat-web-2|297] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686219 connect cost:542 ms 2024-03-05 18:00:41,089 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-163|488] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686235 connect cost:651 ms 2024-03-05 18:00:41,089 INFO 65e6ed483af9bf5d417f1731 [DubboServerHandler-10.11.25.176:20880-162|487] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686234 connect cost:646 ms 2024-03-05 18:00:41,089 INFO 65e6ed48e504f320473bf1de [DubboServerHandler-10.11.25.176:20880-142|455] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686210 connect cost:399 ms 2024-03-05 18:00:41,089 INFO 65e6ed37e504f320473bee68 [DubboServerHandler-10.11.25.176:20880-180|507] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686255 connect cost:740 ms 2024-03-05 18:00:41,089 INFO 65e6ed461c2e264a37c29d3b [DubboServerHandler-10.11.25.176:20880-178|505] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686253 connect cost:735 ms 2024-03-05 18:00:41,090 INFO 65e6ecbd5721aa2f484b2c5d [DubboServerHandler-10.11.25.176:20880-176|502] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686251 connect cost:718 ms 2024-03-05 18:00:41,095 INFO 65e6ed1f9e3f9c218b1469be [DubboServerHandler-10.11.25.176:20880-150|463] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686217 connect cost:521 ms 2024-03-05 18:00:41,095 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-197|527] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686264 connect cost:773 ms 2024-03-05 18:00:41,097 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-198|528] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686266 connect cost:775 ms 2024-03-05 18:00:41,097 INFO 65e6ed484baf5b05db582dfa [tomcat-web-8|348] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686229 connect cost:619 ms 2024-03-05 18:00:41,097 INFO 65e6ed488aeb653bca03d9a7 [DubboServerHandler-10.11.25.176:20880-148|461] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686216 connect cost:517 ms 2024-03-05 18:00:41,097 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-190|520] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686269 connect cost:781 ms 2024-03-05 18:00:41,097 INFO 65e6ed48a0edd309796431a5 [DubboServerHandler-10.11.25.176:20880-160|485] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686231 connect cost:622 ms 2024-03-05 18:00:41,097 INFO 65e6ed48f1271c2314700cb5 [DubboServerHandler-10.11.25.176:20880-165|490] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686236 connect cost:664 ms 2024-03-05 18:00:41,097 INFO 65e6ed48cc9a0e6199ede992 [DubboServerHandler-10.11.25.176:20880-143|456] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686211 connect cost:419 ms 2024-03-05 18:00:41,097 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-196|526] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686271 connect cost:783 ms 2024-03-05 18:00:41,097 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-193|523] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686272 connect cost:783 ms 2024-03-05 18:00:41,098 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-189|519] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686273 connect cost:785 ms 2024-03-05 18:00:41,098 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-194|524] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686268 connect cost:780 ms 2024-03-05 18:00:41,098 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-199|529] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686267 connect cost:779 ms 2024-03-05 18:00:41,098 INFO 65e6ed4828327b6f72a1a0bf [DubboServerHandler-10.11.25.176:20880-144|457] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686212 connect cost:427 ms 2024-03-05 18:00:41,098 INFO 65e6ed1f9e3f9c218b1469be [DubboServerHandler-10.11.25.176:20880-141|454] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686207 connect cost:402 ms 2024-03-05 18:00:41,098 INFO 65e6ed48cc9a0e6199ede982 [DubboServerHandler-10.11.25.176:20880-186|516] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686261 connect cost:766 ms 2024-03-05 18:00:41,098 INFO 65e6ed48a0edd309796431a3 [DubboServerHandler-10.11.25.176:20880-166|491] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686238 connect cost:669 ms 2024-03-05 18:00:41,098 INFO 65e6ed484baf5b05db582e0a [DubboServerHandler-10.11.25.176:20880-136|444] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686200 connect cost:342 ms 2024-03-05 18:00:41,099 INFO 65e6ed485eb2620670ac9957 [DubboServerHandler-10.11.25.176:20880-147|460] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686215 connect cost:471 ms 2024-03-05 18:00:41,099 INFO 65e6ed489d899a2924336a9f [DubboServerHandler-10.11.25.176:20880-181|508] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686256 connect cost:751 ms 2024-03-05 18:00:41,099 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-191|521] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686270 connect cost:783 ms 2024-03-05 18:00:41,099 INFO 65e6ed1f9e3f9c218b1469be [DubboServerHandler-10.11.25.176:20880-145|458] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686213 connect cost:445 ms 2024-03-05 18:00:41,099 INFO 65e6ed484c723c6267a28bc7 [tomcat-web-9|351] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686248 connect cost:715 ms 2024-03-05 18:00:41,099 INFO 65e6ed48cc9a0e6199ede986 [DubboServerHandler-10.11.25.176:20880-164|489] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686237 connect cost:664 ms 2024-03-05 18:00:41,099 INFO 65e6ed48cc9a0e6199ede99b [tomcat-web-10|3800] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686203 connect cost:362 ms 2024-03-05 18:00:41,099 INFO 65e6ed489e3f9c218b14728e [DubboServerHandler-10.11.25.176:20880-137|448] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686201 connect cost:349 ms 2024-03-05 18:00:41,100 INFO 65e6ed489e3f9c218b147291 [DubboServerHandler-10.11.25.176:20880-133|433] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686198 connect cost:336 ms 2024-03-05 18:00:41,100 INFO 65e6ed1f9e3f9c218b1469be [DubboServerHandler-10.11.25.176:20880-179|506] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686254 connect cost:747 ms 2024-03-05 18:00:41,100 INFO 65e6ed48e0b29e67768f72ad [DubboServerHandler-10.11.25.176:20880-177|503] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686252 connect cost:742 ms 2024-03-05 18:00:41,100 INFO 65e6ed489e3f9c218b14728c [tomcat-web-3|298] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686209 connect cost:419 ms 2024-03-05 18:00:41,100 INFO 65e6ed489d899a2924336aa0 [DubboServerHandler-10.11.25.176:20880-175|501] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686249 connect cost:719 ms 2024-03-05 18:00:41,100 INFO 65e6ed485eb2620670ac9967 [DubboServerHandler-10.11.25.176:20880-128|428] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686191 connect cost:271 ms 2024-03-05 18:00:41,100 INFO 65e6ed48f1271c2314700cb7 [DubboServerHandler-10.11.25.176:20880-158|479] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686228 connect cost:620 ms 2024-03-05 18:00:41,100 INFO 65e6ed488aeb653bca03d99f [DubboServerHandler-10.11.25.176:20880-159|484] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686230 connect cost:625 ms 2024-03-05 18:00:41,101 INFO 65e6ed489e3f9c218b147282 [DubboServerHandler-10.11.25.176:20880-156|477] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686226 connect cost:600 ms 2024-03-05 18:00:41,101 INFO 65e6ecbd5721aa2f484b2c5d [DubboServerHandler-10.11.25.176:20880-182|512] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686257 connect cost:755 ms 2024-03-05 18:00:41,101 INFO 65e6ed48e504f320473bf1d7 [DubboServerHandler-10.11.25.176:20880-149|462] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686218 connect cost:546 ms 2024-03-05 18:00:41,101 INFO 65e6ed483af9bf5d417f172c [DubboServerHandler-10.11.25.176:20880-188|518] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686262 connect cost:776 ms 2024-03-05 18:00:41,101 INFO 65e6ed488aeb653bca03d98c [DubboServerHandler-10.11.25.176:20880-183|513] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686258 connect cost:760 ms 2024-03-05 18:00:41,101 INFO 65e6ed451c2e264a37c29ce9 [DubboServerHandler-10.11.25.176:20880-169|494] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686245 connect cost:684 ms 2024-03-05 18:00:41,101 INFO 65e6ed480991712b16c82e5e [DubboServerHandler-10.11.25.176:20880-168|493] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686241 connect cost:682 ms 2024-03-05 18:00:41,101 INFO 65e6ed488aeb653bca03d9b0 [DubboServerHandler-10.11.25.176:20880-135|435] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686199 connect cost:338 ms 2024-03-05 18:00:41,102 INFO 65e6ed485eb2620670ac9948 [DubboServerHandler-10.11.25.176:20880-185|515] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686260 connect cost:767 ms 2024-03-05 18:00:41,102 INFO 65e6ed480991712b16c82e62 [DubboServerHandler-10.11.25.176:20880-157|478] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686227 connect cost:610 ms 2024-03-05 18:00:41,102 INFO 65e6ed483af9bf5d417f1745 [DubboServerHandler-10.11.25.176:20880-126|426] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686188 connect cost:261 ms 2024-03-05 18:00:41,102 INFO 65e6ecfc9e3f9c218b1464c7 [DubboServerHandler-10.11.25.176:20880-187|517] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686263 connect cost:770 ms 2024-03-05 18:00:41,102 INFO 65e6ed483af9bf5d417f172e [DubboServerHandler-10.11.25.176:20880-174|500] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686247 connect cost:717 ms 2024-03-05 18:00:41,102 INFO 65e6ed484baf5b05db582e05 [DubboServerHandler-10.11.25.176:20880-140|451] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686206 connect cost:388 ms 2024-03-05 18:00:41,102 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-195|525] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686265 connect cost:780 ms 2024-03-05 18:00:41,103 INFO 65e6ed484baf5b05db582e0e [DubboServerHandler-10.11.25.176:20880-127|427] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686189 connect cost:265 ms 2024-03-05 18:00:41,103 INFO 65e6ed48e504f320473bf1d3 [DubboServerHandler-10.11.25.176:20880-161|486] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686232 connect cost:629 ms 2024-03-05 18:00:41,103 INFO 65e6ed48e0b29e67768f72c2 [DubboServerHandler-10.11.25.176:20880-129|429] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686193 connect cost:279 ms 2024-03-05 18:00:41,103 INFO 65e6ed484cc4c02bce400325 [DubboServerHandler-10.11.25.176:20880-131|431] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686195 connect cost:309 ms 2024-03-05 18:00:41,103 INFO 65e6ed484c723c6267a28bd8 [DubboServerHandler-10.11.25.176:20880-138|449] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686202 connect cost:358 ms 2024-03-05 18:00:41,104 INFO 65e6ed489d899a2924336a9c [DubboServerHandler-10.11.25.176:20880-184|514] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686259 connect cost:766 ms 2024-03-05 18:00:41,104 INFO 65e6ed484c723c6267a28bc6 [DubboServerHandler-10.11.25.176:20880-173|499] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686246 connect cost:713 ms 2024-03-05 18:00:41,104 INFO 65e6ed489d899a2924336abc [DubboServerHandler-10.11.25.176:20880-125|425] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686187 connect cost:253 ms 2024-03-05 18:00:41,104 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-167|492] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686240 connect cost:685 ms 2024-03-05 18:00:41,104 INFO 65e6ed483af9bf5d417f174b [DubboServerHandler-10.11.25.176:20880-115|409] com.zhu.integration.mysql.interceptor.ConnectionLifeInterceptor:: connectionId:5686175 connect cost:170 ms
可以看到，
2024-03-05 18:00:40,249这个时间点左右，数据库连接池的10个连接几乎在同一个时间关闭，导致池里没有可用的连接。请求进来就只能等待创建连接，而此时创建连接的耗时又非常的长，最终每个请求都要去创建连接，导致瞬间创建了100个连接，数据库连接池一下子就打满了。占满时其实一个可用连接都还没有。直到
2024-03-05 18:00:41,081 ，终于有一个连接建立成功，然后陆续100个连接都创建成功，服务恢复正常。[dev@school-service-q7tw6 logs]$ grep "ConnectionLifeInterceptor" school-service.log-2024-03-05-18 | grep 'connect cost' | wc -l 100
池中连接全部在同一时间关闭
那连接同时关闭的原因是什么呢？
好在这个我们二次开发的tomcat-jdbc在每次关闭连接的时候都会打印原因：
2024-03-05 18:00:40,249 INFO 65e6ecfc9e3f9c218b1464c7 [DubboServerHandler-10.11.25.176:20880-190|520] org.apache.tomcat.jdbc.pool.ConnectionPool[school]:: PooledConnection{createTm=1709629239958, seq=29, age=3600291, poolName='school'}will be released because of MAX_AGE_EXPIRED 2024-03-05 18:00:40,253 INFO 65e6ed48e504f320473bf1c9 [tomcat-web-6|335] org.apache.tomcat.jdbc.pool.ConnectionPool[school]:: PooledConnection{createTm=1709629239963, seq=30, age=3600290, poolName='school'}will be released because of MAX_AGE_EXPIRED 2024-03-05 18:00:40,273 INFO 65e6ed4828327b6f72a1a0ab [DubboServerHandler-10.11.25.176:20880-190|520] org.apache.tomcat.jdbc.pool.ConnectionPool[school]:: PooledConnection{createTm=1709629239958, seq=28, age=3600314, poolName='school'}will be released because of MAX_AGE_EXPIRED 2024-03-05 18:00:40,296 INFO 65e6ed48a0edd3097964319f [DubboServerHandler-10.11.25.176:20880-190|520] org.apache.tomcat.jdbc.pool.ConnectionPool[school]:: PooledConnection{createTm=1709629240167, seq=34, age=3600129, poolName='school'}will be released because of MAX_AGE_EXPIRED 2024-03-05 18:00:40,304 INFO 65e6ed48a0edd3097964319f [DubboServerHandler-10.11.25.176:20880-190|520] org.apache.tomcat.jdbc.pool.ConnectionPool[school]:: PooledConnection{createTm=1709629239957, seq=27, age=3600347, poolName='school'}will be released because of MAX_AGE_EXPIRED 2024-03-05 18:00:40,305 INFO 65e6ed37e504f320473bee68 [DubboServerHandler-10.11.25.176:20880-192|522] org.apache.tomcat.jdbc.pool.ConnectionPool[school]:: PooledConnection{createTm=1709629239968, seq=31, age=3600337, poolName='school'}will be released because of MAX_AGE_EXPIRED 2024-03-05 18:00:40,311 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-192|522] org.apache.tomcat.jdbc.pool.ConnectionPool[school]:: PooledConnection{createTm=1709629240165, seq=33, age=3600146, poolName='school'}will be released because of MAX_AGE_EXPIRED 2024-03-05 18:00:40,311 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-190|520] org.apache.tomcat.jdbc.pool.ConnectionPool[school]:: PooledConnection{createTm=1709629239969, seq=32, age=3600342, poolName='school'}will be released because of MAX_AGE_EXPIRED 2024-03-05 18:00:40,312 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-196|526] org.apache.tomcat.jdbc.pool.ConnectionPool[school]:: PooledConnection{createTm=1709627750257, seq=26, age=5090055, poolName='school'}will be released because of MAX_AGE_EXPIRED 2024-03-05 18:00:40,314 INFO 65e6ed489a8277280479a55e [DubboServerHandler-10.11.25.176:20880-190|520] org.apache.tomcat.jdbc.pool.ConnectionPool[school]:: PooledConnection{createTm=1709626955185, seq=25, age=5885128, poolName='school'}will be released because of MAX_AGE_EXPIRED
可以看到，全部都是因为
MAX_AGE_EXPIRED，也就是超过了连接池配置的连接生命周期。我们配置的生命周期是3600s。但是最后2个连接，其实已经远超1小时了，理论上早就应该释放掉了。这个是因为判定连接生命周期是在每次连接归还到连接池的时刻，所以如果这个连接一直没有被取出来使用，它就会一直待在池子里岁月静好。
并且，tomcat-jdbc连接池对于取连接的策略是——越频繁使用的连接越容易被取出（是通过放回连接的时候把连接放在了队首）。这么一来，大大增加了连接超过max age的概率
更进一步，我们又跟踪了一下从应用启动到出现故障之间的所有连接的生命周期日志。这确实是一个潜在的问题：tomcat-jdbc连接池有一个
initialSize 参数，用来控制连接池创建时会初始化的连接个数。我们配置的数量为10个。这个时候这10个初始化出来的连接的创建时间几乎是一致的。这就带来了一个致命的问题，它们的失效时间也是一致的。这就有点像缓存届大名鼎鼎的“缓存雪崩”问题——同一时间所有连接都失效了，导致所有请求等待连接创建。优化
分析出原因之后，优化就比较简单了。我这里采用了2个方法：
- 连接创建之后，会为它生成一个随机值，这个随机值参与计算连接的最大生命周期。这样就可以把同一时间创建的连接的失效时间错开。
public class PooledConnection { public static final Random RANDOM = new Random(); private volatile long randomMiles; public void connect() throws SQLException { // 省略其余代码 long maxAge = getPoolProperties().getMaxAge(); int range = (int) (maxAge / 10); if (range > 0) { this.randomMiles = RANDOM.nextInt(range); } log.info("connect cost:" + (this.lastConnected - beforeConnect) + " ms, and randomMiles:" + this.randomMiles + ", " + this); } public boolean isMaxAgeExpired() { if (getPoolProperties().getMaxAge()>0 ) { return (System.currentTimeMillis() - getLastConnected() + randomMiles) > getPoolProperties().getMaxAge(); } else { return false; } } }
- 异步任务在检测空闲连接的时候增加生命周期的校验，防止池中存在远远超过最大生命周期的连接。
public void testAllIdle() { try { if (idle.size()==0) return; Iterator<PooledConnection> unlocked = idle.iterator(); while (unlocked.hasNext()) { PooledConnection con = unlocked.next(); try { con.lock(); //the con been taken out, we can't clean it up if (busy.contains(con)) continue; if (!con.validate(PooledConnection.VALIDATE_IDLE)) { idle.remove(con); release(con); log.warn("Connection has been released for idle test failed, " + con); } else if (con.isMaxAgeExpired()) { // 此分支为新增逻辑 idle.remove(con); release(con); log.info(con + "will be released because of " + ShouldCloseReasonEn.MAX_AGE_EXPIRED.name()); } } finally { con.unlock(); } } //while } catch (ConcurrentModificationException e) { log.debug("testAllIdle failed." ,e); } catch (Exception e) { log.warn("testAllIdle failed, it will be retried.",e); } }
- 作者:黑微狗
- 链接:https://blog.hwgzhu.com/article/tomcat-jdbc-pool-exausted
- 声明:本文采用 CC BY-NC-SA 4.0 许可协议，转载请注明出处。
.jpeg?table=block&id=9c5834f3-d0d0-4740-bf3c-7b77e72b9452){kind=tracking}