Spring JPA show-sql打印的SQL是执行前输出还是执行后输出

你日志中使用的org.hibernate.engine.jdbc.spi.SqlStatementLogger是Hibernate内置的SQL日志组件，默认配置下，DEBUG级别的SQL日志是在SQL语句发送给数据库执行之前输出的，并非SQL执行完成后才打印。

你贴出的两段日志时间差不能直接等同于SQL执行耗时：

• 第一条INFO日志是DataBuilder.java:294位置输出的业务日志，第二条DEBUG日志是Hibernate准备发送UPDATE语句到Oracle前打印的SQL日志，中间的间隔是业务逻辑执行、事务资源准备阶段的耗时，和SQL本身在数据库内的执行速度无关。
• 这个阶段常见的耗时原因包括：数据库连接池无可用连接导致线程阻塞等待、@Transactional注解对应的事务代理逻辑开销、触发UPDATE操作前的其他业务计算/关联查询（比如JPA懒加载触发的额外SQL）等。

问题日志 #

[INFO ] 2022-06-01 13:38:51.122 (DataBuilder.java:294) 
[DEBUG] 2022-06-01 13:38:52.927 (SqlStatementLogger.java:128) 100365241355070 -http-nio-8989-exec-230 - UPDATE USER_USAGE ....

调用的Repository方法代码 #

@Transactional
@Modifying
@Query(value = "UPDATE USER_USAGE SET DAILY_COUNT = DAILY_COUNT + ?, WEEKLY_COUNT= WEEKLY_COUNT + ?,MONTHLY_COUNT= MONTHLY_COUNT + ?, "
            + " DAILY_USAGE = DAILY_USAGE + ?, WEEKLY_USAGE = WEEKLY_USAGE + ?, MONTHLY_USAGE = MONTHLY_USAGE + ? WHERE USER_ID = ? AND SERVICE_ID = ?", nativeQuery = true)
int updateUsage(int dailyc, int weeklyc, int monthlyc, double dailya, double weeklya, double monthlya, String userId, Integer service);

如果要定位这条UPDATE语句在Oracle中的真实执行耗时，不要依赖SqlStatementLogger的输出，可以采用以下方式：

• 开启JDBC代理层的耗时统计，打印SQL发送、执行完成返回结果的全链路时间
• 直接查询Oracle侧的性能视图（如v$sql）、AWR报告，获取对应SQL的执行时间、等待事件等准确指标

内容的提问来源于stack exchange，提问作者Arun Sudhakaran