[Twisted-Python] epoll reactor problems
We just switched 2 types of production servers to epoll reactor( Twisted 2.5) from poll reactor (Twisted 2.2). The CPU%% utilization of the first type of server that does not do much except occasionally pushing messages to about 5000 clients dropped from about 40% to 8%, which is very good. The second type of server is more complicated. The CPU utilization of that server (as measured by top) went down from 40% to about 15% after switching to epoll. Here is the problem: after about 10min of running that server with CPU%% staying at about 15%, the CPU suddenly jumps to 99.9% for that process and just stays there. We reproduced this several times. The server remains responsive, even when top shows 99.9% CPU. (Which is very different from 99.9% CPU from real load when we used poll- we are intimately familiar with the performance in that regime unfortunately.) The kernel is 2.6.11.4-21.12-smp Can anybody help with this 99.9% CPU epoll problem?
Quoting Alec Matusis <matusis@matusis.com>:
We just switched 2 types of production servers to epoll reactor( Twisted 2.5) from poll reactor (Twisted 2.2).
The CPU%% utilization of the first type of server that does not do much except occasionally pushing messages to about 5000 clients dropped from about 40% to 8%, which is very good.
That's great.
The second type of server is more complicated. The CPU utilization of that server (as measured by top) went down from 40% to about 15% after switching to epoll.
Here is the problem: after about 10min of running that server with CPU%% staying at about 15%, the CPU suddenly jumps to 99.9% for that process and just stays there. We reproduced this several times. The server remains responsive, even when top shows 99.9% CPU. (Which is very different from 99.9% CPU from real load when we used poll- we are intimately familiar with the performance in that regime unfortunately.)
The kernel is 2.6.11.4-21.12-smp
Can anybody help with this 99.9% CPU epoll problem?
We would probably need more information. What's your version of python? Can you provide a reproductible example? Did you try to do a strace on your running server to see what's going on? As your load was already 99 before using epoll, can it be an application problem? -- Thomas
We would probably need more information. What's your version of python?
We are using Python 2.4.1
Can you provide a reproductible example?
It's hard to provide a reproducible example: we observe this problem only on the live servers. So I do not know how to simplify the code (it has 40000+ lines) such that the problem still remains, since we would have to try it on real users... Did you try to do a strace on your
running server to see what's going on?
I did run strace- it made the server unresponsive, so it had to be restarted. Here is the output from the problematic server at 99% CPU: alecm@web10 ~> strace -p 5315 Process 5315 attached - interrupt to quit --- SIGSTOP (Stopped (signal)) @ 0 (0) --- --- SIGSTOP (Stopped (signal)) @ 0 (0) --- futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=1023, u64=12304606485815493631}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 30) = 5 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=423, u64=12304606485815493031}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 29) = 5 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=1023, u64=12304606485815493631}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 28) = 5 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLIN, {u32=201, u64=12304606485815492809}}, {0, {u32=32, u64=206158430240}}, {EPOLLWRNORM|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=23749657318424575}}, {0, {u32=5315, u64=5315}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=0}}, {0, {u32=4294945068, u64=140737488333100}}}, 1434, 27) = 6 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 recvfrom(201, "getmore:20\r\n\0", 65536, 0, NULL, NULL) = 13 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0xb9d030, FUTEX_WAKE, 1) = 0 futex(0x8a3350, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=1023, u64=12304606485815493631}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 26) = 5 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=423, u64=12304606485815493031}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 25) = 5 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=1023, u64=12304606485815493631}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 24) = 5 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=423, u64=12304606485815493031}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 23) = 5 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=1023, u64=12304606485815493631}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 22) = 5 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=423, u64=12304606485815493031}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 22) = 5 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=1023, u64=12304606485815493631}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 21) = 5 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=423, u64=12304606485815493031}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 20) = 5 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 futex(0x7ce7f0, FUTEX_WAKE, 1) = 0 Interestingly, strace on another type of server, that runs only at 9% CPU does not crash it. Here is that strace for comparison: alecm@web10 ~> strace -p 4131 Process 4131 attached - interrupt to quit futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLIN, {u32=1740, u64=12304606485815494348}}}, 1728, 26) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 recvfrom(1740, "\r\n", 65536, 0, NULL, NULL) = 2 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_ctl(4, EPOLL_CTL_MOD, 1740, {EPOLLIN|EPOLLOUT, {u32=1740, u64=12304606485815494348}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLOUT, {u32=1740, u64=12304606485815494348}}}, 1728, 1) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 sendto(1740, "\r\n\0", 3, 0, NULL, 0) = 3 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_ctl(4, EPOLL_CTL_MOD, 1740, {EPOLLIN, {u32=1740, u64=12304606485815494348}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {}, 1728, 0) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {}, 1728, 0) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {}, 1728, 0) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLIN, {u32=1734, u64=12304606485815494342}}}, 1728, 92) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 recvfrom(1734, "\r\n", 65536, 0, NULL, NULL) = 2 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_ctl(4, EPOLL_CTL_MOD, 1734, {EPOLLIN|EPOLLOUT, {u32=1734, u64=12304606485815494342}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLOUT, {u32=1734, u64=12304606485815494342}}}, 1728, 69) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 sendto(1734, "\r\n\0", 3, 0, NULL, 0) = 3 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_ctl(4, EPOLL_CTL_MOD, 1734, {EPOLLIN, {u32=1734, u64=12304606485815494342}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLIN, {u32=1680, u64=12304606485815494288}}}, 1728, 68) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 recvfrom(1680, "\r\n", 65536, 0, NULL, NULL) = 2 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_ctl(4, EPOLL_CTL_MOD, 1680, {EPOLLIN|EPOLLOUT, {u32=1680, u64=12304606485815494288}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLOUT, {u32=1680, u64=12304606485815494288}}}, 1728, 30) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 sendto(1680, "\r\n\0", 3, 0, NULL, 0) = 3 epoll_ctl(4, EPOLL_CTL_MOD, 1680, {EPOLLIN, {u32=1680, u64=12304606485815494288}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLIN, {u32=1748, u64=12304606485815494356}}}, 1728, 29) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 recvfrom(1748, "\r\n", 65536, 0, NULL, NULL) = 2 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_ctl(4, EPOLL_CTL_MOD, 1748, {EPOLLIN|EPOLLOUT, {u32=1748, u64=12304606485815494356}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLOUT, {u32=1748, u64=12304606485815494356}}}, 1728, 25) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 sendto(1748, "\r\n\0", 3, 0, NULL, 0) = 3 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_ctl(4, EPOLL_CTL_MOD, 1748, {EPOLLIN, {u32=1748, u64=12304606485815494356}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLIN, {u32=1573, u64=12304606485815494181}}}, 1728, 24) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 recvfrom(1573, "\r\n", 65536, 0, NULL, NULL) = 2 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_ctl(4, EPOLL_CTL_MOD, 1573, {EPOLLIN|EPOLLOUT, {u32=1573, u64=12304606485815494181}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLOUT, {u32=1573, u64=12304606485815494181}}}, 1728, 8) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 sendto(1573, "\r\n\0", 3, 0, NULL, 0) = 3 epoll_ctl(4, EPOLL_CTL_MOD, 1573, {EPOLLIN, {u32=1573, u64=12304606485815494181}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLIN, {u32=1681, u64=12304606485815494289}}}, 1728, 7) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 recvfrom(1681, "\r\n", 65536, 0, NULL, NULL) = 2 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_ctl(4, EPOLL_CTL_MOD, 1681, {EPOLLIN|EPOLLOUT, {u32=1681, u64=12304606485815494289}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {{EPOLLOUT, {u32=1681, u64=12304606485815494289}}}, 1728, 2) = 1 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 sendto(1681, "\r\n\0", 3, 0, NULL, 0) = 3 epoll_ctl(4, EPOLL_CTL_MOD, 1681, {EPOLLIN, {u32=1681, u64=12304606485815494289}}) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 epoll_wait(4, {}, 1728, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0 futex(0x859a10, FUTEX_WAKE, 1) = 0
As your load was already 99 before using epoll, can it be an application problem?
Our load with poll reaches 99% only during the daytime. We did all this at night, when the load is only 30-40% with poll. Indeed, after we reverted back to poll, the load went back to 35% and will remain there until the morning. It looked to me like a runaway process: as soon as the load went over ~25% on the problematic server, it continued to rise till it reached 99.9% within less than 1 min.
-----Original Message----- From: twisted-python-bounces@twistedmatrix.com [mailto:twisted-python- bounces@twistedmatrix.com] On Behalf Of Thomas Hervé Sent: Wednesday, April 11, 2007 1:25 AM To: twisted-python@twistedmatrix.com Subject: Re: [Twisted-Python] epoll reactor problems
Quoting Alec Matusis <matusis@matusis.com>:
We just switched 2 types of production servers to epoll reactor( Twisted 2.5) from poll reactor (Twisted 2.2).
The CPU%% utilization of the first type of server that does not do much except occasionally pushing messages to about 5000 clients dropped from about 40% to 8%, which is very good.
That's great.
The second type of server is more complicated. The CPU utilization of that server (as measured by top) went down from 40% to about 15% after switching to epoll.
Here is the problem: after about 10min of running that server with CPU%% staying at about 15%, the CPU suddenly jumps to 99.9% for that process and just stays there. We reproduced this several times. The server remains responsive, even when top shows 99.9% CPU. (Which is very different from 99.9% CPU from real load when we used poll- we are intimately familiar with the performance in that regime unfortunately.)
The kernel is 2.6.11.4-21.12-smp
Can anybody help with this 99.9% CPU epoll problem?
We would probably need more information. What's your version of python? Can you provide a reproductible example? Did you try to do a strace on your running server to see what's going on?
As your load was already 99 before using epoll, can it be an application problem?
-- Thomas
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
Quoting Alec Matusis <matusis@matusis.com>:
We would probably need more information. What's your version of python?
We are using Python 2.4.1
That's old (debian stable ? :)). I don't say that'll solve your problem, but you could try with 2.4.4 (warning, not 2.4.3).
Can you provide a reproductible example?
It's hard to provide a reproducible example: we observe this problem only on the live servers. So I do not know how to simplify the code (it has 40000+ lines) such that the problem still remains, since we would have to try it on real users...
OK...
Did you try to do a strace on your
running server to see what's going on?
I did run strace- it made the server unresponsive, so it had to be restarted. Here is the output from the problematic server at 99% CPU:
epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=1023, u64=12304606485815493631}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 30) = 5
This part is highly suspect. The flags on the fd should not reach these values. What's the global state of the process? Memory, number of opened fd ? -- Thomas
That's old (debian stable ? :)). I don't say that'll solve your problem, but you could try with 2.4.4 (warning, not 2.4.3).
It's SuSE stable ;-) Our stuff on that machine is pretty convoluted now, so we will probably have a chance to test with 2.4.4 only in a week, when we add a brand new server with 2.4.4.
{EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRB AND|E
POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 30) = 5
This part is highly suspect. The flags on the fd should not reach these values.
I noticed a difference between this from the 99.9% CPU server: epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=423, u64=12304606485815493031}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1432, 68) = 5 and this from a normal server running at 5% CPU: epoll_wait(4, {{EPOLLIN, {u32=1769, u64=12304606485815494377}}, {0, {u32=4294944684, u64=140737488332716}}}, 1728, 17) = 2 What does this mean?
What's the global state of the process? Memory, number of opened fd ?
We immediately reverted to poll, so I do not have it in front of me. The RSS size was 45MB, and the number of open fd I do not know: it should have been about 1500, but I did not check. I can do another test run with epoll in about 20hrs, since I do not want to upset users too much. If you have some specific data I should get from the test run, please let me know now. Thanks Alec
-----Original Message----- From: twisted-python-bounces@twistedmatrix.com [mailto:twisted-python- bounces@twistedmatrix.com] On Behalf Of Thomas Hervé Sent: Wednesday, April 11, 2007 2:43 AM To: 'Twisted general discussion' Subject: RE: [Twisted-Python] epoll reactor problems
Quoting Alec Matusis <matusis@matusis.com>:
We would probably need more information. What's your version of python?
We are using Python 2.4.1
That's old (debian stable ? :)). I don't say that'll solve your problem, but you could try with 2.4.4 (warning, not 2.4.3).
Can you provide a reproductible example?
It's hard to provide a reproducible example: we observe this problem only on the live servers. So I do not know how to simplify the code (it has 40000+ lines) such that the problem still remains, since we would have to try it on real users...
OK...
Did you try to do a strace on your
running server to see what's going on?
I did run strace- it made the server unresponsive, so it had to be restarted. Here is the output from the problematic server at 99% CPU:
epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=1023, u64=12304606485815493631}},
{EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRB AND|E
POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLWRNORM|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1434, 30) = 5
This part is highly suspect. The flags on the fd should not reach these values.
What's the global state of the process? Memory, number of opened fd ?
-- Thomas
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
Quoting Alec Matusis <matusis@matusis.com>:
That's old (debian stable ? :)). I don't say that'll solve your problem, but you could try with 2.4.4 (warning, not 2.4.3).
It's SuSE stable ;-) Our stuff on that machine is pretty convoluted now, so we will probably have a chance to test with 2.4.4 only in a week, when we add a brand new server with 2.4.4.
OK. That is just another thing to try, I don't see obvious reasons why it could work better on 2.4.4, but...
I noticed a difference between this from the 99.9% CPU server:
epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=423, u64=12304606485815493031}}, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRBAND|E POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1432, 68) = 5
and this from a normal server running at 5% CPU:
epoll_wait(4, {{EPOLLIN, {u32=1769, u64=12304606485815494377}}, {0, {u32=4294944684, u64=140737488332716}}}, 1728, 17) = 2
What does this mean?
The flags set on your sockets are generally EPOLLIN or EPOLLOUT: data to read or available for write. I don't know much about the other flags. EPOLLERR is set if the fd has been closed for example. EPOLLET is *highly* suspect, because it should only be there if set in the user code. The documentation of other flags is really terse...
What's the global state of the process? Memory, number of opened fd ?
We immediately reverted to poll, so I do not have it in front of me. The RSS size was 45MB, and the number of open fd I do not know: it should have been about 1500, but I did not check.
Hum... it may come from running out of file descriptors, so you'd better check your settings for this.
I can do another test run with epoll in about 20hrs, since I do not want to upset users too much.
Of course :).
If you have some specific data I should get from the test run, please let me know now.
Every information would be useful. The most useful information would be to know when it begins to act strangely, and if there is something that happend at this moment. Otherwise, number of fds, memory, netstat output, strace output... -- Thomas
I am now suspecting there is something strange with Twisted 2.5: Both servers now show 99.9% CPU using top: PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 6929 alecm 16 0 148m 82m 3588 R 99.9 2.1 414:29.24 twistd 4083 alecm 17 0 135m 70m 3640 R 99.9 1.8 421:00.05 twistd The first one 6929 is using poll now, 4083 is using epoll. For this time of the day with Twisted 2.2 and poll the usual CPU would be 15% for 4083 and 80% for 6229. These numbers were pretty stable every day over at leats a month. Both servers seem to be responsive however. There were no code changes. ps shows different %CPU at the same time: #ps -C twistd -o pcpu,cmd,pid,size %CPU CMD PID SZ 61.0 /usr/bin/python /usr/local/ 4083 82240 66.5 /usr/bin/python /usr/local/ 6929 97300 I wonder if we should revert to Twisted 2.2 ASAP
-----Original Message----- From: twisted-python-bounces@twistedmatrix.com [mailto:twisted-python- bounces@twistedmatrix.com] On Behalf Of Thomas Hervé Sent: Wednesday, April 11, 2007 4:47 AM To: twisted-python@twistedmatrix.com Subject: RE: [Twisted-Python] epoll reactor problems
Quoting Alec Matusis <matusis@matusis.com>:
That's old (debian stable ? :)). I don't say that'll solve your problem, but you could try with 2.4.4 (warning, not 2.4.3).
It's SuSE stable ;-) Our stuff on that machine is pretty convoluted now, so we will probably have a chance to test with 2.4.4 only in a week, when we add a brand new server with 2.4.4.
OK. That is just another thing to try, I don't see obvious reasons why it could work better on 2.4.4, but...
I noticed a difference between this from the 99.9% CPU server:
epoll_wait(4, {{EPOLLERR|EPOLLHUP, {u32=423, u64=12304606485815493031}},
{EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRNORM|EPOLLWRB AND|E
POLLMSG|EPOLLERR|EPOLLHUP|0x7820, {u32=5529648, u64=5529648}}, {EPOLLIN|EPOLLPRI|EPOLLRDNORM|EPOLLRDBAND|EPOLLMSG|0x1000, {u32=0, u64=22827751178240}}, {0, {u32=0, u64=0}}, {EPOLLOUT|EPOLLERR|EPOLLONESHOT|EPOLLET|0x3fffa820, {u32=32767, u64=18097643565645823}}}, 1432, 68) = 5
and this from a normal server running at 5% CPU:
epoll_wait(4, {{EPOLLIN, {u32=1769, u64=12304606485815494377}}, {0, {u32=4294944684, u64=140737488332716}}}, 1728, 17) = 2
What does this mean?
The flags set on your sockets are generally EPOLLIN or EPOLLOUT: data to read or available for write. I don't know much about the other flags. EPOLLERR is set if the fd has been closed for example. EPOLLET is *highly* suspect, because it should only be there if set in the user code. The documentation of other flags is really terse...
What's the global state of the process? Memory, number of opened fd ?
We immediately reverted to poll, so I do not have it in front of me. The RSS size was 45MB, and the number of open fd I do not know: it should have been about 1500, but I did not check.
Hum... it may come from running out of file descriptors, so you'd better check your settings for this.
I can do another test run with epoll in about 20hrs, since I do not want to upset users too much.
Of course :).
If you have some specific data I should get from the test run, please let me know now.
Every information would be useful. The most useful information would be to know when it begins to act strangely, and if there is something that happend at this moment. Otherwise, number of fds, memory, netstat output, strace output...
-- Thomas
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
On 06:38 pm, matusis@matusis.com wrote:
I wonder if we should revert to Twisted 2.2 ASAP
I can't speak to your deployment requirements, but it sounds like this inquiry could lead to some extremely valuable information to fix this issue in the next release of Twisted. Would it be possible to replicate this issue with your application in some kind of load-testing environment so that we can analyze it "in the lab"? Although I'd really like to see this through to a satisfying conclusion, I don't want your application to have to pay the cost of fixing Twisted.
We have tested the upgrade to 2.5 on our dev and stage, and we have not run into this problem. So the only way I know how to demonstrate it is to look on live. We are in San Francisco. I wonder if anybody from Twisted is in the Bay Area, then maybe we can get together, ssh into the live servers and examine it. Otherwise, I will have to look into creating a simpler load testing environment with fake clients: this would take me a bit of time… From: twisted-python-bounces@twistedmatrix.com [mailto:twisted-python-bounces@twistedmatrix.com] On Behalf Of glyph@divmod.com Sent: Wednesday, April 11, 2007 12:28 PM To: Twisted general discussion Subject: RE: [Twisted-Python] epoll reactor problems On 06:38 pm, matusis@matusis.com wrote:
I wonder if we should revert to Twisted 2.2 ASAP
I can't speak to your deployment requirements, but it sounds like this inquiry could lead to some extremely valuable information to fix this issue in the next release of Twisted. Would it be possible to replicate this issue with your application in some kind of load-testing environment so that we can analyze it "in the lab"? Although I'd really like to see this through to a satisfying conclusion, I don't want your application to have to pay the cost of fixing Twisted.
Would it be possible to replicate this issue with your application in some kind of load-testing environment so that we can analyze it "in the lab"?
So far, we could not replicate this in the lab- with thousands of fake multithreaded clients the behavior is normal. Thus far, we have run this for 2 days with twisted 2.5 with poll and epoll, and we are now seeing big memory leaks that did not occur on 2.2, especially on epoll, in addition to 99.9% CPU. Back on 2.2 one of our servers was slowly leaking memory, going from 45MB to about 500MB in about 10 days. On epoll in 2.5 it went from 45MB to 1.9g in a couple of hours, almost taking the machine down. The other server did not have memory leak on 2.2, staying at 70MB for weeks at a time. In one day it went from 70MB to 80MB on epoll in 2.5. Both show 99% CPU, so I suspect the memory leaks may be caused by skipping garbage collection because the process is too busy. Interestingly, the actual performance on epoll is not bad, the servers remain responsive even where the poll-based reactor in 2.2 was having difficulties. We must revert to 2.2 tonight. I emailed you and Jean-Paul. If you like, we can arrange ssh to our live servers, then you could look at it on Twisted 2.2 first, then we will switch again to 2.5 and then you can examine it when it’s unstable. From: twisted-python-bounces@twistedmatrix.com [mailto:twisted-python-bounces@twistedmatrix.com] On Behalf Of glyph@divmod.com Sent: Wednesday, April 11, 2007 12:28 PM To: Twisted general discussion Subject: RE: [Twisted-Python] epoll reactor problems On 06:38 pm, matusis@matusis.com wrote:
I wonder if we should revert to Twisted 2.2 ASAP
I can't speak to your deployment requirements, but it sounds like this inquiry could lead to some extremely valuable information to fix this issue in the next release of Twisted. Would it be possible to replicate this issue with your application in some kind of load-testing environment so that we can analyze it "in the lab"? Although I'd really like to see this through to a satisfying conclusion, I don't want your application to have to pay the cost of fixing Twisted.
On Thu, 2007-04-12 at 18:50 -0700, Alec Matusis wrote:
So far, we could not replicate this in the lab- with thousands of fake multithreaded clients the behavior is normal.
Are you using same version of Python and same kernel on test machine and production? If you have memory leaks, there are various utility libraries out there that will show you what the most common objects in your Python program are; you might want to try those.
On Wed, 11 Apr 2007 11:38:02 -0700, Alec Matusis <matusis@matusis.com> wrote:
I am now suspecting there is something strange with Twisted 2.5:
Both servers now show 99.9% CPU using top:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 6929 alecm 16 0 148m 82m 3588 R 99.9 2.1 414:29.24 twistd
4083 alecm 17 0 135m 70m 3640 R 99.9 1.8 421:00.05 twistd
The first one 6929 is using poll now, 4083 is using epoll. For this time of the day with Twisted 2.2 and poll the usual CPU would be 15% for 4083 and 80% for 6229. These numbers were pretty stable every day over at leats a month. Both servers seem to be responsive however. There were no code changes.
ps shows different %CPU at the same time:
#ps -C twistd -o pcpu,cmd,pid,size %CPU CMD PID SZ 61.0 /usr/bin/python /usr/local/ 4083 82240 66.5 /usr/bin/python /usr/local/ 6929 97300
I wonder if we should revert to Twisted 2.2 ASAP
I can't speak to whether or not you want to do that, but I can suggest that if you can provide a more detailed bug report, then any problem in Twisted will probably be fixed for you. Jean-Paul
Alec Matusis wrote:
I am now suspecting there is something strange with Twisted 2.5:
Both servers now show 99.9% CPU using top:
It would be nice to know where in the code it is spending all that time. I would consider installing the debug symbols for python, and getting a C and python backtrace with gdb. (use the .gdbinit file from http://svn.python.org/view/python/trunk/Misc/gdbinit?rev=39492&view=auto to get the "pystack" gdb command, you may need the patch to it from http://jcalderone.livejournal.com/28224.html too). Or maybe even install a simple SIGUSR1 signal handler than dumps a backtrace, and send SIGUSR1 to your process repeatedly while it's at 99.9% CPU. Or a SIGUSR1 handler to install a trace hook (like the twistd --spew option does). The idea either way is to find out by random sampling what code is executing; presumably it's doing the same redundant work over and over, so it shouldn't take many samples to find one code path that is occurring frequently. Then hopefully that extra information will hint at what the problem is. -Andrew.
On 4/11/07, Andrew Bennetts <andrew-twisted@puzzling.org> wrote:
Alec Matusis wrote:
I am now suspecting there is something strange with Twisted 2.5:
Both servers now show 99.9% CPU using top:
It would be nice to know where in the code it is spending all that time.
It would appear from the earlier strace output that the code is busy dealing with bogus epoll_wait results. Sounds like a buggy kernel.
It would be nice to know where in the code it is spending all that time.
I would consider installing the debug symbols for python, and getting a C and python backtrace with gdb.
oprofile is also an excellent tool, and very little disruptive to the behavior of your production server. Regards, Zooko
participants (8)
-
Alec Matusis -
Andrew Bennetts -
glyph＠divmod.com -
Itamar Shtull-Trauring -
Jean-Paul Calderone -
Pavel Pergamenshchik -
Thomas Hervé -
zooko＠zooko.com