Issue: Losing MySQL connections even though using Pool etc.
Author: cpury
State: closed
Created: 2014-11-18 18:11:42

Hi,
so I'm writing a Python Thrift service and use Peewee as my ORM. Our DB is on a MySQL server. I've had many different problems with the "MySQL server going away" and googling it I found these two tips: a) Use the playhouse connection pool
b) After connecting, call database.get_conn().ping(True) (though I feel like I need to add that inside the pool code?)

So right now I'm using a pool both for write-connections as well as the read-slaves. I experimented with a bunch of different values for the pool parameters, but at the moment I am at:

```
max_connections=100, connect_timeout=20, stale_timeout=60, threadlocals=True
```

Problem is, I still regularly get into the position where the connection goes away during an operation, or in between operations... Which would be fine, but in that case Peewee is failing completely to reconnect, even though that is exactly what the pool should do? E.g. this morning I got a "OperationalError: (2006, "MySQL server has gone away (error(32, 'Broken pipe'))")" when trying to run something on my service, and, alarmingly, it did not work even when sending new requests, i.e. Peewee did not even try to reconnect. The MySQL server was all up and running though and simply restarting the service fixed it.

From time to time I will also get a "OperationalError: (2013, "Lost connection to MySQL server during query (timeout('timed out',))")", which is probably some server issue, but I'd really really like Peewee to reconnect automatically so that I don't have to manually "try except retry" every single Peewee command I run.

Do you have any help for me how I can make definitely sure that my queries don't fail, and if they do, how to reconnect? Also, how could that "Server gone away" happen, even after resending the query? Below I attached two example stack traces for exceptions.

Thanks,
Max

```
  File "/var/www/model.py", line 216, in find_all_general
    total = query.select(Resource).count()
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 2366, in count
    return self.wrapped_count(clear_limit=clear_limit)
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 2379, in wrapped_count
    return rq.scalar() or 0
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 2135, in scalar
    row = self._execute().fetchone()
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 2126, in _execute
    return self.database.execute_sql(sql, params, self.require_commit)
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 2728, in execute_sql
    self.commit()
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 2597, in __exit__
    reraise(new_type, new_type(*exc_value.args), traceback)
  File "/usr/local/lib/python2.7/dist-packages/peewee.py", line 2720, in execute_sql
    cursor.execute(sql, params or ())
  File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 132, in execute
    result = self._query(query)
  File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 271, in _query
    conn.query(q)
  File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 725, in query
    self._execute_command(COM_QUERY, sql)
  File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 888, in _execute_command
    self._write_bytes(prelude + sql[:chunk_size-1])
  File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 848, in _write_bytes
    raise OperationalError(2006, "MySQL server has gone away (%r)" % (e,))
OperationalError: (2006, "MySQL server has gone away (error(32, 'Broken pipe'))")


  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/peewee.py", line 3385, in get
    return sq.get()
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/peewee.py", line 2389, in get
    return clone.execute().next()
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/peewee.py", line 2430, in execute
    self._qr = ResultWrapper(model_class, self._execute(), query_meta)
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/peewee.py", line 2126, in _execute
    return self.database.execute_sql(sql, params, self.require_commit)
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/peewee.py", line 2728, in execute_sql
    self.commit()
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/peewee.py", line 2597, in __exit__
    reraise(new_type, new_type(*exc_value.args), traceback)
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/peewee.py", line 2720, in execute_sql
    cursor.execute(sql, params or ())
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/pymysql/cursors.py", line 132, in execute
    result = self._query(query)
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/pymysql/cursors.py", line 271, in _query
    conn.query(q)
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/pymysql/connections.py", line 726, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/pymysql/connections.py", line 861, in _read_query_result
    result.read()
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/pymysql/connections.py", line 1064, in read
    first_packet = self.connection._read_packet()
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/pymysql/connections.py", line 825, in _read_packet
    packet = packet_type(self)
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/pymysql/connections.py", line 242, in __init__
    self._recv_packet(connection)
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/pymysql/connections.py", line 248, in _recv_packet
    packet_header = connection._read_bytes(4)
  File "/Users/max/code/content-service/venv-cs/lib/python2.7/site-packages/pymysql/connections.py", line 838, in _read_bytes
    2013, "Lost connection to MySQL server during query (%r)" % (e,))
OperationalError: (2013, "Lost connection to MySQL server during query (timeout('timed out',))")
```


