Hibernate Transaction Connection Pool Exhaustion with MongoDB plugin.

[themarchoffolly]

Hi,

I've recently completed a port of a large Grails application which included replacing the original MySQL data store and with a MongoDB data store using the MongoDB GORM plugin. It all appeared to be going well until I introduced some initial and pretty basic load on the server: a test consisting of 5 sequential calls on the server being made by 15 concurrent clients.

Each time this series of tests are run the server effectively locks up after about 60 (out of 75) of the test calls have completed. Having generated a thread dump on the server in this locked up state I can see there are a large number of threads all waiting on a connection associated with a new transaction initiated by SessionImpl.beginTransaction(). The thread dump snippet can be found below.

With the server in this blocked state I've attempted further calls on the server. Any call that does not require a transaction completes just fine. Any call that requires a transaction, such as a call from a Controller to a transactional method on a Service or anywhere a call to SomeDomain.withTransaction or SomeDomain.withNewTransaction that call will end up being blocked in the exact same way.

Without understanding the inner workings of the Grails Hibernate transaction manager I can't tell exactly what's happening here but I'm guessing that somehow calls to the server are taking connections from the Hibernate transaction manager connection pool but not returning them to the pool after use with the resulting resource exhaustion in the pool is blocking all further calls.

Can anyone explain what the cause might be for the problem I'm describing here, perhaps this is a known bug? Perhaps there's a known solution, workaround? Any help very much appreciated as right now I'm in deadlock.

I'm using: Grails 2.0.3, MongoDB:1.0.0.GA. My DataSource is as follows:

        grails {
            mongo {
                host = "localhost"
                port = 27017
                databaseName = "mydb"
                options {
                    connectionsPerHost = 100
                    autoConnectRetry = true
                    connectTimeout = 300
                }
            }
        }


Locked up server thread dump stack trace snippet below.

Thanks,
David


"ajp-bio-8008-exec-15" daemon prio=10 tid=0x00002aaab8022800 nid=0x31b9 in Object.wait() [0x000000004408f000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000f4c39660> (a org.apache.commons.pool.impl.GenericObjectPool$Latch)
    at java.lang.Object.wait(Object.java:485)
    at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1115)
    - locked <0x00000000f4c39660> (a org.apache.commons.pool.impl.GenericObjectPool$Latch)
    at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
    at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
    at org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.java:224)
    at $Proxy25.getAutoCommit(Unknown Source)
    at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
    at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
    at org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:555)
    at org.codehaus.groovy.grails.orm.hibernate.GrailsHibernateTransactionManager.super$3$doBegin(GrailsHibernateTransactionManager.groovy)
    at sun.reflect.GeneratedMethodAccessor337.invoke(Unknown Source)


--
"It's possible that my whole purpose in life is simply to serve as a warning to others."

[Octavian Covalschi]

Have you uninstalled hibernate plugin? Or you still need both mysql and mongodb? I mean I wonder how are you ending by triggering hibernate's transaction with mongodb, since there are not meant to be...

On Thu, Jul 26, 2012 at 10:39 PM, David Russell <[hidden email]> wrote:

Hi,

I've recently completed a port of a large Grails application which included replacing the original MySQL data store and with a MongoDB data store using the MongoDB GORM plugin. It all appeared to be going well until I introduced some initial and pretty basic load on the server: a test consisting of 5 sequential calls on the server being made by 15 concurrent clients.

Each time this series of tests are run the server effectively locks up after about 60 (out of 75) of the test calls have completed. Having generated a thread dump on the server in this locked up state I can see there are a large number of threads all waiting on a connection associated with a new transaction initiated by SessionImpl.beginTransaction(). The thread dump snippet can be found below.

With the server in this blocked state I've attempted further calls on the server. Any call that does not require a transaction completes just fine. Any call that requires a transaction, such as a call from a Controller to a transactional method on a Service or anywhere a call to SomeDomain.withTransaction or SomeDomain.withNewTransaction that call will end up being blocked in the exact same way.

