java - Spring Boot + JdbcTemplate 有无法解释的查询慢？

Question

我正在使用带有 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

如您所见，从“获取 JDBC 连接”到“返回 JDBC 连接”大约需要 8 秒。

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

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

关于如何调试它有什么想法吗？

Answer 1

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