[2.0.1-scala] In production: "java.sql.SQLException: Timed out waiting for a free available connection." when there are plenty of connections available

[Jxtps]

I'm starting to see exceptions like these in my log files:

 

[ERROR] [05/20/2012 18:21:21.172] [application-akka.actor.default-dispatcher-5] [akka://application/user/$a] Timed out waiting for a free available connection.
java.sql.SQLException: Timed out waiting for a free available connection.
        at com.jolbox.bonecp.BoneCP.getConnection(BoneCP.java:503)
        at com.jolbox.bonecp.BoneCPDataSource.getConnection(BoneCPDataSource.java:114)
        at play.api.db.DBApi$class.getConnection(DB.scala:62)
        at play.api.db.BoneCPApi.getConnection(DB.scala:264)
        at play.api.db.DBApi$class.withConnection(DB.scala:75)
        at play.api.db.BoneCPApi.withConnection(DB.scala:264)
        at play.api.db.DB$$anonfun$withConnection$3.apply(DB.scala:156)
        at play.api.db.DB$$anonfun$withConnection$3.apply(DB.scala:156)
        at scala.Option.map(Option.scala:133)
        at play.api.db.DB$.withConnection(DB.scala:156)
        at models.User$.expireCredits(User.scala:170)
        at actors.UserHelper$$anonfun$receive$1.apply(UserHelper.scala:52)
        at actors.UserHelper$$anonfun$receive$1.apply(UserHelper.scala:44)
        at akka.actor.Actor$class.apply(Actor.scala:311)
        at actors.UserHelper.apply(UserHelper.scala:43)
        at akka.actor.ActorCell.invoke(ActorCell.scala:619)
        at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:196)
        at akka.dispatch.Mailbox.run(Mailbox.scala:178)
        at akka.dispatch.ForkJoinExecutorConfigurator$MailboxExecutionTask.exec(AbstractDispatcher.scala:505)
        at akka.jsr166y.ForkJoinTask.doExec(ForkJoinTask.java:259)
        at akka.jsr166y.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:974)
        at akka.jsr166y.ForkJoinPool.runWorker(ForkJoinPool.java:1478)
        at akka.jsr166y.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:104)

 

However:

 

mysql> show variables like 'max_connections';
+-----------------+-------+
| Variable_name   | Value |
+-----------------+-------+
| max_connections | 991   |
+-----------------+-------+

 

and the number of connections to it hasn't exceeded 101 connections over the last week: http://imgur.com/lBiaH - specifically, around 5/20/2012 @ 18:21 there were <90 connections active.

 

It appears to happen intermittently - sometimes you get a couple of them in a row, then they go away for a while, then they come back (based on inspecting the logs). When I encountered one while using the site myself the timeout was very short, at most a second or so (though I didn't use a stopwatch - I wasn't expecting it to not work ;)

 

Q: Any pointers? Are there some configuration options I'm not setting correctly?

 

 

Also, I've seen entries like this in both dev & production:

 

WARN  - BoneCP detected an unclosed connection and will now attempt to close it for you. You should be closing this connection in your application - enable connectionWatch for additional debugging assistance.

 

???

 

Thanks!

[Jxtps]

https://groups.google.com/forum/?fromgroups#!topic/play-framework/LRc37zPRkf4 has some relevant info but no apparent resolution.

 

I'm actually running four applications, three of them use the same usage style as Drew (DB.withConnection { ... }), and one uses Squeryl (that one hasn't had any exceptions so far).

 

Not timing out the connections sounds ideal. This is eerily reminiscent of ActiveRecord issues in Rails 1.x - plus ca change... ;)

[Jxtps]

For anyone interested in the BoneCP configuration used in Play2.0.1, don't miss play.api.db.BoneCPApi.createDataSource (in DB.scala) since it completely overrides BoneCPs 1) defaults 2) names used in the configuration (BoneCP has a much more flexible naming convention which may lead you to believe you've set something that you haven't).

 

