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