Thanks for sharing this. I'm sorry that you've still been experiencing errors.

Quick question -- are you calling `my_db.connect()` and `my_db.close()` between requests? I ask because these calls are necessary for opening the conn and for returning it to the pool.

I think some improvements could definitely be made to the mysql pool implementation -- particularly now that there's an API hook for determining if a connection is actually available.


Ha! That might just be it. I wasn't aware I have to manually open/close the connections, but that seems only logical now that I think of it >.<

Related to that, I'm using the Thrift TForkedServer, which forks a new process for each request. Will the pool with threadlocals=True work fine with this?


And also, what will happen if too many requests come in at once and the number of max_connections is reached? I'd like them to wait until a new connection is available, and not to fail.


> Related to that, I'm using the Thrift TForkedServer, which forks a new process for each request. Will the pool with threadlocals=True work fine with this?

Ahh... I am not sure how that will work. The connections will be opened and maintained in the server process, then when `fork` is called they will be used in the request process... But I'm not sure what will actually happen there. If it spawned a thread for each request then `threadlocals` would work, but I'm not sure for an entire process.

> And also, what will happen if too many requests come in at once and the number of max_connections is reached? I'd like them to wait until a new connection is available, and not to fail.

Currently the pool does not block, though this might be worth adding. You could always subclass and override the pool's `_connect()` method, then call it in a busy-loop?


Thanks man! I'll experiment with this and report back on how it goes.


Cool, I'll look into it as well this evening when I'm done with work.


Where are you at with this one? Did connect/close per-request fix the issue?


So I tinkered around a lot and changed a bunch of things, and it does seem to be more stable. Especially the "MySQL server gone away" error hasn't appeared since, and just logically I don't think it will. I haven't seen the "Connection lost during query" one yet, but if it happens again I guess I should also have a look at the MySQL server configuration.

As for the ForkedServer, I found out that the different forks do not share the memory for variables, which means the Pool essentially becomes useless. Thus it would be a feasible solution to combine the ForkedServer with just opening a simple connection per fork. I guess I can load test that at some point, but for now I'm going for ThreadedServer with Connection Pool.

For establishing connections, I added the busy loop as you suggested to make sure queries only fail if the server is really busy.

Thanks!


Hmm so when posting a lot of parallel requests to my server, at some point one query and all subsequent will fail with the OperationalError: (2013, "Lost connection to MySQL server during query (timeout('timed out',))"). Sadly, Peewee seems unable to restart the connection then, and I have to manually restart the whole service in order for it to work again... Do you have an idea how I can have the Pool automatically kill connections that have died like this? At this point I'm not even sure the Thread/Pool combination is doing what I want. I have each request run on a separate thread, and each thread opens/closes connections from the Pool.


I guess I could subclass Database and have execute_sql catch OperationalErrors and automatically reconnect if that happens? Could that cause any other issues? Would I lose my transactions?


> As for the ForkedServer, I found out that the different forks do not share the memory for variables, which means the Pool essentially becomes useless.

Correct -- at this point you are going to be opening a connection-per-process.

> Thus it would be a feasible solution to combine the ForkedServer with just opening a simple connection per fork. I guess I can load test that at some point, but for now I'm going for ThreadedServer with Connection Pool.

That sounds good. Make sure you are instantiating your database with `threadlocals=True` (this is the default but in older versions of peewee this was not the case).

> For establishing connections, I added the busy loop as you suggested to make sure queries only fail if the server is really busy.

Have you tested your implementation? Can you share any code?

> Hmm so when posting a lot of parallel requests to my server, at some point one query and all subsequent will fail with the OperationalError: (2013, "Lost connection to MySQL server during query (timeout('timed out',))").