In 2.0.1, the configuration section is:

 

    // Pool configuration
    datasource.setPartitionCount(conf.getInt("partitionCount").getOrElse(1))
    datasource.setMaxConnectionsPerPartition(conf.getInt("maxConnectionsPerPartition").getOrElse(30))
    datasource.setMinConnectionsPerPartition(conf.getInt("minConnectionsPerPartition").getOrElse(5))
    datasource.setAcquireIncrement(conf.getInt("acquireIncrement").getOrElse(1))
    datasource.setAcquireRetryAttempts(conf.getInt("acquireRetryAttempts").getOrElse(10))
    datasource.setAcquireRetryDelayInMs(conf.getMilliseconds("acquireRetryDelay").getOrElse(1000))
    datasource.setConnectionTimeoutInMs(conf.getMilliseconds("connectionTimeout").getOrElse(1000))
    datasource.setIdleMaxAge(conf.getMilliseconds("idleMaxAge").getOrElse(1000 * 60 * 10), java.util.concurrent.TimeUnit.MILLISECONDS)
    datasource.setMaxConnectionAge(conf.getMilliseconds("maxConnectionAge").getOrElse(1000 * 60 * 60), java.util.concurrent.TimeUnit.MILLISECONDS)
    datasource.setDisableJMX(conf.getBoolean("disableJMX").getOrElse(true))
    datasource.setIdleConnectionTestPeriod(conf.getMilliseconds("idleConnectionTestPeriod").getOrElse(1000 * 60), java.util.concurrent.TimeUnit.MILLISECONDS)

 

As of this writing that code is on: https://github.com/playframework/Play20/blob/master/framework/src/play/src/main/scala/play/api/db/DB.scala#L362

 

Increasing connectionTimeout seems reasonable - 1 second sounds a bit aggressive.

[mortimer]

Hi,

I get this too, have you found a solution? Increasing the timeout seems fine, but if there are connections not being closed (as the warning suggest) then there is something more to it than the timeout :S

Thanks

Pierre

[MG]

I am too getting the same error message and exception. Have you found a solution?

-MG

On Thursday, May 24, 2012 10:49:27 AM UTC-7, Jxtps wrote:

On Thursday, May 24, 2012 10:49:27 AM UTC-7, Jxtps wrote:

[Jxtps]

I added a controller action like so:

 

  def keepDbConnectionFresh = Action {
    DB.withConnection(c => 1)
    Ok("ok")
  }

 

