[Twisted-Python] deferToThread and reactor loop

[Tobias Oberstein]

Hi,

I've got a question regarding

deferToThread / runWithConnection

I have a network server that accepts RPCs and forwards those to a relational database calling stored procedures.

The call of the stored procedures is happening via "runWithConnection" .. that is on a background thread pool (since that DBs driver is blocking).

Now, when there is a large number of RPCs coming in roughly at once, the latency of each call forwarded to the RDBMs increased into the 10's of ms.

I have created a self-contained test program without DB etc that I think reproduces the "issue":

https://github.com/oberstet/scratchbox/blob/master/python/twisted/threadpoollatency/test.py

**************
Am I correct that "deferToThread" does not immediately forward the call to a background thread, but only the next time the reactor loop runs?
**************

At least that is what I conclude from the test program's option
 
https://github.com/oberstet/scratchbox/blob/master/python/twisted/threadpoollatency/test.py#L58

which produces totally different timing results:

$ python test.py 800 no 20
2012-10-29 18:41:11+0100 [-] Log opened.
2012-10-29 18:41:11+0100 [-] Using Twisted reactor class <class 'twisted.internet.iocpreactor.reactor.IOCPReactor'>
2012-10-29 18:41:11+0100 [-] Thread pool size suggested: 20
2012-10-29 18:41:11+0100 [-] Worker count: 800
2012-10-29 18:41:11+0100 [-] release to reactor between deferToThread: False
2012-10-29 18:41:11+0100 [-] total run-time: 121 ms
2012-10-29 18:41:11+0100 [-] avg. thread switch IN  time: 61177 us
2012-10-29 18:41:11+0100 [-] max. thread switch IN  time: 79436 us
2012-10-29 18:41:11+0100 [-] avg. thread switch OUT time: 16021 us
2012-10-29 18:41:11+0100 [-] max. thread switch OUT time: 23150 us
2012-10-29 18:41:11+0100 [-] Main loop terminated.

$ python test.py 800 yes 20
2012-10-29 18:41:14+0100 [-] Log opened.
2012-10-29 18:41:14+0100 [-] Using Twisted reactor class <class 'twisted.internet.iocpreactor.reactor.IOCPReactor'>
2012-10-29 18:41:14+0100 [-] Thread pool size suggested: 20
2012-10-29 18:41:14+0100 [-] Worker count: 800
2012-10-29 18:41:14+0100 [-] release to reactor between deferToThread: True
2012-10-29 18:41:14+0100 [-] total run-time: 201 ms
2012-10-29 18:41:14+0100 [-] avg. thread switch IN  time: 127 us
2012-10-29 18:41:14+0100 [-] max. thread switch IN  time: 5131 us
2012-10-29 18:41:14+0100 [-] avg. thread switch OUT time: 166 us
2012-10-29 18:41:14+0100 [-] max. thread switch OUT time: 7886 us
2012-10-29 18:41:15+0100 [-] Main loop terminated.

===

Could someone pls enlighten me rgd the "issue"? What's the point, and how to interpret the timings?

Any hints greatly appreciated!

Thanks,
Tobias

Above timings are on Windows. Here other platforms:


Results on FreeBSD
================

[oberstet at www ~/scm/scratchbox/python/twisted/threadpoollatency]$ python test.py 800 no 20
2012-10-29 17:53:37+0000 [-] Log opened.
2012-10-29 17:53:37+0000 [-] Using Twisted reactor class <class 'twisted.internet.kqreactor.KQueueReactor'>
2012-10-29 17:53:37+0000 [-] Thread pool size suggested: 20
2012-10-29 17:53:37+0000 [-] Worker count: 800
2012-10-29 17:53:37+0000 [-] release to reactor between deferToThread: False
2012-10-29 17:53:37+0000 [-] total run-time: 469 ms
2012-10-29 17:53:37+0000 [-] avg. thread switch IN  time: 244311 us
2012-10-29 17:53:37+0000 [-] max. thread switch IN  time: 300846 us
2012-10-29 17:53:37+0000 [-] avg. thread switch OUT time: 2347 us
2012-10-29 17:53:37+0000 [-] max. thread switch OUT time: 25703 us
2012-10-29 17:53:37+0000 [-] Main loop terminated.

[oberstet at www ~/scm/scratchbox/python/twisted/threadpoollatency]$ python test.py 800 yes 20
2012-10-29 17:53:44+0000 [-] Log opened.
2012-10-29 17:53:44+0000 [-] Using Twisted reactor class <class 'twisted.internet.kqreactor.KQueueReactor'>
2012-10-29 17:53:44+0000 [-] Thread pool size suggested: 20
2012-10-29 17:53:44+0000 [-] Worker count: 800
2012-10-29 17:53:45+0000 [-] release to reactor between deferToThread: True
2012-10-29 17:53:45+0000 [-] total run-time: 707 ms
2012-10-29 17:53:45+0000 [-] avg. thread switch IN  time: 410 us
2012-10-29 17:53:45+0000 [-] max. thread switch IN  time: 6184 us
2012-10-29 17:53:45+0000 [-] avg. thread switch OUT time: 310 us
2012-10-29 17:53:45+0000 [-] max. thread switch OUT time: 1331 us
2012-10-29 17:53:45+0000 [-] Main loop terminated.


Results on Linux
=============

[webmq at webmqpgcentos threadpoollatency]$ python test.py 800 no 20
2012-10-29 18:56:13+0100 [-] Log opened.
2012-10-29 18:56:13+0100 [-] Using Twisted reactor class <class 'twisted.internet.epollreactor.EPollReactor'>
2012-10-29 18:56:13+0100 [-] Thread pool size suggested: 20
2012-10-29 18:56:13+0100 [-] Worker count: 800
2012-10-29 18:56:13+0100 [-] release to reactor between deferToThread: False
2012-10-29 18:56:13+0100 [-] total run-time: 178 ms
2012-10-29 18:56:13+0100 [-] avg. thread switch IN  time: 77332 us
2012-10-29 18:56:13+0100 [-] max. thread switch IN  time: 123225 us
2012-10-29 18:56:13+0100 [-] avg. thread switch OUT time: 22048 us
2012-10-29 18:56:13+0100 [-] max. thread switch OUT time: 43779 us
2012-10-29 18:56:13+0100 [-] Main loop terminated.

[webmq at webmqpgcentos threadpoollatency]$ python test.py 800 yes 20
2012-10-29 18:56:14+0100 [-] Log opened.
2012-10-29 18:56:14+0100 [-] Using Twisted reactor class <class 'twisted.internet.epollreactor.EPollReactor'>
2012-10-29 18:56:14+0100 [-] Thread pool size suggested: 20
2012-10-29 18:56:14+0100 [-] Worker count: 800
2012-10-29 18:56:15+0100 [-] release to reactor between deferToThread: True
2012-10-29 18:56:15+0100 [-] total run-time: 370 ms
2012-10-29 18:56:15+0100 [-] avg. thread switch IN  time: 694 us
2012-10-29 18:56:15+0100 [-] max. thread switch IN  time: 3204 us
2012-10-29 18:56:15+0100 [-] avg. thread switch OUT time: 483 us
2012-10-29 18:56:15+0100 [-] max. thread switch OUT time: 7991 us
2012-10-29 18:56:15+0100 [-] Main loop terminated.