If you can, I'd like to see as much of your relevant code as you can share. Or perhaps an example that illustrates the problem. I'm having a hard time connecting this behavior with the implementation of the pool.

> I guess I could subclass Database and have execute_sql catch OperationalErrors and automatically reconnect if that happens? Could that cause any other issues? Would I lose my transactions?

I would advise against that.


Sure let me see how much code I can share. However, I did not subclass the Pool as proposed, but rather just wrapped the connect calls. Maybe I'll do that now that it has proven to be useful. This is all very hacky and probably not pythonic, but here goes:

```
def connect_to_db_with_retries(db, tries=50, pause=0.05):
    for t in xrange(tries):
        try:
            db.connect()
            return
        except ValueError:
            # no connection in pool
            if t + 1 == tries:
                raise
            time.sleep(pause)
```

Then, I have a wrapper around each handler method (each of those should be called in a subthread) that goes something like this:

```
def connect(db):
    def connect_decorator(f):
        @wraps(f)
        def wrapper(*args, **kwargs):
            connect_to_db_with_retries(db)

            try:
                result = f(*args, **kwargs)
            except OperationalError:
                db.manual_close()

            db.close()

            return result
        return wrapper
    return connect_decorator
```

Oh and here is how I instantiate the pool:

```
db = PooledMySQLDatabase(charset='utf8', use_unicode=True, max_connections=1000, connect_timeout=10, stale_timeout=60, **db_credentials)
```

Note that it's actually slightly more complicated than this, since I have separate read/write connections. If you think this could be part of the issue, I can add the relevant code. Oh and the Thrift Threaded Server implementation can be found here:
https://github.com/evernote/evernote-sdk-python/blob/master/lib/thrift/server/TServer.py#L92

Thanks again!


For an example that illustrates the problem: I built a little Go-tool that sends random requests in parallel to my Python service. Here is a little table to illustrate the scale (which makes it seem like the MySQL requests are actually handled consecutively):

```
n parallel requests | avg time for request (s) | n errors
1   | 0.1 | 0
2   | 0.2 | 0
4   | 0.4 | 0
8   | 0.8 | 0
16  | 1.6 | 0
32  | 3.2 | 0
64  | -   | 64
```

Note that this wall where all the requests fail and return "Connection lost during query" is reached whenever the average time reaches the connection_timeout I set when initializing the pool (in this case it was 5). This raises two concerns for me:
a) Why is the time scaling exponentially with number of parallel requests? By the way, average here means that ALL of the requests basically need exactly that amount of time, even the very first one which shouldn't face any obstacles
b) Why do all the connections break and need to be manually closed if this happens?


It looks to me like the time is not scaling exponentially but linearly, and that might indicate that your parallel requests are running sequentially. I'm not sure what's going on -- I have very littleexperience with MySQL (I use SQLite/Postgres), so I have no idea what the db server might be doing. My best suggestion is just to add a shitload of logging and try to go from there. If you had some minimal code that reliably reproduced this problem, I'd be happy to dig further.


Yeah you're right, the time per request scales linearly, but that makes the whole process explode. I'll go with your advice and log the shit out of it :) Thanks man!


I've got more info! Hopefully this will help us both. So I ran my server and sent four parallel requests its way. I enabled the Pool's logging, as well as some logging by me: 1. When a request is received. 2. When we are done handling it, along with the time it took 3. Inside pool.py whenever _close or _connect are called. The results are as follows (with some comments)

```
Request received
Connect call:
No connection available in pool.
Request received
Connect call:
No connection available in pool.
Request received
Connect call:
No connection available in pool.
Request received
Connect call:
No connection available in pool.
# Up until here, no connections were available, so four connections should have been created right?
Created new connection 4335533392.
Created new connection 4335533392.
Created new connection 4335533392.
Created new connection 4335533392.
# Wrong! They all have the same key... If that means that only one connection was opened or if they just all get mapped to the same key, I don't know
# And now see how these are handled in a linear fashion, but each thread seems to think it "owns" the connection with this key
Close call:
Returning 4335533392 to pool.
Request finished: Took 2.06 sec
Close call:
Returning 4335533392 to pool.
Request finished: Took 2.14 sec
Close call:
Returning 4335533392 to pool.
Close call:
Request finished: Took 2.15 sec
Returning 4335533392 to pool.
Request finished: Took 2.16 sec
```

