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@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. _______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
