Hibernate 花费了太多时间并执行了一些神秘的操作。
Posted
技术标签:
【中文标题】Hibernate 花费了太多时间并执行了一些神秘的操作。【英文标题】：Hibernate takes too much time and performs some cryptic actions.. 【发布时间】：2013-09-15 23:50:44 【问题描述】：我不了解 hibernate 执行的很多操作。例如：TwoPhaseLoad、Loader、EntityPrinter 等...虽然我添加了 cp30（连接池）属性，但 hibernate 正在为每个查询打开/关闭 jdbc 连接..
另外，任何人都可以建议如何减少查询时间。在这种情况下，我只获取 7 个对象，它需要将近 3 秒...仅供参考，我没有使用任何关联..
CP30 Props:
<prop key="hibernate.c3p0.min_size">5</prop>
<prop key="hibernate.c3p0.max_size">20</prop>
<prop key="hibernate.c3p0.timeout">300</prop>
<prop key="hibernate.c3p0.max_statements">50</prop>
<prop key="hibernate.c3p0.idle_test_period">3000</prop>
18:03:18,037 DEBUG LogicalConnectionImpl:212 - Obtaining JDBC connection
18:03:18,048 DEBUG LogicalConnectionImpl:218 - Obtained JDBC connection
18:03:18,056 DEBUG AbstractTransactionImpl:158 - begin
18:03:18,056 DEBUG JdbcTransaction:69 - initial autocommit status: true
18:03:18,057 DEBUG JdbcTransaction:71 - disabling autocommit
18:03:18,135 DEBUG QueryTranslatorImpl:265 - parse() - HQL: from XXX
18:03:18,146 DEBUG QueryTranslatorImpl:283 - --- HQL AST ---
\-[QUERY] Node: 'query'
\-[SELECT_FROM] Node: 'SELECT_FROM'
\-[FROM] Node: 'from'
\-[RANGE] Node: 'RANGE'
\-[DOT] Node: '.'
+-[DOT] Node: '.'
| +-[DOT] Node: '.'
| | +-[DOT] Node: '.'
| | | +-[IDENT] Node: 'XXX'
| | | \-[IDENT] Node: 'XXX'
| | \-[IDENT] Node: 'XXX'
| \-[IDENT] Node: 'XXX'
\-[IDENT] Node: 'XXX'
18:03:18,146 DEBUG ErrorCounter:82 - throwQueryException() : no errors
18:03:18,181 DEBUG HqlSqlBaseWalker:121 - select << begin [level=1, statement=select]
18:03:18,205 DEBUG FromElement:157 - FromClauselevel=1 : XXX (<no alias>) -> region0_
18:03:18,205 DEBUG HqlSqlBaseWalker:125 - select : finishing up [level=1, statement=select]
18:03:18,206 DEBUG HqlSqlWalker:629 - processQuery() : ( SELECT ( FromClauselevel=1 CRMMAINT.dbo.Region region0_ ) )
18:03:18,212 DEBUG HqlSqlWalker:869 - Derived SELECT clause created.
18:03:18,221 DEBUG JoinProcessor:175 - Using FROM fragment [CRMMAINT.dbo.Region region0_]
18:03:18,222 DEBUG HqlSqlBaseWalker:129 - select >> end [level=1, statement=select]
18:03:18,223 DEBUG QueryTranslatorImpl:252 - --- SQL AST ---
\-[SELECT] QueryNode: 'SELECT' querySpaces (CRMMAINT.dbo.Region)
+-[SELECT_CLAUSE] SelectClause: 'derived select clause'
| +-[SELECT_EXPR] SelectExpressionImpl: 'region0_.Region as Region1_12_, region0_.Country as Country2_12_' FromElementexplicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=null,role=null,tableName=CRMMAINT.dbo.Region,tableAlias=region0_,origin=null,columns=,className=XXX
| \-[SQL_TOKEN] SqlFragment: 'region0_.Description as Descript3_12_, region0_.Display as Display4_12_'
\-[FROM] FromClause: 'from' FromClauselevel=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[], fromElementByTableAlias=[region0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]
\-[FROM_FRAGMENT] FromElement: 'CRMMAINT.dbo.Region region0_' FromElementexplicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=null,role=null,tableName=CRMMAINT.dbo.Region,tableAlias=region0_,origin=null,columns=,className=XXX
18:03:18,224 DEBUG ErrorCounter:82 - throwQueryException() : no errors
18:03:18,234 DEBUG QueryTranslatorImpl:235 - HQL: from XXX
18:03:18,234 DEBUG QueryTranslatorImpl:236 - SQL: select region0_.Region as Region1_12_, region0_.Country as Country2_12_, region0_.Description as Descript3_12_, region0_.Display as Display4_12_ from CRMMAINT.dbo.Region region0_
18:03:18,235 DEBUG ErrorCounter:82 - throwQueryException() : no errors
18:03:18,319 DEBUG SQL:104 - select region0_.Region as Region1_12_, region0_.Country as Country2_12_, region0_.Description as Descript3_12_, region0_.Display as Display4_12_ from CRMMAINT.dbo.Region region0_
18:03:18,333 DEBUG Loader:941 - Result set row: 0
18:03:18,339 DEBUG Loader:1475 - Result row: EntityKey[XXX#component[region,country]region=CANADA, country=Canada]
18:03:18,348 DEBUG Loader:941 - Result set row: 1
18:03:18,349 DEBUG Loader:1475 - Result row: EntityKey[XXX#component[region,country]region=US-CAN OPS, country=United States]
18:03:18,350 DEBUG Loader:941 - Result set row: 2
18:03:18,350 DEBUG Loader:1475 - Result row: EntityKey[XXX#component[region,country]region=US1 - NORTH WEST, country=United States]
18:03:18,351 DEBUG Loader:941 - Result set row: 3
18:03:18,352 DEBUG Loader:1475 - Result row: EntityKey[XXX#component[region,country]region=US2 - GULF PLAINS, country=United States]
18:03:18,352 DEBUG Loader:941 - Result set row: 4
18:03:18,353 DEBUG Loader:1475 - Result row: EntityKey[XXX#component[region,country]region=US3 - MID CENTRAL, country=United States]
18:03:18,354 DEBUG Loader:941 - Result set row: 5
18:03:18,354 DEBUG Loader:1475 - Result row: EntityKey[XXX#component[region,country]region=US4 - SOUTH EAST, country=United States]
18:03:18,355 DEBUG Loader:941 - Result set row: 6
18:03:18,356 DEBUG Loader:1475 - Result row: EntityKey[XXX#component[region,country]region=US5 - NORTH EAST, country=United States]
18:03:18,358 DEBUG TwoPhaseLoad:158 - Resolving associations for [XXX#component[region,country]region=CANADA, country=Canada]
18:03:18,361 DEBUG TwoPhaseLoad:277 - Done materializing entity [XXX#component[region,country]region=CANADA, country=Canada]
18:03:18,363 DEBUG TwoPhaseLoad:158 - Resolving associations for [XXX#component[region,country]region=US-CAN OPS, country=United States]
18:03:18,363 DEBUG TwoPhaseLoad:277 - Done materializing entity [XXX#component[region,country]region=US-CAN OPS, country=United States]
18:03:18,364 DEBUG TwoPhaseLoad:158 - Resolving associations for [XXX#component[region,country]region=US1 - NORTH WEST, country=United States]
18:03:18,364 DEBUG TwoPhaseLoad:277 - Done materializing entity [XXX#component[region,country]region=US1 - NORTH WEST, country=United States]
18:03:18,365 DEBUG TwoPhaseLoad:158 - Resolving associations for [XXX#component[region,country]region=US2 - GULF PLAINS, country=United States]
18:03:18,366 DEBUG TwoPhaseLoad:277 - Done materializing entity [XXX#component[region,country]region=US2 - GULF PLAINS, country=United States]
18:03:18,366 DEBUG TwoPhaseLoad:158 - Resolving associations for [XXX#component[region,country]region=US3 - MID CENTRAL, country=United States]
18:03:18,367 DEBUG TwoPhaseLoad:277 - Done materializing entity [XXX#component[region,country]region=US3 - MID CENTRAL, country=United States]
18:03:18,367 DEBUG TwoPhaseLoad:158 - Resolving associations for [XXX#component[region,country]region=US4 - SOUTH EAST, country=United States]
18:03:18,375 DEBUG TwoPhaseLoad:277 - Done materializing entity [XXX#component[region,country]region=US4 - SOUTH EAST, country=United States]
18:03:18,376 DEBUG TwoPhaseLoad:158 - Resolving associations for [XXX#component[region,country]region=US5 - NORTH EAST, country=United States]
18:03:18,377 DEBUG TwoPhaseLoad:277 - Done materializing entity [XXX#component[region,country]region=US5 - NORTH EAST, country=United States]
18:03:18,381 DEBUG ConcurrentStatisticsImpl:411 - HHH000117: HQL: from Region, time: 71ms, rows: 7
18:03:18,384 DEBUG AbstractTransactionImpl:173 - committing
18:03:18,385 DEBUG AbstractFlushingEventListener:143 - Processing flush-time cascades
18:03:18,389 DEBUG AbstractFlushingEventListener:184 - Dirty checking collections
18:03:18,393 DEBUG AbstractFlushingEventListener:117 - Flushed: 0 insertions, 0 updates, 0 deletions to 7 objects
18:03:18,394 DEBUG AbstractFlushingEventListener:124 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
18:03:18,396 DEBUG EntityPrinter:114 - Listing entities:
18:03:18,415 DEBUG EntityPrinter:121 - XXXid=component[region,country]region=US2 - GULF PLAINS, country=United States, description=Gulf Plains, display=1
18:03:18,415 DEBUG EntityPrinter:121 - XXXid=component[region,country]region=US5 - NORTH EAST, country=United States, description=North East, display=1
18:03:18,416 DEBUG EntityPrinter:121 - XXXid=component[region,country]region=CANADA, country=Canada, description=Canada, display=1
18:03:18,416 DEBUG EntityPrinter:121 - XXXid=component[region,country]region=US3 - MID CENTRAL, country=United States, description=Mid Central, display=1
18:03:18,417 DEBUG EntityPrinter:121 - XXXid=component[region,country]region=US4 - SOUTH EAST, country=United States, description=South East, display=1
18:03:18,417 DEBUG EntityPrinter:121 - XXXid=component[region,country]region=US-CAN OPS, country=United States, description=US-CAN OPS, display=1
18:03:18,417 DEBUG EntityPrinter:121 - XXXid=component[region,country]region=US1 - NORTH WEST, country=United States, description=North West, display=1
18:03:18,418 DEBUG JdbcTransaction:113 - committed JDBC Connection
18:03:18,418 DEBUG JdbcTransaction:126 - re-enabling autocommit
18:03:18,420 DEBUG LogicalConnectionImpl:232 - Releasing JDBC connection
18:03:18,421 DEBUG LogicalConnectionImpl:250 - Released JDBC connection
18:03:20,424 DEBUG LogicalConnectionImpl:212 - Obtaining JDBC connection
18:03:20,432 DEBUG LogicalConnectionImpl:218 - Obtained JDBC connection
18:03:20,433 DEBUG AbstractTransactionImpl:158 - begin
18:03:20,433 DEBUG JdbcTransaction:69 - initial autocommit status: true
18:03:20,434 DEBUG JdbcTransaction:71 - disabling autocommit
18:03:20,449 DEBUG QueryTranslatorImpl:265 - parse() - HQL: SELECT l FROM Location l WHERE l.region = :region
【问题讨论】：
【参考方案1】：您已激活调试信息；尝试使用Turning off hibernate logging console output 禁用并检查您的查询是否运行得更快；通常控制台输出是性能的杀手。
【讨论】：
我过去曾尝试过。它加快了进程，但我仍然不知道为什么我会看到很多隐秘的冬眠活动。比如两相负载等等。 .【参考方案2】：从日志看来，它花费了大部分时间来释放 JDBC 连接并获取它。 尝试在互联网上搜索“Hibernate 重用连接”。
但是，坦率地说，我可以建议您使用fjorm，它简单、轻量且快速，而不是休眠。免责声明：我是 fjorm 的创始人。
【讨论】：
感谢您的推荐.. 但我的领导特别关注休眠.. 我认为我做错了什么..以上是关于Hibernate 花费了太多时间并执行了一些神秘的操作。的主要内容，如果未能解决你的问题，请参考以下文章