This could have many implications and I will wait for your comments. But yeah apparently I'm doing something wrong or the pool is not very smart when too many new connections come at once (and there aren't enough connections in the pool). At least this explains why it seemed like my requests are sequential and not parallel. Note that the base 2 seconds is probably the time it needed to connect to the DB, as I'm behind a VPN at the moment.

Thanks,
Max


That certainly is strange, I think some weird things must be going on but I'm not sure what.

The key used for the connection is `id()` which should be the memory address of the database connection. If you created your `MySQLDatabase` with `threadlocals=True`, then technically a connection should be opened for each thread. I would guess this was the case, but it seems like something else is going on. What does your code look like that opens each connection? What does your database definition look like? I'm also curious what your server looks like. Anything I can implement on my end to try and replicate your setup will be good. Thanks for your help with this, I'll spend some more time looking into the unit-tests.


Weird...

Well, my server is pretty complicated, but the main parts are as described above:
- Basis for my threaded server is TThreadedServer, which is provided by Thrift and should be stable and trustworthy. The logs above should also show that each request is indeed launched in it's own thread, since they handle the requests in parallel.
- I have separate read and write connections (and for each maintain one pool), but open/close only what is needed for the request. In this case, I only need read connections so all the above applies to the read pool.
- Each handler method (aka method ran in it's own thread) is wrapped as I explained above so that it first opens the connections it needs (here only read), then handles the request, and then closes them. In case an OperationalError occurs, I call close_manual() on the connection so it doesn't get recycled.
- The DB is defined roughly as follows:
  
  ```
  write_database = Proxy()
  read_database = Proxy()
  
  class BaseModel(gfk.Model, read_slave.ReadSlaveModel):
      class Meta:
          database = write_database
          read_slaves = (read_database,)
  
      def __str__(self):
          return str(self.__dict__['_data'])
  
  # Model definitions etc...
  
  def initialize_db_proxy(db_credentials):
      """ Init the models with the given databases. """
  
      write_db = PooledMySQLDatabase(charset='utf8', use_unicode=True, max_connections=1000, connect_timeout=10, stale_timeout=60, threadlocals=True, **db_credentials['write'])
  
      # Only initialize read-connection if given in config
      read_db = None
      if "read" in db_credentials:
          read_db = PooledMySQLDatabase(charset='utf8', use_unicode=True, max_connections=1000, connect_timeout=10, stale_timeout=60, threadlocals=True, **db_credentials['read'])
  
      write_database.initialize(write_db)
      read_database.initialize(read_db or write_db)
  ```

Are there any other values I can log to help debug this?


I wrote a little test script which, in my mind, shows that the pool works correctly. The idea is the program will spawn 10 threads. Each thread adds a row to the database which indicates:
- the thread ID (each thread should have a unique id)
- the available connections (should be empty)
- the connections in use (should grow with each thread)
- a piece of data unique to the thread

When all threads are done, the program prints the number of rows in the database and the number of connections in use by the pool.

``` python
import threading

from peewee import *
from playhouse.pool import PooledPostgresqlDatabase


db = PooledPostgresqlDatabase('peewee_test')

class Note(Model):
    data = TextField()

    class Meta:
        database = db

Note.drop_table(True)
Note.create_table()

class NoteThread(threading.Thread):
    def __init__(self, data, *args, **kwargs):
        self.data = data
        super(NoteThread, self).__init__(*args, **kwargs)

    def run(self):
        db.connect()
        values = [
            'Thread ID=%s' % self.ident,
            'Pool connections=%s' % db._connections,
            'Pool in use=%s' % db._in_use,
            'Data=%s' % self.data,
        ]
        Note.create(data='\n'.join(values))

threads = [NoteThread(str(i)) for i in range(10)]
for t in threads:
    t.start()
for t in threads:
    t.join()

print 'Connections\n=============='
print db._connections
print 'In use\n====='
print len(set(db._in_use))
print
print 'Notes in database: %s' % Note.select().count()
```

Output:

```
Connections
==============
[]
In use
=====
10

Notes in database: 10
```


D'oh! Of course something fishy was going on... While experimenting I must have at some point switched back to TForkedServer, so all my "threads" were actually processes. I switched back to threads and now the behavior is at it should be!

Thanks a lot for your example. I notice that you don't close the connections after you're done, but that is probably for educational purposes. Trying to log these two values (db._connections and db._in_use) is what led me ultimately to debug the thread creation.

And overall, thanks for your amazing and quick help! Peewee is awesome and I'll definitely recommend it to my friends!


> I notice that you don't close the connections after you're done, but that is probably for educational purposes

Yes, that was just to show that there are multiple connections in use.

> And overall, thanks for your amazing and quick help

My pleasure glad to help. Thanks for working with me on this issue.


Hi 
I have a question that I prefer to ask here because it's relevant.

why do we need to start/close connections? In the connectionloop case, what does that really mean?  Isn't the pool responsible for taking care of connections (closing idle ones and connecting once a connection is needed)?


When a connection is opened the pool will check to see if it's stale, and if so, will close it and reopen a new one, but there is no "active" monitoring of the connections.


I have same problem：...   (2006, "MySQL server has gone away (error(32, 'Broken pipe'))")
anyone have a solution? tks.


In case you're interested, I've got a mixin for retrying failed queries in 017e4e4952f0b429dd21f0e90465a0f644cf6015 . Docs:

http://docs.peewee-orm.com/en/latest/peewee/database.html#automatic-reconnect


Awesome! Thanks


Hi, 
I have some questions. This is my error:
![error](https://user-images.githubusercontent.com/35761189/43952438-8b369964-9cc8-11e8-90e0-349afbb237d7.jpg)
I used PooledMySQLDatabase . And I used the 'with db.atomic()' to process request, so I think connect will return back to pool. 
I think the reason for this is that MySQL closed automatic the connection, but peewee doesn't know. From the Docs, I couldn't find any about automatic-reconnect. I know RetryOperationalError can deal with, but I find it  had delete from shortcuts file. I don't know why. Is there other method I don't find?
What should I do? Thanks



MySQL will close connections after a certain period of time. When using the connection pool, you'll want to make sure the ["stale_timeout"](http://docs.peewee-orm.com/en/latest/peewee/playhouse.html#PooledDatabase) is set to some value less than mysql server's timeout.

Additionally, if you're using the connection pool, you need to explicitly connect and close connections, just as if you were using the regular/non-pooled connection type. This gives peewee an opportunity to recycle/close the connection as appropriate. It sounds like you may not be doing this, though. Read the docs: http://docs.peewee-orm.com/en/latest/peewee/database.html#connection-management

Just a quick Q&A: does `connection_context()` closes the connection properly using a pooled connection? Or do I need to close it manually as well?

The [docs](http://docs.peewee-orm.com/en/3.6.0/peewee/api.html#Database.connection_context) say:
>Create a context-manager that will hold open a connection for the duration of the wrapped block.

But omits if I need to close the connection.

Example:
```
def run():
    with db.connection_context():
        with db.atomic() as txn:
            # do stuff
```

Ignore my previous comment, looking at the source code of `ConnectionContext`, it's pretty clear that it opens and closes the connection. I will leave both of my comments for documentation purposes.

It would be nice if this is explicitly stated in the docs! :)

```
class ConnectionContext(_callable_context_manager):
    __slots__ = ('db',)
    def __init__(self, db): self.db = db
    def __enter__(self):
        if self.db.is_closed():
            self.db.connect()
    def __exit__(self, exc_type, exc_val, exc_tb): self.db.close()
```