On Tue, Sep 27, 2005 at 10:25:01AM +1000, Andrew Bennetts wrote:
On Mon, Sep 26, 2005 at 05:50:24PM +0200, Andrea Arcangeli wrote: [...]
This should be a python or twisted-thread-pool bug. I'm not sure about the best way to track it down, especially because so far I can reproduce it only on the server, that is a bit slower and that I cannot use for debugging.
Twisted's threadpools are pretty straightforward wrappers around Python's threading module. See twisted.python.threadpool.
I'd expect you could reproduce this with a simple python script that starts two threads, with one putting items on a Queue.Queue, and the other reading them off, as a simple approximation of the threadpool arrangement.
In fact, here's a script that does this:
---- import threading import Queue
q = Queue.Queue()
def producer(): # Count from 0 to 99, over and over. i = 0 while True: q.put(i) i += 1 i %= 100
def consumer(): while True: i = q.get() i * 2
p = threading.Thread(target=producer) c = threading.Thread(target=consumer) p.setDaemon(True) c.setDaemon(True) p.start() c.start()
import time; time.sleep(10) ----
vmstat reports lines like:
1 1 350740 18828 38260 204880 0 0 2696 0 1099 100315 83 17 0 0 3 2 350740 16852 38336 206760 0 0 1956 20 1133 100174 86 14 0 0 1 1 350740 15116 38444 208352 0 0 1684 592 1106 99901 85 15 0 0 1 1 350740 12760 38520 210640 0 0 2364 0 1119 100183 87 13 0 0 1 1 350740 11024 38612 212336 0 0 1792 0 1123 100255 85 15 0 0 1 1 350740 9048 38696 214216 0 0 1964 0 1129 100057 85 15 0 0
(it also appears that the producer adds to the queue faster than the consumer gets from it. Doesn't really matter, aside from the memory cost.)
I don't see it with a simple script that has two threads running in parallel with no inter-thread communication at all, however. I'd say the place to look is Python's implementation of thread synchronisation primitives.
Thanks for the example but the above looks quite normal and expected, this passes a token at a fast rate from one thread to the next. In my workload there are say 5/6 queries, two through pb, the others through psycopg2, so it should schedule a dozen times, not 20k times. If I were to pass 10k separate tokens (similar to above testcase) then 20k schedules would have been normal. I even tried pgasync and it also schedules >20k times. I tracked it down by executing multiple sql queries simultaneously. So now I wonder if it's postgres scheduling so fast and not twisted... Unfortunately I have no kernel knob installed to know who is scheduling so fast and strace alters the runtime as well. I'll try to serialize the sql queries, so that no more than one query runs at once, and I guess that'll fix it just fine. (working on making this change right now) It still looks to me that something could be optimized because on such a basic workload that many schedules are not needed (the futex syscalls as well makes no sense, especially with pgasync) but perhaps that's not on the twisted side that generates the overscheduling.