and then my external process monitor ( http://mmonit.com/monit/ ) hits that URL once per minute.

 

It's very crude, but so far it seems to work - haven't seen any of the exceptions in the logs since, and I've been running with this for the last couple of days.

 

 

Presumably you could just schedule an Akka callback, something along the lines of:

 

Akka.system.scheduler.schedule(2.minutes, 2.minute)({DB.withConnection(c => 1)})

but I haven't tested that.

 

 

[MG]

Thank you for sharing your work around.

I am trying out a different technique. It seems that by default Play sets getConnection timeout to 1 sec, which could be a problem depending on network latency if the database and app are not running on the same machine. I am increasing it to 5 sec and see if that fixes the issue.

-MG

[Jxtps]

Sorry, forgot to mention, I did add:

 

db.default.connectionTimeout=10000

i.e. a ten second timeout. I didn't test this change independently of the other, so it's quite possible that this one is enough (though https://groups.google.com/forum/?fromgroups#!topic/play-framework/LRc37zPRkf4 seemed to indicate that a 30 second timeout wasn't).

[MG]

It is all right.

According to the BoneCP developer, here is the code that throws the exception:

result = connectionPartition.getFreeConnections().poll(this.connectionTimeoutInMs, TimeUnit.MILLISECONDS);
            if (result == null){
               if (this.nullOnConnectionTimeout){
                  return null;
               }
               // 08001 = The application requester is unable to establish the connection.
               throw new SQLException("Timed out waiting for a free available connection.", "08001");
            }


Looking at this code, it would seem that 5-10 seconds should be plenty unless the network or database is down.

-MG

[Nilanjan]

Use db.connectionTestStatement configuration to specify the query that
should be used by the datasource to check that the connnection is
live.

Thanks
Nilanjan

On May 29, 1:17 pm, Jxtps <jxtps...@gmail.com> wrote:
> Sorry, forgot to mention, I did add:
>
> db.default.connectionTimeout=10000
> i.e. a ten second timeout. I didn't test this change independently of the

> other, so it's quite possible that this one is enough (thoughhttps://groups.google.com/forum/?fromgroups#!topic/play-framework/LRc...seemed

> to indicate that a 30 second timeout wasn't).
>
>
>
>
>
>
>
> On Tuesday, May 29, 2012 10:13:43 AM UTC-7, MG wrote:
> > Thank you for sharing your work around.
>
> > I am trying out a different technique. It seems that by default Play sets
> > getConnection timeout to 1 sec, which could be a problem depending on
> > network latency if the database and app are not running on the same
> > machine. I am increasing it to 5 sec and see if that fixes the issue.
>
> > -MG
>
> > On Tuesday, May 29, 2012 9:48:54 AM UTC-7, Jxtps wrote:
>
> >> I added a controller action like so:
>
> >>>   def keepDbConnectionFresh = Action {
> >>>     DB.withConnection(c => 1)
> >>>     Ok("ok")
> >>>   }
>

> >> and then my external process monitor ( *http://mmonit.com/monit/*<http://mmonit.com/monit/> )

> >>>> over the last week: *http://imgur.com/lBiaH*<http://imgur.com/lBiaH> -

> >>>> specifically, around 5/20/2012 @ 18:21 there were <90 connections active.
>
> >>>> It appears to happen intermittently - sometimes you get a couple of
> >>>> them in a row, then they go away for a while, then they come back (based on
> >>>> inspecting the logs). When I encountered one while using the site
> >>>> myself the timeout was very short, at most a second or so (though I didn't
> >>>> use a stopwatch - I wasn't expecting it to not work ;)
>

> >>>> *Q: Any pointers? Are there some configuration options I'm not setting
> >>>> correctly?*

> >>>> over the last week: *http://imgur.com/lBiaH*<http://imgur.com/lBiaH> -

> >>>> specifically, around 5/20/2012 @ 18:21 there were <90 connections active.
>
> >>>> It appears to happen intermittently - sometimes you get a couple of
> >>>> them in a row, then they go away for a while, then they come back (based on
> >>>> inspecting the logs). When I encountered one while using the site
> >>>> myself the timeout was very short, at most a second or so (though I didn't
> >>>> use a stopwatch - I wasn't expecting it to not work ;)
>

> >>>> *Q: Any pointers? Are there some configuration options I'm not setting
> >>>> correctly?*

[MG]

Thanks Nilanjan for trying to help us out.

I do have that in my config file, but looking at the BoneCP documentation, it seems BoneCP uses a default connectionTestStatement if you do not explicitly set it. So, IMHO, the lack of connectionTestStatement should not cause the timeout exception.

-MG

[Nilanjan]

Hmm...interesting. In that case you should not get a connection from
the pool that already timed out. Do you know what test statement it
uses?

Nilanjan

On May 29, 2:00 pm, MG <mohammed.gul...@gmail.com> wrote:
> Thanks Nilanjan for trying to help us out.
>
> I do have that in my config file, but looking at the BoneCP documentation,
> it seems BoneCP uses a default connectionTestStatement if you do not
> explicitly set it. So, IMHO, the lack of connectionTestStatement should not
> cause the timeout exception.
>
> -MG
>
>
>
>
>
>
>
> On Tuesday, May 29, 2012 10:35:03 AM UTC-7, Nilanjan wrote:
>
> > Use db.connectionTestStatement configuration to specify the query that
> > should be used by the datasource to check that the connnection is
> > live.
>
> > Thanks
> > Nilanjan
>
> > On May 29, 1:17 pm, Jxtps <jxtps...@gmail.com> wrote:
> > > Sorry, forgot to mention, I did add:
>
> > > db.default.connectionTimeout=10000
> > > i.e. a ten second timeout. I didn't test this change independently of
> > the
> > > other, so it's quite possible that this one is enough (thoughhttps://

> > groups.google.com/forum/?fromgroups#!topic/play-framework/LRc...seemed<http://groups.google.com/forum/?fromgroups#%21topic/play-framework/LR...>

> ...
>
> read more »

[MG]

Apparently it sends a meta data request as per the doc:

setConnectionTestStatement

public void setConnectionTestStatement(String connectionTestStatement)

Sets the connection test statement. The query to send to the DB to maintain keep-alives and test for dead connections. This is database specific and should be set to a query that consumes the minimal amount of load on the server. Examples: MySQL: "/* ping *\/ SELECT 1", PostgreSQL: "SELECT NOW()". If you do not set this, then BoneCP will issue a metadata request instead that should work on all databases but is probably slower. (Note: In MySQL, prefixing the statement by /* ping *\/ makes the driver issue 1 fast packet instead. See http://blogs.sun.com/SDNChannel/entry/mysql_tips_for_java_developers )

Default: Use metadata request

Parameters:

connectionTestStatement - to set.

[Nilanjan]

Thanks for the response. So it seems that setConnectionTestStatement
is not working properly then? I looked around but didn't see any
complains/issues.

Nilanjan

On May 29, 2:29 pm, MG <mohammed.gul...@gmail.com> wrote:
> Apparently it sends a meta data request as per the doc:
>
> setConnectionTestStatement
>

> public void *setConnectionTestStatement*(String <http://java.sun.com/javase/6/docs/api/java/lang/String.html?is-extern...> connectionTestStatement)

>
> Sets the connection test statement. The query to send to the DB to maintain
> keep-alives and test for dead connections. This is database specific and
> should be set to a query that consumes the minimal amount of load on the
> server. Examples: MySQL: "/* ping *\/ SELECT 1", PostgreSQL: "SELECT
> NOW()". If you do not set this, then BoneCP will issue a metadata request
> instead that should work on all databases but is probably slower. (Note: In
> MySQL, prefixing the statement by /* ping *\/ makes the driver issue 1 fast
> packet instead. Seehttp://blogs.sun.com/SDNChannel/entry/mysql_tips_for_java_developers)
>
> Default: Use metadata request
>

>  *Parameters:*connectionTestStatement - to set.

> ...
>
> read more »

[MG]

I think that that setConnectionTestStatement is working, but it has nothing to do with the call to getFreeConnections(). The exception that we are getting is thrown by getFreeConnections(). My guess is that after the connections have been idle for sometime, they get closed. So getFreeConnection tries to open a new one and if takes longer than the set timeout, it throws an exception. The default timeout set by Play was 1 sec, which may or may not be enough depending on network latency, etc. As long as an open connection is available in the pool, getFreeConnections seems to work fine.

-MG

[Ivan Meredith]

Did anyone ever figure out what was happening with this? I got it after upgrading to play 2.1

[Ondřej Kroupa]

I have the same issue on Play 2.1 RC2.

Dne středa, 21. listopadu 2012 6:33:39 UTC+1 Ivan Meredith napsal(a):

[Eishay Smith]

I have the same issue as well using Play 2.1.1.

--

You received this message because you are subscribed to the Google Groups "play-framework" group.

To unsubscribe from this group and stop receiving emails from it, send an email to play-framewor...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[somatik]

could be related to this bug:

https://bugs.launchpad.net/bonecp/+bug/999114

more info in this thread:

https://groups.google.com/forum/#!topic/play-framework/RM1QwOFz-2A

(I'm using the latest snapshot of bonecp to fix this)

Cheers,

F

[Niklas Nylund]

We are seeing this with 2.2 also, did anyone find a good solution?

Niklas

[Think]

same problem here. Still didn't find the solution and this is a hudge bug. Sometimes my website just don't answer request because of that.
Don't know if it is an Ebean bug or a play! bug but we definitly need a fix. I am using play 2.0.3

[Richard Walker]

I'm also using Play! 2.2 (with Postgres). Add me to the list of those that are seeking an answer to this issue. My experience is more pronounced than most in that I'm not able to get two successive sequences of read/writes to work without getting the famous error message >>>[warn] c.j.b.ConnectionPartition - BoneCP detected an unclosed connection and will now attempt to close it for you. You should be closing this connection in your application - enable connectionWatch for additional debugging assistance or set disableConnectionTracking to true to disable this feature entirely.<<<

[virtualeyes]

@Richard Walker If you're not already on 2.2.1, you should upgrade in order to get BoneCP 0.8-release (or depend on it manually if you can't upgrade Play).

Then set partitionCount = number of available CPU core(s)

Finally, set maxConnectionAge=0

Play's maxConnectionAge default of 1 hour means, kill this connection no matter what in 1 hour, regardless of whether or not the connection is active; presumably this could cause a race condition occur.

[Mary Senkiv]

The same issue on play-2.1.3. I've updated BoneCP. Didn't help. It'huge problem!!!

[Niklas Nylund]

I am currently waiting for 2.2.2 as there is a possible fix for these issues in the next release.

Niklas Nylund

On 13 feb 2014, at 19:17, Mary Senkiv <marich...@gmail.com> wrote:

The same issue on play-2.1.3. I've updated BoneCP. Didn't help. It'huge problem!!!

--
You received this message because you are subscribed to a topic in the Google Groups "play-framework" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/play-framework/n5FW16QHu_c/unsubscribe.
To unsubscribe from this group and all its topics, send an email to play-framewor...@googlegroups.com.