Curious about the rationale behind the design of the pool_recycle setting

[André Caron]

Hi there!

It's my first time on this list.  Don't be shy to tell me if this isn't the right channel to discuss this :-)

When looking at MySQL metrics on our production deployment of MySQL, I noticed a hammer effect in the number of new connections to MySQL.  In short, when there is a sudden burst of new connections, this burst repeats itself every 8 minutes for quite some time until randomized access patterns smooth it out.  I could correlate impacts on latency of MySQL queries in our application to these bursts in reconnections.

I tracked this down to our use of the pool_recycle setting, which was set to 8 minutes.  I built a small executable example and posted it on GitHub to showcase the behaviour: https://github.com/AndreLouisCaron/sqlalchemy-pool-recycle

I'm really curious to know why the QueuePool chooses to track time elapsed since the connection was opened rather than the time elapsed since the connection was last used since the latter seems more natural to me.

Was this design of the pool_recycle deliberate?  If so, what was the rationale?

Thanks,

André

[Mike Bayer]

On Thu, Oct 26, 2017 at 5:36 AM, André Caron <andre....@gmail.com> wrote:
> Hi there!
>
> It's my first time on this list. Don't be shy to tell me if this isn't the
> right channel to discuss this :-)
>
> When looking at MySQL metrics on our production deployment of MySQL, I
> noticed a hammer effect in the number of new connections to MySQL. In
> short, when there is a sudden burst of new connections, this burst repeats
> itself every 8 minutes for quite some time until randomized access patterns
> smooth it out. I could correlate impacts on latency of MySQL queries in our
> application to these bursts in reconnections.
>
> I tracked this down to our use of the pool_recycle setting, which was set to
> 8 minutes. I built a small executable example and posted it on GitHub to
> showcase the behaviour:
> https://github.com/AndreLouisCaron/sqlalchemy-pool-recycle

so yes, 8 minutes is lower than what was the original idea for this
setting. Also, depending on what you have set for max_overflow vs.
pool size, usually the "newness" of connections gets flattened out
pretty quickly due to some of them being created as "overflow"
connections, combined with the fact that its random which checked-out
connections become persistently pooled vs. not. These aren't
necessarily excuses but this is probably why what you are observing is
not too common.

>
> I'm really curious to know why the QueuePool chooses to track time elapsed
> since the connection was opened rather than the time elapsed since the
> connection was last used since the latter seems more natural to me.

