[1.3.1] Could not open connection - Possible causes

[Ivan Viragine]

Hi!

Hope you guys could help me out: I have several jobs on my app and sometimes it gives a timeout getting a db connection from the pool, resulting on the app to hang forever, forcing me to force restart the server (tomcat).

Postgresql has 160 maxConnections parameters, my pool goes from 100 to 145 on Play.

The stack:

11:25:26,113 ERROR ~ An attempt by a client to checkout a Connection has timed out.

11:25:26,114 ERROR ~

@6ol3fdafg

Internal Server Error (500)

Oops: PersistenceException

An unexpected error occured caused by exception PersistenceException: org.hibernate.exception.GenericJDBCException: Could not open connection

play.exceptions.UnexpectedException: Unexpected Error

        at play.Invoker$Invocation.onException(Invoker.java:245)

        at play.Invoker$Invocation.run(Invoker.java:305)

        at play.server.ServletWrapper$ServletInvocation.run(ServletWrapper.java:557)

        at play.Invoker.invokeInThread(Invoker.java:69)

        at play.server.ServletWrapper.service(ServletWrapper.java:145)

        at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)

        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)

        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)

        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)

        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)

        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)

        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)

        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)

        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:957)

        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)

        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423)

        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079)

        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:620)

        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:318)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)

        at java.lang.Thread.run(Thread.java:745)

Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Could not open connection

        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387)

        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310)

        at org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1397)

        at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:62)

        at play.db.jpa.JPA.withTransaction(JPA.java:254)

        at play.db.jpa.JPA.withinFilter(JPA.java:217)

        at play.db.jpa.JPAPlugin$TransactionalFilter.withinFilter(JPAPlugin.java:299)

        at play.Invoker$Invocation.withinFilter(Invoker.java:271)

        at play.Invoker$Invocation.run(Invoker.java:287)

        ... 24 more

Caused by: org.hibernate.exception.GenericJDBCException: Could not open connection

        at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54)

        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:124)

        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109)

        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:221)

        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:157)

        at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:67)

        at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:160)

        at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1351)

        at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:59)

        ... 29 more

Caused by: java.sql.SQLException: An attempt by a client to checkout a Connection has timed out.

        at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:118)

        at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:77)

        at org.hibernate.service.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:141)

        at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:301)

        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:214)

        ... 34 more

Caused by: com.mchange.v2.resourcepool.TimeoutException: A client timed out while waiting to acquire a resource from com.mchange.v2.resourcepool.BasicResourcePool@2d1a9076 -- timeout at awaitAvailable()

        at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1461)

        at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:639)

        at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:549)

        ... 37 more

The app still runs for a while, but seems that after a while it starts giving this error for every request, then, server hangs.

Sounds like a connection leak, but I don't know if that's it nor the cause.

Instead of explaining the whole scenario, I think maybe it's better to know if you guys could help me out listing possible causes for this, then we discuss my scenario.

Can anyone help me?

[Ivan Viragine]

Digging deeper, we found that is more of a memory leak than a issue with the pool.

The heap dump shows that the amount of char[] and byte[] is insanely high, which is causing this memory rise, leading to the pooling error...

Has anyone experienced these errors on Play 1.3.1?

[Scott Rippee]

Hi Ivan,

I'm running 1.4.1 and haven't ran into that issue, I didn't check if it's the same version of c3p0 and Hibernate..  

Are you setting JDBC connection and request timeout values?  That may have an effect, although I'm not sure now that you've tracked it down to a memory problem.

[Ivan Viragine]

Hi Scott!

Thanks for the reply.

I've got the dump on MAT, it shows that 30% of the memory is allocated by hibernate's session, which is allocated by tomcats class loader. It says that this may be the leak cause.

Searched a lot and found that Tomcat has leaks issues when the JDBC driver is bundled in the WAR (that's play's default setting), so I moved it to tomcat's lib folder.

I'm still seeing my memory goes up, but can't get a dump right now from production... I'm still checking my code to see if I may have not closed the session somewhere (I never even open a session, it's all controlled by Play, but I'm checking, anyway).

I also updated my dev to 1.4.1, i'll try to deploy it ASAP.

I'm out of guesses :(

[Scott Rippee]

It'll be interesting to hear if 1.4.1 helps.  FYI I'm running using the built in netty server. My pool configured to min 15 max 80 (not that the pool size  should matter)..

[Ivan Viragine]

Hi Scott!

Haven't updated my prod env with 1.4.1, but, removed the postgresql driver from the app's dir and put it on tomcat's dir. It seems that this resolved the issue (at least GC is clearing the heap).

Thanks!