-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 4 posts ] 
Author Message
 Post subject: GlobalMaxOnlyStatementCache threads lock issue
PostPosted: Sat Nov 30, 2013 5:44 am 
Newbie

Joined: Sat Nov 30, 2013 5:24 am
Posts: 3
Hello Support Team,
We are facing an issue with one of the JAVA process which is using Hibernate to connect to Oracle DB. We think Hibernate is causing memory leak because of the delay in SQL query execution based on our application thread dump and it may be resulting into high cpu utilization of Oracle DB as well.

Please have a look at the stack trace below and let us know if there is any issue with hibernate here.. thanks

INFO | jvm 2 | 2013/11/28 02:40:49 | "TopoMgr.ModifyNodeMsgProcessor.159" prio=3 tid=0x01b6e400 nid=0xfc in Object.wait() [0x20b9e000]
INFO | jvm 2 | 2013/11/28 02:40:49 | java.lang.Thread.State: BLOCKED (on object monitor)
INFO | jvm 2 | 2013/11/28 02:40:49 | at java.lang.Object.wait(Native Method)
INFO | jvm 2 | 2013/11/28 02:40:49 | at java.lang.Object.wait(Object.java:485)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.mchange.v2.c3p0.stmt.GooGooStatementCache.acquireStatement(GooGooStatementCache.java:552)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.mchange.v2.c3p0.stmt.GooGooStatementCache.checkoutStatement(GooGooStatementCache.java:168)
INFO | jvm 2 | 2013/11/28 02:40:49 | - locked <0x594c0990> (a com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.mchange.v2.c3p0.impl.NewPooledConnection.checkoutStatement(NewPooledConnection.java:277)
INFO | jvm 2 | 2013/11/28 02:40:49 | - locked <0x5c71fd60> (a com.mchange.v2.c3p0.impl.NewPooledConnection)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:199)
INFO | jvm 2 | 2013/11/28 02:40:49 | - locked <0xe09955e0> (a com.mchange.v2.c3p0.impl.NewProxyConnection)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:534)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:452)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:161)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1573)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.doQuery(Loader.java:696)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.loadEntity(Loader.java:1881)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:71)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:65)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3072)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:434)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:415)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:165)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:223)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:126)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:905)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:873)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:590)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.type.EntityType.resolve(EntityType.java:412)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:139)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:877)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.doQuery(Loader.java:752)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.loadEntity(Loader.java:1881)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:71)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:65)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3072)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:434)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:415)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:165)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:223)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:126)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:905)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:873)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:590)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.type.EntityType.resolve(EntityType.java:412)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:139)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:877)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.doQuery(Loader.java:752)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.Loader.loadEntity(Loader.java:1881)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:71)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:65)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3072)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:434)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:415)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:165)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:223)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:126)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:905)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.impl.SessionImpl.get(SessionImpl.java:842)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.impl.SessionImpl.get(SessionImpl.java:835)
INFO | jvm 2 | 2013/11/28 02:40:49 | at org.hibernate.ejb.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:182)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.motorola.nsm.common.node.NodeInfoMgrImpl.getInTx(NodeInfoMgrImpl.java:504)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.motorola.nsm.common.node.NodeInfoMgrImpl.get(NodeInfoMgrImpl.java:408)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.motorola.nsm.common.node.NodeInfoMgrImpl.get(NodeInfoMgrImpl.java:444)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.motorola.nsm.common.tm.TopoMgr.sendModifyResponse(TopoMgr.java:3870)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.motorola.nsm.common.tm.TmNodeValidator.doSystemOpValidate(TmNodeValidator.java:262)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.motorola.nsm.common.tm.TopoMgr.startModifyValidator(TopoMgr.java:3676)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.motorola.nsm.common.tm.TopoMgr.access$800(TopoMgr.java:145)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.motorola.nsm.common.tm.TopoMgr$8.procMessage(TopoMgr.java:398)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.motorola.nsm.common.services.mbc.MBCMessageProcessor.run(MBCMessageProcessor.java:103)



INFO | jvm 2 | 2013/11/28 02:40:49 | "com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#79" daemon prio=3 tid=0x019f6800 nid=0x8a waiting for monitor entry [0x2301f000]
INFO | jvm 2 | 2013/11/28 02:40:49 | java.lang.Thread.State: BLOCKED (on object monitor)
INFO | jvm 2 | 2013/11/28 02:40:49 | at oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1338)
INFO | jvm 2 | 2013/11/28 02:40:49 | - waiting to lock <0x5c6cf640> (a oracle.jdbc.driver.T4CConnection)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
INFO | jvm 2 | 2013/11/28 02:40:49 | at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)


Top
 Profile  
 
 Post subject: Re: GlobalMaxOnlyStatementCache threads lock issue
PostPosted: Sun Dec 01, 2013 2:58 am 
Newbie

Joined: Sat Nov 30, 2013 5:24 am
Posts: 3
Any update on this issue?


Top
 Profile  
 
 Post subject: Re: GlobalMaxOnlyStatementCache threads lock issue
PostPosted: Mon Dec 02, 2013 12:05 am 
Newbie

Joined: Sat Nov 30, 2013 5:24 am
Posts: 3
We are struck totally in this issue in our production setup, can someone please look into this and replay?


Top
 Profile  
 
 Post subject: Re: GlobalMaxOnlyStatementCache threads lock issue
PostPosted: Wed Mar 05, 2014 5:16 pm 
Expert
Expert

Joined: Sat Jan 17, 2004 2:57 pm
Posts: 329
Location: In the basement in my underwear
If it's the same type of issue we ran into it's not a Hibernate problem but a problem with C3P0 and it's implementation of statement caching with the global setting.

The problem happens when you have closed statements available for cleanup that are associated with connection that is active in the pool.

Connection 1 opens and closes a number of prepared statements so that they become available for reaping and starts a long running query (someone runs a massive report). In executing the query Oracle obtains a lock on the session until the query completes.
Connections 2+ try to obtain a statement but the pool is full so the cache tries to cull the oldest statements which happen to be from connection 1. Each statement will only be processed once but it will try to obtain a lock on the connection in order to close the statement. However, the lock is still in place from the running query and will only be released once the query completes.

If you are still fighting with it I recommend looking at using a per connection cache instead. In our case we completely killed statement caching for the short term while we evaluate other pooling options. We'll take a hit in performance vs hard blocks.

_________________
Some people are like Slinkies - not really good for anything, but you still can't help but smile when you see one tumble down the stairs.


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 4 posts ] 

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.