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