Well, the pool was written about 11 years ago and decisions like these
filtered out of things I saw in projects like the c3p0 connection pool
as well as from working a lot with Apache, and the concept of
"limiting the life of a resource" is more common there, as even today
c3p0 has this setting maxConnectionAge:
http://www.mchange.com/projects/c3p0/#maxConnectionAge . The
rationale they give is sort of along the lines of what my thinking was
as well, that of the "misbehaving database connection" that leaks
memory either on the client or server and needs to have its lifespan
limited (they mention this here:
http://www.mchange.com/projects/c3p0/#configuring_connection_testing).
That concept was more common back then and was probably part of the
rationale.

After that, c3p0 has an enormous number of flags and switches and is
extremely complicated, and I was looking to build an very simple pool,
especially one that didn't have exotic requirements like running a
background thread to test connections and such. The "pool_recycle"
setting presented itself as a simple approach to the problem of
connections timed out by the server or middleware that would work in
all cases with virtually no overhead. While c3p0 also has a
maxIdleTime setting I could have imitated, it is actually not trivial
to track "idle" time on the connection, since you have to instrument
every API call on the connection that emits on the connection such as
cursor.execute(), and additionally you can't even know in the case of
DBAPI if a call like connection.rollback() actually emits SQL; the
earliest version of the pool did not even emit rollback() upon
checkin.

Even as I think about it now, while it seems like an unusual case that
"connection is checked out" would not be equivalent to "non-idle",
maybe it's not. Maybe a web application is set up to build a Session
on every request that will pull up a connection, but the vast majority
of web requests just read from a cache, or don't write to a particular
database that nonetheless has a connection checked out. These
situations could produce long-idle connections that are nevertheless
being checked out.

It would certainly be very easy to add an "idle" timeout, but it would
need to be accompanied by the above caveat that this is not as much an
"idle" timeout as it is a "not checked out" timeout, which may or may
not track "idleness". However, when combined with pre-ping, this
would work quite well. Pre-ping, something that I would have
considered to be unheard of when I first wrote the pool (since I
anticipated a vastly higher checkin/checkout frequency back then when
transactions were not used by default), is now a built in feature at
http://docs.sqlalchemy.org/en/latest/changelog/migration_12.html#pessimistic-disconnection-detection-added-to-the-connection-pool.

You can make an idle timeout right now with any version of SQLAlchemy
using pool events. See below.

from sqlalchemy import create_engine
from sqlalchemy import event
from sqlalchemy import exc
import time

e = create_engine("mysql://scott:tiger@localhost/test", echo_pool='debug')


idle_time = 30


@event.listens_for(e, "checkout")
def co(dbapi_connection, connection_record, connection_proxy):
now = time.time()
checkout_time = connection_record.info.get('checkout_time')
if checkout_time and now - checkout_time > idle_time:
raise exc.DisconnectionError(
"recycling connection idle past %s seconds" % idle_time)
connection_record.info['checkout_time'] = now


c = e.connect()
time.sleep(1)
c.close()

time.sleep(35)
c = e.connect()
time.sleep(1)
c.close()

time.sleep(5)
c = e.connect()
time.sleep(1)
c.close()



2017-10-26 12:24:46,825 DEBUG sqlalchemy.pool.QueuePool Created new
connection <_mysql.connection open to 'localhost' at 55c60f8d8920>
2017-10-26 12:24:46,831 DEBUG sqlalchemy.pool.QueuePool Connection
<_mysql.connection open to 'localhost' at 55c60f8d8920> checked out
from pool
2017-10-26 12:24:47,834 DEBUG sqlalchemy.pool.QueuePool Connection
<_mysql.connection open to 'localhost' at 55c60f8d8920> being returned
to pool
2017-10-26 12:24:47,834 DEBUG sqlalchemy.pool.QueuePool Connection
<_mysql.connection open to 'localhost' at 55c60f8d8920>
rollback-on-return
2017-10-26 12:25:22,870 DEBUG sqlalchemy.pool.QueuePool Connection
<_mysql.connection open to 'localhost' at 55c60f8d8920> checked out
from pool
2017-10-26 12:25:22,870 INFO sqlalchemy.pool.QueuePool Disconnection
detected on checkout, invalidating individual connection:
DisconnectionError('recycling connection idle past 30 seconds',)
2017-10-26 12:25:22,871 INFO sqlalchemy.pool.QueuePool Invalidate
connection <_mysql.connection open to 'localhost' at 55c60f8d8920>
(reason: DisconnectionError:recycling connection idle past 30 seconds)
2017-10-26 12:25:22,871 DEBUG sqlalchemy.pool.QueuePool Closing
connection <_mysql.connection open to 'localhost' at 55c60f8d8920>
2017-10-26 12:25:22,873 DEBUG sqlalchemy.pool.QueuePool Created new
connection <_mysql.connection open to 'localhost' at 55c60f8d9b40>
2017-10-26 12:25:23,874 DEBUG sqlalchemy.pool.QueuePool Connection
<_mysql.connection open to 'localhost' at 55c60f8d9b40> being returned
to pool
2017-10-26 12:25:23,875 DEBUG sqlalchemy.pool.QueuePool Connection
<_mysql.connection open to 'localhost' at 55c60f8d9b40>
rollback-on-return
2017-10-26 12:25:28,880 DEBUG sqlalchemy.pool.QueuePool Connection
<_mysql.connection open to 'localhost' at 55c60f8d9b40> checked out
from pool
2017-10-26 12:25:29,881 DEBUG sqlalchemy.pool.QueuePool Connection
<_mysql.connection open to 'localhost' at 55c60f8d9b40> being returned
to pool
2017-10-26 12:25:29,881 DEBUG sqlalchemy.pool.QueuePool Connection
<_mysql.connection open to 'localhost' at 55c60f8d9b40>
rollback-on-return

>
> Was this design of the pool_recycle deliberate? If so, what was the
> rationale?
>
> Thanks,
>
> André
>

> --
> SQLAlchemy -
> The Python SQL Toolkit and Object Relational Mapper
>
> http://www.sqlalchemy.org/
>
> To post example code, please provide an MCVE: Minimal, Complete, and
> Verifiable Example. See http://stackoverflow.com/help/mcve for a full
> description.
> ---
> You received this message because you are subscribed to the Google Groups
> "sqlalchemy" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to sqlalchemy+...@googlegroups.com.
> To post to this group, send email to sqlal...@googlegroups.com.
> Visit this group at https://groups.google.com/group/sqlalchemy.
> For more options, visit https://groups.google.com/d/optout.

[Jonathan Vanasco]

On a related note, I suggest implementing the timeout as happening at a random time within a 2-3 minute window (e.g. at 2 minutes there is an increasing 25% chance of a reconnect, at 3 minutes it jumps up to 75%).  This should scatter reconnects during periods of high load.

A property I managed once had an issue where a link wasn't fronted through the CDN as intended, and publicly hit the origin servers [so 1-3 million requests within 30 minutes to a cluster of 4 nodes sharing a mysql master].  There was a perfect storm of timing where many simultaneous timeouts + reconnects ended up ddos'ing the database and crashing mysql; the barrage of reconnects kept mysql from restarting correctly too.  Variants of this scenario are amazingly common in publishing, and a dozen major sites get blackouts from it each year.  Two sites I know of had links to their bare origin in server/cdn error pages too - so causing an error brought more damage.

[André Caron]

Thanksl Mike and Jonathan! I wasn't expecting such good advice and such detailed responses so quickly :-)

> The rationale they give is sort of along the lines of what my thinking was as well, that of the "misbehaving database connection" that leaks memory either on the client or server and needs to have its lifespan limited.

Interesting, I hadn't thought of it in those terms.  I guess this setting makes more sense to me as a form of garbage collection.

> it is actually not trivial to track "idle" time on the connection

Of course, the client can only approximate the idle time.  To be honest, I was expecting to put a value much lower than that of the timeout on the server (the default for MySQL is 8 hours) such that the approximation's quality doesn't really matter.  I assume that the person who set the pool_recycle to 5 minutes was thinking along the same lines.

> You can make an idle timeout right now with any version of SQLAlchemy using pool events.   See below.

Thanks for the detailed example, I'll most definitely try this out!

> I suggest implementing the timeout as happening at a random time 

This also sounds quite interesting, especially for the maximum connection age.

Again, many thanks for sharing.  I'll see how I can put all this information to good use :-)

André 

On Thu, Oct 26, 2017 at 8:14 PM, Jonathan Vanasco <jona...@findmeon.com> wrote:

On a related note, I suggest implementing the timeout as happening at a random time within a 2-3 minute window (e.g. at 2 minutes there is an increasing 25% chance of a reconnect, at 3 minutes it jumps up to 75%).  This should scatter reconnects during periods of high load.

A property I managed once had an issue where a link wasn't fronted through the CDN as intended, and publicly hit the origin servers [so 1-3 million requests within 30 minutes to a cluster of 4 nodes sharing a mysql master].  There was a perfect storm of timing where many simultaneous timeouts + reconnects ended up ddos'ing the database and crashing mysql; the barrage of reconnects kept mysql from restarting correctly too.  Variants of this scenario are amazingly common in publishing, and a dozen major sites get blackouts from it each year.  Two sites I know of had links to their bare origin in server/cdn error pages too - so causing an error brought more damage.

--

SQLAlchemy -
The Python SQL Toolkit and Object Relational Mapper
 
http://www.sqlalchemy.org/
 
To post example code, please provide an MCVE: Minimal, Complete, and Verifiable Example. See http://stackoverflow.com/help/mcve for a full description.
---

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

[André Caron]

FYI, I tried this out and updated my GitHub project to reflect your excellent insight.

Thanks again!

André

[Jonathan Vanasco]

On Friday, October 27, 2017 at 10:26:50 AM UTC-4, André Caron wrote:

FYI, I tried this out and updated my GitHub project to reflect your excellent insight.

Since your connections were large enough to notice an effect in production, if you have spare time I suggest doing some tests to prevent situations where mysql restarts and all your appservers hit it with new connections (using an exponential backoff for failed reconnects attempts, etc). It's the other way the problem you encountered gets triggered.

[André Caron]

Thanks Jonathan!

We've been meaning to get into more serious failure/negative testing for a while now.  I'll take note of your advice, as it will be useful when we get there.

André

--