[DBCP-381] Threads BLOCKED on stress tests

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Invalid
• Labels: BLOCKED PERFORMANCE ROLLBACK
• Assignee: Unassigned
• Reporter: Carlos Martinez
• Created: 13/Apr/12 07:39
• Updated: 31/May/14 04:08
• Resolved: 30/Jan/14 12:55

Description

Hi,

We are performing stress tests of OpenCMS. The database used is Oracle one. The pool of connections that OpenCMS is using is the DBCP pool.

While performing performance tests we see that with minimal load already generated, almost all of the threads in java get "BLOCKED" trying to release back connections to the pool, and the performance of the application is really poor. We also see that the CPU consumption on the application server machine goes up to 100%. We are not generating enough load to cause this consumption. I believe that the CPU is all spent trying to handle those BLOCK threads.

We did perform a thread dump of the Java on many occasions and the pattern is always similar. Plenty of connections blocked releasing the connection:

-------------------
"TP-Processor8" daemon prio=10 tid=0x00007fa2848b4000 nid=0x4713 waiting for monitor entry [0x00007fa2833f8000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.commons.pool.impl.GenericObjectPool.returnObject(GenericObjectPool.java:916)

• waiting to lock <0x0000000780ba7cc8> (a org.apache.commons.pool.impl.GenericObjectPool)
  at org.apache.commons.dbcp.PoolableConnection.close(PoolableConnection.java:87)
• locked <0x00000007811a6f78> (a org.apache.commons.dbcp.PoolableConnection)
  at org.apache.commons.dbcp.PoolingDriver$PoolGuardConnectionWrapper.close(PoolingDriver.java:269)
  at org.opencms.ocee.db.transaction.CmsTransactionConnection.close(CmsTransactionConnection.java:79)
  at org.opencms.ocee.db.transaction.CmsTransaction.close(CmsTransaction.java:121)
  at org.opencms.ocee.db.transaction.CmsTransactionDbContext.clear(CmsTransactionDbContext.java:99)
  at org.opencms.db.CmsSecurityManager.readFile(CmsSecurityManager.java:3351)
  at org.opencms.file.CmsObject.readFile(CmsObject.java:2725)
  at org.opencms.file.CmsObject.readFile(CmsObject.java:2777)
  at org.opencms.file.CmsObject.readFile(CmsObject.java:2747)
  at org.apache.jsp.WEB_002dINF.jsp.online.system.modules.org_opentrends_upf_template.templates.mainUPF_jsp._jspService(mainUPF_jsp.java:654)
  at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:98)
  -------------

And one thread active releasing the connection:

-------------
"TP-Processor10" daemon prio=10 tid=0x00007fa284b34800 nid=0x4715 runnable [0x00007fa2831f4000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at oracle.net.ns.Packet.receive(Unknown Source)
at oracle.net.ns.DataPacket.receive(Unknown Source)
at oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)
at oracle.net.ns.NetInputStream.read(Unknown Source)
at oracle.net.ns.NetInputStream.read(Unknown Source)
at oracle.net.ns.NetInputStream.read(Unknown Source)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1104)
at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1075)
at oracle.jdbc.driver.T4C7Ocommoncall.receive(T4C7Ocommoncall.java:106)
at oracle.jdbc.driver.T4CConnection.doRollback(T4CConnection.java:568)

• locked <0x00000007810e2ac0> (a oracle.jdbc.driver.T4CConnection)
  at oracle.jdbc.driver.PhysicalConnection.rollback(PhysicalConnection.java:1164)
• locked <0x00000007810e2ac0> (a oracle.jdbc.driver.T4CConnection)
  at org.apache.commons.dbcp.DelegatingConnection.rollback(DelegatingConnection.java:328)
  at org.apache.commons.dbcp.DelegatingConnection.rollback(DelegatingConnection.java:328)
  at org.apache.commons.dbcp.PoolableConnectionFactory.passivateObject(PoolableConnectionFactory.java:359)
  at org.apache.commons.pool.impl.GenericObjectPool.addObjectToPool(GenericObjectPool.java:926)
  at org.apache.commons.pool.impl.GenericObjectPool.returnObject(GenericObjectPool.java:917)
• locked <0x0000000780ba7cc8> (a org.apache.commons.pool.impl.GenericObjectPool)
  at org.apache.commons.dbcp.PoolableConnection.close(PoolableConnection.java:87)
• locked <0x00000007810e29b0> (a org.apache.commons.dbcp.PoolableConnection)
  at org.apache.commons.dbcp.PoolingDriver$PoolGuardConnectionWrapper.close(PoolingDriver.java:269)
  at org.opencms.ocee.db.transaction.CmsTransactionConnection.close(CmsTransactionConnection.java:79)
  at org.opencms.ocee.db.transaction.CmsTransaction.close(CmsTransaction.java:121)
  at org.opencms.ocee.db.transaction.CmsTransactionDbContext.clear(CmsTransactionDbContext.java:99)
  at org.opencms.db.CmsSecurityManager.readFile(CmsSecurityManager.java:3351)
  at org.opencms.file.CmsObject.readFile(CmsObject.java:2725)
  ------------

As we can see the thread releasing the connection is performing a rollback, probably so that the connection gets back clean to the pool.

In this case the application is not performing Updates/Deletes or Inserts. In the future it will, but not in the stress tests.

This is a big issue, as a Rollback is not a light operation, even when it has not to rollback many actions.

This is affecting the pool, as while the connection is performing rollback nobody can use the pool as it is locked.

This does not make any sense.

I believe that what is happening is:

1) I lock the pool
2) I perform a rollback of the connection
3) I return the connection to the pool
4) I unlock the pool

Why is the rollback holding the pool??? The rollback should be done before locking the pool. It would be better if:

1) I perform a rollback of the connection
2) I lock the pool
3) I return the connection to the pool
4) I unlock the pool

I have seen many threads on internet of people having this kind of locking under stress tests, and I believe this could be the cause. The lock should be hold really the shortest time possible.

Thanks,
Carlos