Spring Boot + JdbcTemplate 出现无法解释的查询缓慢？答案

【问题标题】：Spring Boot + JdbcTemplate has unexplained query slowness?Spring Boot + JdbcTemplate 出现无法解释的查询缓慢？
【发布时间】：2017-01-25 06:11:21
【问题描述】：

我正在使用带有 JdbcTemplate 和默认 Tomcat 连接池的 Spring Boot。

当我在 MVC 应用程序中点击路由时，它会使用 JdbcTemplate 运行查询。以下是日志：

Sep 16 16:04:34 beta.dw java[24249]: 2016-09-16 16:04:34.441 DEBUG 24249 --- [io-8080-exec-10] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL update
Sep 16 16:04:34 beta.dw java[24249]: 2016-09-16 16:04:34.443 DEBUG 24249 --- [io-8080-exec-10] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [UPDATE tokens SET last_accessed = NOW() where token = ?]
Sep 16 16:04:34 beta.dw java[24249]: 2016-09-16 16:04:34.444 DEBUG 24249 --- [io-8080-exec-10] o.s.jdbc.datasource.DataSourceUtils      : Fetching JDBC Connection from DataSource
Sep 16 16:04:34 beta.dw java[24249]: 2016-09-16 16:04:34.451 DEBUG 24249 --- [io-8080-exec-10] o.s.jdbc.core.JdbcTemplate               : SQL update affected 1 rows
Sep 16 16:04:34 beta.dw java[24249]: 2016-09-16 16:04:34.452 DEBUG 24249 --- [io-8080-exec-10] o.s.jdbc.datasource.DataSourceUtils      : Returning JDBC Connection to DataSource
Sep 16 16:04:34 beta.dw java[24249]: 2016-09-16 16:04:34.457  INFO 24249 --- [io-8080-exec-10] e.u.d.d.w.e.u.d.d.w.c.CensusController   : Before census query:Fri Sep 16 16:04:34 PDT 2016
Sep 16 16:04:34 beta.dw java[24249]: 2016-09-16 16:04:34.458 DEBUG 24249 --- [io-8080-exec-10] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL query
Sep 16 16:04:34 beta.dw java[24249]: 2016-09-16 16:04:34.459 DEBUG 24249 --- [io-8080-exec-10] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [SELECT o.acad_term_code, o.crse_num, o.acad_subject_code, sum(s.current_enrol_cnt) as current_enrol_cnt, sum(o.max_enrol_cnt) as max_enrol_cnt, s.snapshot_code, sum(s.wait_cnt) as wait_cnt FROM course_sect_snapshot s INNER JOIN course_sect_offering o ON s.crn_num = o.crn_num AND s.acad_term_code = o.acad_term_code AND s.vers = o.vers WHERE s.vers = (SELECT max(vers) FROM cdw_vers WHERE import_finished IS NOT NULL) AND o.acad_subject_code = ? AND o.crse_num = ? AND s.snapshot_code IN ('INSTR_BEG', 'CURRENT', 'DAY5', 'DAY10', 'DAY15') GROUP BY o.acad_term_code, o.acad_subject_code, o.crse_num, s.snapshot_code ORDER BY o.acad_term_code, o.crse_num]
Sep 16 16:04:34 beta.dw java[24249]: 2016-09-16 16:04:34.460 DEBUG 24249 --- [io-8080-exec-10] o.s.jdbc.datasource.DataSourceUtils      : Fetching JDBC Connection from DataSource
Sep 16 16:04:42 beta.dw java[24249]: 2016-09-16 16:04:42.243 DEBUG 24249 --- [io-8080-exec-10] o.s.jdbc.datasource.DataSourceUtils      : Returning JDBC Connection to DataSource
Sep 16 16:04:42 beta.dw java[24249]: 2016-09-16 16:04:42.244  INFO 24249 --- [io-8080-exec-10] e.u.d.d.w.e.u.d.d.w.c.CensusController   : After census query:Fri Sep 16 16:04:42 PDT 2016

如您所见，“Fetching JDBC Connection”和“Returning JDBC Connection”之间大约需要 8 秒。

但是，查询不需要 8 秒。通过 'mysql' 命令在同一台服务器上运行相同的查询显示确切的查询（填写相同的参数）大约需要 1.8 秒。

缺少的 6.2s 是从哪里来的？我怀疑 Tomcat 连接池 - 例如，当我在启动 Spring Boot 后执行我的第一个查询时，只有那时 - 不是在启动时而是在页面加载时 - Tomcat 连接池才会费心收集连接。

任何想法如何去调试这个？

【问题讨论】：

从外观上看，您似乎有连接泄漏。您的应用程序代码可能无法正确释放连接。如果不查看获取连接、使用并释放它的整个代码，就不可能说出问题出在哪里。另请注意，某些连接池（包括 Tomcat）在回收连接方面很差。使用较新的池（如 HikariCP 或 BoneCP）可以为您提供更好的结果。

标签： java mysql spring-mvc connection-pooling

【解决方案1】：

结果证明这是与在 VM 中运行的 MySQL 相关的性能问题。

【讨论】：