[Twisted-Python] deferToThread and reactor loop
![](https://secure.gravatar.com/avatar/83111e3ce141b383d5169be6edd768d1.jpg?s=120&d=mm&r=g)
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/threadpool... ************** 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/threadpool... 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@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@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@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@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.
![](https://secure.gravatar.com/avatar/607cfd4a5b41fe6c886c978128b9c03e.jpg?s=120&d=mm&r=g)
On 29 Oct, 05:58 pm, tobias.oberstein@tavendo.de wrote:
Hi Tobias, Sorry, I haven't had a chance to read your minimal example in any detail. However, I can direct you to the implementation of deferToThread: http://twistedmatrix.com/trac/browser/trunk/twisted/python/threadpool.py#L11... Notice the `self.q.put(o)`. This matches up with the call to `self.q.get` in the same module: http://twistedmatrix.com/trac/browser/trunk/twisted/python/threadpool.py#L15... Together, these bits of source should demonstrate that there's no waiting for a reactor iteration before the work is enqueued. The work goes into the Queue instance, and instantly any worker thread is free to grab it. Jean-Paul
![](https://secure.gravatar.com/avatar/83111e3ce141b383d5169be6edd768d1.jpg?s=120&d=mm&r=g)
Hi Jean-Paul,
Ok, I see. There might be a mutex or something in the Queue implementation (if it's not a lockless queue implementation) or the GIL might be involved. I have no convinving explanation for the behavior I see (which also seems to be platform agnostic). Another wild guess (besides above) I have: maybe the OS does not immediately schedule other process threads for execution if the current thread (the one pushing to the Queue) is very busy .. Thanks, Tobias
![](https://secure.gravatar.com/avatar/607cfd4a5b41fe6c886c978128b9c03e.jpg?s=120&d=mm&r=g)
On 29 Oct, 05:58 pm, tobias.oberstein@tavendo.de wrote:
Hi Tobias, Sorry, I haven't had a chance to read your minimal example in any detail. However, I can direct you to the implementation of deferToThread: http://twistedmatrix.com/trac/browser/trunk/twisted/python/threadpool.py#L11... Notice the `self.q.put(o)`. This matches up with the call to `self.q.get` in the same module: http://twistedmatrix.com/trac/browser/trunk/twisted/python/threadpool.py#L15... Together, these bits of source should demonstrate that there's no waiting for a reactor iteration before the work is enqueued. The work goes into the Queue instance, and instantly any worker thread is free to grab it. Jean-Paul
![](https://secure.gravatar.com/avatar/83111e3ce141b383d5169be6edd768d1.jpg?s=120&d=mm&r=g)
Hi Jean-Paul,
Ok, I see. There might be a mutex or something in the Queue implementation (if it's not a lockless queue implementation) or the GIL might be involved. I have no convinving explanation for the behavior I see (which also seems to be platform agnostic). Another wild guess (besides above) I have: maybe the OS does not immediately schedule other process threads for execution if the current thread (the one pushing to the Queue) is very busy .. Thanks, Tobias
participants (2)
-
exarkun@twistedmatrix.com
-
Tobias Oberstein