Without understanding the inner workings of the Grails Hibernate transaction manager I can't tell exactly what's happening here but I'm guessing that somehow calls to the server are taking connections from the Hibernate transaction manager connection pool but not returning them to the pool after use with the resulting resource exhaustion in the pool is blocking all further calls.

Can anyone explain what the cause might be for the problem I'm describing here, perhaps this is a known bug? Perhaps there's a known solution, workaround? Any help very much appreciated as right now I'm in deadlock.

I'm using: Grails 2.0.3, MongoDB:1.0.0.GA. My DataSource is as follows:

        grails {
            mongo {
                host = "localhost"
                port = 27017
                databaseName = "mydb"
                options {
                    connectionsPerHost = 100
                    autoConnectRetry = true
                    connectTimeout = 300
                }
            }
        }


Locked up server thread dump stack trace snippet below.

Thanks,
David


"ajp-bio-8008-exec-15" daemon prio=10 tid=0x00002aaab8022800 nid=0x31b9 in Object.wait() [0x000000004408f000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000f4c39660> (a org.apache.commons.pool.impl.GenericObjectPool$Latch)
    at java.lang.Object.wait(Object.java:485)
    at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1115)
    - locked <0x00000000f4c39660> (a org.apache.commons.pool.impl.GenericObjectPool$Latch)
    at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
    at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
    at org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.java:224)
    at $Proxy25.getAutoCommit(Unknown Source)
    at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
    at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
    at org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:555)
    at org.codehaus.groovy.grails.orm.hibernate.GrailsHibernateTransactionManager.super$3$doBegin(GrailsHibernateTransactionManager.groovy)
    at sun.reflect.GeneratedMethodAccessor337.invoke(Unknown Source)


--
"It's possible that my whole purpose in life is simply to serve as a warning to others."

[themarchoffolly]

<[hidden email]> wrote:

Have you uninstalled hibernate plugin? Or you still need both mysql and mongodb?

So I've tried my application with and without the hibernate plugin installed. In both cases I see the exact same failure with the exact same stack trace.
 

I mean I wonder how are you ending by triggering hibernate's transaction with mongodb, since there are not meant to be...

Good question, the stack trace clearly shows hibernate classes, such as:

org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)

The only answer that I can think of that makes sense is that the Mongo plugin depends on Grails datasource GORM plugins and that those datasource plugin somehow still has dependencies on some of the hibernate classes.

As improbable as that seems I can't explain it any other way. It would be great if Graeme could chime in here, how can a Grails app with a Mongo-only (no-Hibernate) plugin dependency show hibernate classes in a stack trace?

In the meantime, Octavian thanks for your inputs. Any more, very welcome.

--
"It's possible that my whole purpose in life is simply to serve as a warning to others."

[themarchoffolly]

Just to close out this thread. While I had removed the hibernate plugin dependency from BuildConfig it turns out that a call on grails upgrade had unexpectedly added the hibernate plugin back into my application.properties. This explains why hibernate classes were still appearing in the stack trace.

With the hibernate plugin properly removed from the application this issue is resolved.

On Fri, Jul 27, 2012 at 11:10 AM, David Russell <[hidden email]> wrote:

<[hidden email]> wrote:

Have you uninstalled hibernate plugin? Or you still need both mysql and mongodb?

So I've tried my application with and without the hibernate plugin installed. In both cases I see the exact same failure with the exact same stack trace.
 

I mean I wonder how are you ending by triggering hibernate's transaction with mongodb, since there are not meant to be...

Good question, the stack trace clearly shows hibernate classes, such as:

org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)

The only answer that I can think of that makes sense is that the Mongo plugin depends on Grails datasource GORM plugins and that those datasource plugin somehow still has dependencies on some of the hibernate classes.

As improbable as that seems I can't explain it any other way. It would be great if Graeme could chime in here, how can a Grails app with a Mongo-only (no-Hibernate) plugin dependency show hibernate classes in a stack trace?

In the meantime, Octavian thanks for your inputs. Any more, very welcome.

--
"It's possible that my whole purpose in life is simply to serve as a warning to others."

--
"It's possible that my whole purpose in life is simply to serve as a warning to others."