【发布时间】:2014-07-09 13:06:15
【问题描述】:
我们有一个使用 Hibernate 查询 Oracle 数据库的 Grails 应用程序。
一个相对简单的条件查询,当通过 SQL Developer 之类的工具直接针对数据库运行时,最多需要二十分之一秒,从几分之一秒到 30 秒完成。
将logSql 设置为true 并确认生成的SQL 是高性能的(说明计划成本大约为100,执行时间为10-30 毫秒),我们通过设置仔细研究了Hibernate 的功能其日志记录级别为TRACE。
这是我们在标准输出中看到的:
******************** START HIBERNATE QUERY TRACE *****************
start time (millis): 1400772671767
2014-05-22 11:31:11,767 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction - begin
2014-05-22 11:31:11,767 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction - current autocommit status: true
2014-05-22 11:31:11,767 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction - disabling autocommit
2014-05-22 11:31:11,767 [http-bio-8080-exec-5] TRACE jdbc.JDBCContext - after transaction begin
2014-05-22 11:31:11,770 [http-bio-8080-exec-5] TRACE loader.Loader - querySpaces is [REDACTED]
2014-05-22 11:31:11,770 [http-bio-8080-exec-5] TRACE loader.Loader - transformer=org.hibernate.transform.RootEntityResultTransformer returnTypes=[ REDACTED ] returnClasses=[ class REDACTED ]
2014-05-22 11:31:11,770 [http-bio-8080-exec-5] DEBUG jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2014-05-22 11:31:11,771 [http-bio-8080-exec-5] DEBUG hibernate.SQL - select REDACTED
2014-05-22 11:31:11,771 [http-bio-8080-exec-5] TRACE jdbc.AbstractBatcher - preparing statement
2014-05-22 11:31:11,771 [http-bio-8080-exec-5] TRACE sql.BasicBinder - binding parameter [1] as REDACTED
2014-05-22 11:31:11,771 [http-bio-8080-exec-5] TRACE sql.BasicBinder - binding parameter [2] as REDACTED
2014-05-22 11:31:11,772 [http-bio-8080-exec-5] TRACE sql.BasicBinder - binding parameter [3] as REDACTED
2014-05-22 11:31:11,772 [http-bio-8080-exec-5] TRACE loader.Loader - Bound [4] parameters total
2014-05-22 11:31:12,323 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564865835008
2014-05-22 11:31:12,324 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:12,324 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:12,324 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564865839104
2014-05-22 11:31:12,324 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:12,324 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:14,331 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564874059776
2014-05-22 11:31:14,331 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:14,331 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:14,331 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564874059777
2014-05-22 11:31:14,331 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:14,332 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:16,339 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564882284544
2014-05-22 11:31:16,339 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:16,339 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:16,339 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564882284545
2014-05-22 11:31:16,340 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:16,340 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:18,348 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564890513408
2014-05-22 11:31:18,348 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:18,348 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:18,348 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564890513409
2014-05-22 11:31:18,349 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:18,349 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:20,356 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564898738176
2014-05-22 11:31:20,356 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:20,356 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:20,356 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564898738177
2014-05-22 11:31:20,357 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:20,357 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564906958848
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564906962944
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:24,373 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564915191808
2014-05-22 11:31:24,373 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:24,373 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:24,373 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564915191809
2014-05-22 11:31:24,374 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:24,374 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564923408384
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564923408385
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:28,387 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564931633152
2014-05-22 11:31:28,387 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:28,387 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:28,387 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564931633153
2014-05-22 11:31:28,387 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:28,388 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:30,395 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564939857920
2014-05-22 11:31:30,396 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:30,396 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:30,396 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564939862016
2014-05-22 11:31:30,396 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:30,396 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:32,403 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564948082688
2014-05-22 11:31:32,404 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:32,404 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:32,404 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564948086784
2014-05-22 11:31:32,404 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:32,404 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:34,408 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564956295168
2014-05-22 11:31:34,409 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:34,409 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:34,409 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564956299264
2014-05-22 11:31:34,409 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:34,409 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:36,416 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564964519936
2014-05-22 11:31:36,416 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:36,416 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:36,416 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564964519937
2014-05-22 11:31:36,416 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:36,417 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:38,421 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564972732416
2014-05-22 11:31:38,422 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:38,422 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:38,422 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564972736512
2014-05-22 11:31:38,422 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:38,422 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:40,428 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564980953088
2014-05-22 11:31:40,429 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:40,429 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:40,429 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564980957184
2014-05-22 11:31:40,429 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:40,429 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:42,436 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564989177856
2014-05-22 11:31:42,437 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:42,437 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:42,437 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564989181952
2014-05-22 11:31:42,437 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:42,437 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:44,441 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564997390336
2014-05-22 11:31:44,442 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:44,442 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:44,442 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737564997394432
2014-05-22 11:31:44,442 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:44,442 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:46,449 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737565005615104
2014-05-22 11:31:46,450 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:46,450 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:46,450 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737565005619200
2014-05-22 11:31:46,450 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:46,450 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737565013839872
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] DEBUG impl.SessionImpl - opened session at timestamp: 5737565013843968
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] TRACE impl.SessionImpl - closing session
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager - connection already null in cleanup : no action
2014-05-22 11:31:49,985 [http-bio-8080-exec-5] DEBUG jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] TRACE loader.Loader - processing result set
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] TRACE loader.Loader - done processing result set (0 rows)
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] DEBUG jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] DEBUG jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] TRACE jdbc.AbstractBatcher - closing statement
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] TRACE loader.Loader - total objects hydrated: 0
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] DEBUG engine.StatefulPersistenceContext - initializing non-lazy collections
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] TRACE loader.Loader - transformer=org.hibernate.transform.RootEntityResultTransformer returnTypes=[ REDACTED ] returnClasses=[ class REDACTED ]
2014-05-22 11:31:49,987 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction - commit
2014-05-22 11:31:49,987 [http-bio-8080-exec-5] TRACE impl.SessionImpl - automatically flushing session
2014-05-22 11:31:49,987 [http-bio-8080-exec-5] TRACE def.AbstractFlushingEventListener - flushing session
2014-05-22 11:31:49,987 [http-bio-8080-exec-5] REDACTED
2014-05-22 11:31:49,989 [http-bio-8080-exec-5] TRACE jdbc.ConnectionManager - registering flush begin
2014-05-22 11:31:49,989 [http-bio-8080-exec-5] TRACE jdbc.ConnectionManager - registering flush end
2014-05-22 11:31:49,989 [http-bio-8080-exec-5] TRACE def.AbstractFlushingEventListener - post flush
2014-05-22 11:31:49,989 [http-bio-8080-exec-5] TRACE jdbc.JDBCContext - before transaction completion
2014-05-22 11:31:49,989 [http-bio-8080-exec-5] TRACE impl.SessionImpl - before transaction completion
2014-05-22 11:31:49,991 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction - re-enabling autocommit
2014-05-22 11:31:49,991 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction - committed JDBC Connection
2014-05-22 11:31:49,991 [http-bio-8080-exec-5] TRACE jdbc.JDBCContext - after transaction completion
2014-05-22 11:31:49,991 [http-bio-8080-exec-5] DEBUG jdbc.ConnectionManager - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] TRACE impl.SessionImpl - after transaction completion
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] DEBUG impl.SessionImpl - disconnecting session
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] TRACE jdbc.ConnectionManager - performing cleanup
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] DEBUG jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] TRACE jdbc.JDBCContext - after transaction completion
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] DEBUG jdbc.ConnectionManager - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] TRACE impl.SessionImpl - after transaction completion
end time (millis): 1400772709992
difference: 38.225 seconds
******************* END HIBERNATE QUERY TRACE ********************
让我提醒您注意什么引起了我们的注意——大约每 2 秒重复一次的六行代码——opened session 然后closing session 然后connection already null,在一毫秒内完成了两次。
每隔 2 秒左右,Hibernate 会打开并立即关闭 2 个会话?我是否正确解释了这一点?什么情况下会做这样的事情?
DataSource.groovy中的数据源配置基本:
dataSource_REDACTED {
driverClassName = 'oracle.jdbc.OracleDriver'
dialect = 'org.hibernate.dialect.Oracle10gDialect'
url = 'jdbc:oracle:thin:@REDACTED:1521/REDACTED'
username = 'REDACTED'
password = 'REDACTED'
pooled = true
properties {
maxActive = 20
minIdle = 1
initialSize = 10
testOnBorrow = true
testWhileIdle = true
validationQuery = "SELECT 1 FROM DUAL"
}
}
那里没有properties {} 块,因此无论使用空闲超时等属性的默认值。
同一个文件里还有一个hibernate配置:
hibernate {
cache.use_second_level_cache = true
cache.use_query_cache = true
cache.provider_class = 'net.sf.ehcache.hibernate.EhCacheProvider'
}
正如我之前所说,我正在执行的条件查询相当简单:
withTransaction {
List<MyAwesomeClass> awesomeThings = withCriteria {
between("importantTime", startDate, endDate)
eq("importantField", targetValue)
}
}
条件查询是从 Grails 域类中的一个方法运行的,该方法由控制器直接调用,而不是事务服务,因此我将其包装在 withTransaction 中。
无论如何,简而言之,这里的交易是什么?为什么在 something (不确定是什么)发生并且查询实际执行之前,这会搞乱会话?尝试创建连接时是否与数据库本身的可用性有关?
【问题讨论】:
标签: oracle hibernate session grails transactions