Change in vdsm[master]: protocoldetector: Fix busy read loop [2/3]

nsoffer at redhat.com nsoffer at redhat.com
Sat Apr 18 14:49:51 UTC 2015


Nir Soffer has uploaded a new change for review.

Change subject: protocoldetector: Fix busy read loop [2/3]
......................................................................

protocoldetector: Fix busy read loop [2/3]

Profiling test_reject_very_slow_client reveal another issue in
protocoldetector._ProtocolDetector dispatcher. The detector checks if it
has expired in handle_read, but it is done too late, causing the reactor
to busy loop calling handle_read:

Sat Apr 18 16:44:11 2015    test-use-ssl-before.prof

    480783 function calls (480797 primitive calls) in 1.050 seconds

    Ordered by: internal time
    List reduced from 188 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    20880    0.275    0.000    0.825    0.000 asyncore.py:170(poll2)
    83521    0.198    0.000    0.333    0.000 betterAsyncore.py:139(Dispatcher._delegate_call)
    20880    0.126    0.000    0.574    0.000 betterAsyncore.py:209(Reactor._get_timeout)
    41759    0.082    0.000    0.233    0.000 betterAsyncore.py:69(Dispatcher.next_check_interval)
    20880    0.079    0.000    0.095    0.000 asyncore.py:416(AsyncoreEvent.__getattr__)
    20880    0.055    0.000    0.891    0.000 asyncore.py:205(loop)
    41759    0.047    0.000    0.214    0.000 betterAsyncore.py:51(Dispatcher.readable)
    41759    0.044    0.000    0.205    0.000 betterAsyncore.py:54(Dispatcher.writable)
    20878    0.041    0.000    0.105    0.000 protocoldetector.py:93(_ProtocolDetector.next_check_interval)
    20883    0.027    0.000    0.047    0.000 utils.py:1220(monotonic_time)

Sat Apr 18 16:44:53 2015    test-no-ssl-before.prof

    538369 function calls (538376 primitive calls) in 1.049 seconds

    Ordered by: internal time
    List reduced from 145 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    23388    0.282    0.000    0.814    0.000 asyncore.py:170(poll2)
    93551    0.187    0.000    0.318    0.000 betterAsyncore.py:139(Dispatcher._delegate_call)
    23388    0.129    0.000    0.579    0.000 betterAsyncore.py:209(Reactor._get_timeout)
    46774    0.082    0.000    0.234    0.000 betterAsyncore.py:69(Dispatcher.next_check_interval)
    23388    0.079    0.000    0.096    0.000 asyncore.py:416(AsyncoreEvent.__getattr__)
    23388    0.056    0.000    0.881    0.000 asyncore.py:205(loop)
    46774    0.045    0.000    0.205    0.000 betterAsyncore.py:51(Dispatcher.readable)
    46774    0.043    0.000    0.200    0.000 betterAsyncore.py:54(Dispatcher.writable)
    23386    0.040    0.000    0.106    0.000 protocoldetector.py:93(_ProtocolDetector.next_check_interval)
    23388    0.029    0.000    0.049    0.000 utils.py:1220(monotonic_time)

Now we check if a dispatcher has expired in readable(), closing the
dispatcher. This remove the dispatcher from the reactor event loop
immediately. Profiling the same test after this change show expected
behavior:

Sat Apr 18 16:54:48 2015    test-use-ssl-after.prof

    743 function calls (750 primitive calls) in 0.006 seconds

    Ordered by: internal time
    List reduced from 186 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001    0.001    0.001 sslutils.py:291(SSLHandshakeDispatcher._set_up_socket)
      8/9    0.000    0.000    0.006    0.001 asyncore.py:170(poll2)
        9    0.000    0.000    0.001    0.000 __init__.py:242(LogRecord.__init__)
       34    0.000    0.000    0.005    0.000 betterAsyncore.py:139(Dispatcher._delegate_call)
        1    0.000    0.000    0.000    0.000 pthread.py:129(Cond.wait)
        9    0.000    0.000    0.001    0.000 betterAsyncore.py:209(Reactor._get_timeout)
        9    0.000    0.000    0.000    0.000 asyncore.py:416(AsyncoreEvent.__getattr__)
        1    0.000    0.000    0.000    0.000 ssl.py:294(SSLSocket.close)
        1    0.000    0.000    0.004    0.004 protocoldetectorTests.py:191(AcceptorTests.check_very_slow_client)
        4    0.000    0.000    0.000    0.000 socket.py:185(_socketobject.__init__)

Sat Apr 18 16:55:09 2015    test-no-ssl-after.prof

    1002 function calls (1009 primitive calls) in 0.007 seconds

    Ordered by: internal time
    List reduced from 139 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    23/24    0.001    0.000    0.004    0.000 asyncore.py:170(poll2)
       93    0.001    0.000    0.002    0.000 betterAsyncore.py:139(Dispatcher._delegate_call)
       24    0.000    0.000    0.002    0.000 betterAsyncore.py:209(Reactor._get_timeout)
       24    0.000    0.000    0.000    0.000 asyncore.py:416(AsyncoreEvent.__getattr__)
        8    0.000    0.000    0.001    0.000 __init__.py:242(LogRecord.__init__)
       46    0.000    0.000    0.001    0.000 betterAsyncore.py:69(Dispatcher.next_check_interval)
        1    0.000    0.000    0.000    0.000 pthread.py:129(Cond.wait)
    23/24    0.000    0.000    0.004    0.000 asyncore.py:205(loop)
       45    0.000    0.000    0.000    0.000 utils.py:1220(monotonic_time)
       46    0.000    0.000    0.001    0.000 betterAsyncore.py:51(Dispatcher.readable)

Change-Id: Ia5a04b471846a85e2af63402c96dfd31dfe03644
Signed-off-by: Nir Soffer <nsoffer at redhat.com>
---
M vdsm/protocoldetector.py
1 file changed, 4 insertions(+), 4 deletions(-)


  git pull ssh://gerrit.ovirt.org:29418/vdsm refs/changes/97/39997/1

diff --git a/vdsm/protocoldetector.py b/vdsm/protocoldetector.py
index a3fd402..0454de4 100644
--- a/vdsm/protocoldetector.py
+++ b/vdsm/protocoldetector.py
@@ -85,6 +85,10 @@
         self._give_up_at = monotonic_time() + timeout
 
     def readable(self, dispatcher):
+        if monotonic_time() > self._give_up_at:
+            self.log.debug("Timed out while waiting for data")
+            dispatcher.close()
+            return False
         return True
 
     def writable(self, dispatcher):
@@ -105,10 +109,6 @@
 
         if len(data) < self._required_size:
             return
-
-        if monotonic_time() > self._give_up_at:
-            self.log.debug("Timed out while waiting for data")
-            dispatcher.close()
 
         for detector in self._detectors:
             if detector.detect(data):


-- 
To view, visit https://gerrit.ovirt.org/39997
To unsubscribe, visit https://gerrit.ovirt.org/settings

Gerrit-MessageType: newchange
Gerrit-Change-Id: Ia5a04b471846a85e2af63402c96dfd31dfe03644
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