Change in vdsm[master]: protocoldetector: Fix busy poll loop
nsoffer at redhat.com
nsoffer at redhat.com
Sat Apr 18 13:34:50 UTC 2015
Nir Soffer has uploaded a new change for review.
Change subject: protocoldetector: Fix busy poll loop
......................................................................
protocoldetector: Fix busy poll loop
Watching top during protocoldetector tests show very high (100%) cpu
usage during the slow client test. Profiling test_detect_slow_client
test show that the reactor is running a busy poll loop:
Sat Apr 18 15:43:05 2015 test-use-ssl.prof
191917 function calls (191928 primitive calls) in 0.367 seconds
Ordered by: internal time
List reduced from 197 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function)
6598 0.091 0.000 0.325 0.000 asyncore.py:170(poll2)
32987 0.074 0.000 0.143 0.000 betterAsyncore.py:139(Dispatcher._delegate_call)
6598 0.036 0.000 0.160 0.000 betterAsyncore.py:209(Reactor._get_timeout)
6598 0.024 0.000 0.029 0.000 asyncore.py:416(AsyncoreEvent.__getattr__)
13194 0.022 0.000 0.064 0.000 betterAsyncore.py:69(Dispatcher.next_check_interval)
6598 0.015 0.000 0.343 0.000 asyncore.py:205(loop)
6597 0.012 0.000 0.068 0.000 asyncore.py:105(readwrite)
13194 0.012 0.000 0.057 0.000 betterAsyncore.py:51(Dispatcher.readable)
13194 0.012 0.000 0.069 0.000 betterAsyncore.py:54(Dispatcher.writable)
6595 0.011 0.000 0.029 0.000 protocoldetector.py:87(_ProtocolDetector.next_check_interval)
Sat Apr 18 15:46:09 2015 test-no-ssl.prof
184319 function calls (184329 primitive calls) in 0.359 seconds
Ordered by: internal time
List reduced from 148 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function)
6340 0.090 0.000 0.320 0.000 asyncore.py:170(poll2)
31696 0.073 0.000 0.139 0.000 betterAsyncore.py:139(Dispatcher._delegate_call)
6340 0.035 0.000 0.155 0.000 betterAsyncore.py:209(Reactor._get_timeout)
6340 0.022 0.000 0.026 0.000 asyncore.py:416(AsyncoreEvent.__getattr__)
12678 0.022 0.000 0.062 0.000 betterAsyncore.py:69(Dispatcher.next_check_interval)
6340 0.015 0.000 0.338 0.000 asyncore.py:205(loop)
12678 0.012 0.000 0.057 0.000 betterAsyncore.py:51(Dispatcher.readable)
6339 0.012 0.000 0.064 0.000 asyncore.py:105(readwrite)
12678 0.012 0.000 0.068 0.000 betterAsyncore.py:54(Dispatcher.writable)
6338 0.011 0.000 0.028 0.000 protocoldetector.py:87(_ProtocolDetector.next_check_interval)
The root cause is not implementing writable() method, inheriting the
writable() method from asyncore.dispatcher, returning True. The reactor
poll the sockets for POLLOUT, and since a socket is always writable if
you never write to it, the reactor is waking up immediately. This
creates a busy loop, invoking poll 6340 times for handling one
connection, sending one line.
Now we implement writable(), so the reactor wakes up only when data can
be read from a socket, or when a dispatcher has expired. Profiling same
test after this show expected behavior:
Sat Apr 18 15:53:40 2015 test-use-ssl-after.prof
686 function calls (697 primitive calls) in 0.005 seconds
Ordered by: internal time
List reduced from 199 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function)
4 0.001 0.000 0.001 0.000 asyncore.py:416(AsyncoreEvent.__getattr__)
2 0.000 0.000 0.000 0.000 pthread.py:129(Cond.wait)
9 0.000 0.000 0.000 0.000 __init__.py:242(LogRecord.__init__)
4 0.000 0.000 0.000 0.000 socket.py:185(_socketobject.__init__)
4 0.000 0.000 0.004 0.001 asyncore.py:170(poll2)
24 0.000 0.000 0.000 0.000 socket.py:223(meth)
16 0.000 0.000 0.004 0.000 betterAsyncore.py:139(Dispatcher._delegate_call)
1 0.000 0.000 0.004 0.004 protocoldetectorTests.py:184(AcceptorTests.check_slow_client)
15 0.000 0.000 0.000 0.000 pthread.py:95(RLock.lock)
1 0.000 0.000 0.000 0.000 ssl.py:294(SSLSocket.close)
Sat Apr 18 16:23:43 2015 test-no-ssl-after.prof
541 function calls (551 primitive calls) in 0.006 seconds
Ordered by: internal time
List reduced from 145 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function)
2 0.002 0.001 0.002 0.001 threading.py:561(_Event.__init__)
8 0.000 0.000 0.001 0.000 __init__.py:242(LogRecord.__init__)
2 0.000 0.000 0.000 0.000 pthread.py:129(Cond.wait)
1 0.000 0.000 0.001 0.001 protocoldetectorTests.py:184(AcceptorTests.check_slow_client)
20/21 0.000 0.000 0.001 0.000 socket.py:223(meth)
8 0.000 0.000 0.001 0.000 __init__.py:736(MyMemoryHandler.handle)
3 0.000 0.000 0.000 0.000 socket.py:185(_socketobject.__init__)
13 0.000 0.000 0.000 0.000 pthread.py:95(RLock.lock)
8 0.000 0.000 0.001 0.000 __init__.py:1302(Logger.callHandlers)
10 0.000 0.000 0.004 0.000 betterAsyncore.py:139(Dispatcher._delegate_call)
Change-Id: Id18d87d10db63f216699bd60ee82fd3ff08e7624
Signed-off-by: Nir Soffer <nsoffer at redhat.com>
---
M lib/vdsm/sslutils.py
M vdsm/protocoldetector.py
2 files changed, 9 insertions(+), 0 deletions(-)
git pull ssh://gerrit.ovirt.org:29418/vdsm refs/changes/96/39996/1
diff --git a/lib/vdsm/sslutils.py b/lib/vdsm/sslutils.py
index 2fe7200..70e4f2a 100644
--- a/lib/vdsm/sslutils.py
+++ b/lib/vdsm/sslutils.py
@@ -315,6 +315,9 @@
return True
+ def writable(self, dispatcher):
+ return False
+
def has_expired(self):
return monotonic_time() > self._give_up_at
diff --git a/vdsm/protocoldetector.py b/vdsm/protocoldetector.py
index cb90397..a3fd402 100644
--- a/vdsm/protocoldetector.py
+++ b/vdsm/protocoldetector.py
@@ -60,6 +60,9 @@
def readable(self, dispatcher):
return True
+ def writable(self, dispatcher):
+ return False
+
def handle_accept(self, dispatcher):
try:
client, _ = dispatcher.socket.accept()
@@ -84,6 +87,9 @@
def readable(self, dispatcher):
return True
+ def writable(self, dispatcher):
+ return False
+
def next_check_interval(self):
return max(self._give_up_at - monotonic_time(), 0)
--
To view, visit https://gerrit.ovirt.org/39996
To unsubscribe, visit https://gerrit.ovirt.org/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: Id18d87d10db63f216699bd60ee82fd3ff08e7624
Gerrit-PatchSet: 1
Gerrit-Project: vdsm
Gerrit-Branch: master
Gerrit-Owner: Nir Soffer <nsoffer at redhat.com>
More information about the vdsm-patches
mailing list