[Twisted-Python] twisted server blocking on MySQL read in main thread when using adbapi.ConnectionPool

[Dan Williams]

...and I don't understand why it is running in the main (reactor)
thread.

I have a twisted.web server that uses adbapi.ConnectionPool to read
and sometimes update a MySQL database with small amounts of data at a
fairly high rate.

It's been stable for quite a while, but is now seeing increasing load
and been hanging a couple of times a day. monit gets triggered when
the web server fails to respond to an HTTP GET health check. SIGTERM
won't terminate it, so I'm using monit to send it SIGABRT.

Examining the core file shows that the main (reactor) thread is
blocking in a read in the mysql client library:

> Program terminated with signal 6, Aborted.
> #0  0x00007f549b341d2d in read () from
> /lib/x86_64-linux-gnu/libpthread.so.0
> (gdb) bt 10
> #0  0x00007f549b341d2d in read () from
> /lib/x86_64-linux-gnu/libpthread.so.0
> #1  0x00007f5497429112 in vio_read_buff () from
> /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
> #2  0x00007f549741b24f in ?? () from
> /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
> #3  0x00007f549741bde8 in my_net_read () from
> /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
> #4  0x00007f54974155ba in cli_safe_read () from
> /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
> #5  0x00007f5497416618 in ?? () from
> /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
> #6  0x00007f5497413f8b in mysql_next_result () from
> /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
> #7  0x00007f549792bccc in ?? () from
> /usr/lib/python2.7/dist-packages/_mysql.so
> #8  0x0000000000497ea4 in PyEval_EvalFrameEx ()
> #9  0x0000000000498602 in PyEval_EvalFrameEx ()
> (More stack frames follow...)
> (gdb) bt -10
> #62 0x0000000000498602 in PyEval_EvalFrameEx ()
> #63 0x0000000000498602 in PyEval_EvalFrameEx ()
> #64 0x0000000000498602 in PyEval_EvalFrameEx ()
> #65 0x0000000000498602 in PyEval_EvalFrameEx ()
> #66 0x000000000049f1c0 in PyEval_EvalCodeEx ()
> #67 0x00000000004a9081 in PyRun_FileExFlags ()
> #68 0x00000000004a9311 in PyRun_SimpleFileExFlags ()
> #69 0x00000000004aa8bd in Py_Main ()
> #70 0x00007f549a05976d in __libc_start_main () from
> /lib/x86_64-linux-gnu/libc.so.6
> #71 0x000000000041b9b1 in _start ()
> (gdb)

All of the 10 thread pool threads are sitting waiting on locks:

> (gdb) thread 11
> [Switching to thread 11 (Thread 0x7f54963dd700 (LWP 2691))]
> #0  0x00007f549b340fd0 in sem_wait () from
> /lib/x86_64-linux-gnu/libpthread.so.0
> (gdb) bt 10
> #0  0x00007f549b340fd0 in sem_wait () from
> /lib/x86_64-linux-gnu/libpthread.so.0
> #1  0x0000000000547525 in lock_PyThread_acquire_lock.49023 ()
> #2  0x0000000000497ea4 in PyEval_EvalFrameEx ()
> #3  0x000000000049f1c0 in PyEval_EvalCodeEx ()
> #4  0x00000000004983b8 in PyEval_EvalFrameEx ()
> #5  0x000000000049f1c0 in PyEval_EvalCodeEx ()
> #6  0x00000000004983b8 in PyEval_EvalFrameEx ()
> #7  0x000000000049f1c0 in PyEval_EvalCodeEx ()
> #8  0x00000000004a8a92 in function_call ()
> #9  0x00000000004e9f36 in PyObject_Call ()
> (More stack frames follow...)
> (gdb)

What has me very confused is seeing the MySQL read happening in the
main thread; how can that be?

This is running in AWS EC2 on a pretty busy host but there isn't any
discernible correlation between times of high I/O or CPU usage and the
hangs.

Environment is Ubuntu 12.04.1 LTS, Python 2.7.3, Twisted 11.1.0.

Thanks for any help!

Dan