Nir Soffer has uploaded a new change for review.
Change subject: misc: Faster version of readspeed ......................................................................
misc: Faster version of readspeed
After optimizing list2cmdline, we can see that the profile is dominated by utils.execCmd(), used to invoke dd for checking reading speed. This code is quite complex, using fancy classes such as AsyncProc and StreamWrapper. These are useful when you read from multiple streams to avoid deadlocks. However for checking reading speed, this seems like an overkill; we want dd to read a block from storage and read 3 lines of statistics from stderr. We don't care about the data read by dd, and have no reason to read this data from dd stdout.
This patch uses cpopen.Popen directly, running dd reading from a path and writing to /dev/null, and use Popen.communicate to read dd stderr. Since we are communicating with dd using a single pipe, a deadlock is not possible.
I tested this patch on two identical machines connected to 32 storage domains. Each one run 5 minutes as spm, and 5 minutes as hsm during 10 minutes profiling session. The first system was running the previous patch in this branch:
Sun May 11 02:23:31 2014 vdsmd-list2cmdline.prof
8758092 function calls (8816678 primitive calls) in 81.525 CPU seconds
Ordered by: internal time List reduced from 1872 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function) 101/136 6.554 0.065 46.116 0.339 threading.py:481(Thread.run) 1352629 3.652 0.000 6.595 0.000 utils.py:557(AsyncProc._processStreams) 134289 2.296 0.000 2.296 0.000 pthread.py:98(Lock.unlock) 9764 2.282 0.000 3.617 0.000 __init__.py:226(LogRecord.__init__) 25631 2.202 0.000 10.448 0.000 utils.py:466(_streamWrapper._readNonBlock) 116992 2.145 0.000 2.157 0.000 pthread.py:95(Lock.lock) 6049 2.031 0.000 6.722 0.001 misc.py:125(findCaller) 18524 1.954 0.000 22.039 0.001 io.py:492(BufferedReader.readline) 58408 1.788 0.000 1.882 0.000 genericpath.py:85(_splitext) 2521 1.631 0.001 8.974 0.004 utils.py:623(AsyncProc.wait)
Ordered by: cumulative time List reduced from 1872 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function) 33/36 0.001 0.000 69.017 1.917 utils.py:770(wrapper) 31/32 0.072 0.002 68.740 2.148 domainMonitor.py:163(DomainMonitorThread._monitorLoop) 1072/2105 0.720 0.001 68.122 0.032 domainMonitor.py:186(DomainMonitorThread._monitorDomain) 2519 0.494 0.000 56.573 0.022 utils.py:666(execCmd) 2041/2105 0.110 0.000 46.814 0.022 blockSD.py:594(BlockStorageDomain.getReadDelay) 2105 0.139 0.000 46.411 0.022 misc.py:222(readspeed) 2105 0.314 0.000 46.241 0.022 misc.py:192(_readfile) 101/136 6.554 0.065 46.116 0.339 threading.py:481(Thread.run) 2516 0.133 0.000 34.884 0.014 utils.py:633(AsyncProc.communicate) 18520/18524 0.255 0.000 22.294 0.001 io.py:532(BufferedReader.next)
The seconds system was running this branch:
Sun May 11 02:23:38 2014 vdsmd-optimize.prof
2113774 function calls (2168006 primitive calls) in 43.489 CPU seconds
Ordered by: internal time List reduced from 1873 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function) 111/136 8.270 0.075 29.113 0.214 threading.py:481(Thread.run) 41106 0.912 0.000 0.912 0.000 pthread.py:95(Lock.lock) 2146 0.898 0.000 1.412 0.001 subprocess.py:1344(Popen._communicate_with_poll) 27318 0.866 0.000 1.873 0.000 utils.py:557(AsyncProc._processStreams) 1867 0.810 0.000 2.509 0.001 misc.py:126(findCaller) 43735 0.791 0.000 0.791 0.000 pthread.py:98(Lock.unlock) 8112 0.719 0.000 5.590 0.001 __init__.py:1204(Logger.callHandlers) 7326/7338 0.692 0.000 0.741 0.000 pthread.py:133(Cond.timedwait) 1553/2145 0.648 0.000 34.541 0.016 domainMonitor.py:186(DomainMonitorThread._monitorDomain)
Ordered by: cumulative time List reduced from 1873 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function) 34/36 0.001 0.000 35.231 0.979 utils.py:770(wrapper) 32 0.075 0.002 35.099 1.097 domainMonitor.py:163(DomainMonitorThread._monitorLoop) 1553/2145 0.648 0.000 34.541 0.016 domainMonitor.py:186(DomainMonitorThread._monitorDomain) 111/136 8.270 0.075 29.113 0.214 threading.py:481(Thread.run) 13501 0.179 0.000 17.309 0.001 sdc.py:51(DomainProxy.getRealDomain) 13501 0.381 0.000 17.129 0.001 sdc.py:101(StorageDomainCache._realProduce) 97 0.009 0.000 15.431 0.159 sdc.py:133(StorageDomainCache._findDomain) 97 0.007 0.000 15.112 0.156 blockSD.py:1359(findDomain) 91 0.007 0.000 14.304 0.157 sdc.py:148(StorageDomainCache._findUnfetchedDomain) 97 0.042 0.000 14.060 0.145 blockSD.py:400(BlockStorageDomain.__init__) ... 2145 0.344 0.000 8.410 0.004 misc.py:223(readspeed)
Comparing the profiles show:
- Number of function calls dropped from 8758092 to 2113774 (75%) - Number of cpu seconds dropped from 81 to 43 (46%) - Time spent in _monitorDomain() dropped from 68 to 34 seconds (%50) - Time spent in readspeed() dropped from 46.4 to 8.4 seconds (81%)
Change-Id: I7ecf1f27d8434aeae672e92ec7adb12e52e419a9 Signed-off-by: Nir Soffer nsoffer@redhat.com --- M vdsm/storage/misc.py 1 file changed, 20 insertions(+), 7 deletions(-)
git pull ssh://gerrit.ovirt.org:29418/vdsm refs/changes/53/27553/1
diff --git a/vdsm/storage/misc.py b/vdsm/storage/misc.py index 12d4d97..8520c37 100644 --- a/vdsm/storage/misc.py +++ b/vdsm/storage/misc.py @@ -32,6 +32,7 @@ from functools import wraps, partial from itertools import chain, imap import contextlib +import cpopen import errno import glob import logging @@ -219,26 +220,38 @@ )
-def readspeed(path, buffersize=None): +def readspeed(path, buffersize): """ Measures the amount of bytes transferred and the time elapsed reading the content of the file/device """ - rc, _, err = _readfile(path, buffersize)
- if rc != 0: - log.error("Unable to read file '%s'", path) - raise se.MiscFileReadException(path) + # Read data from file to /dev/null, as we are not interested in the data + # itself, only in the read statistics provided by dd on stderr. + cmd = [constants.EXT_DD, "if=%s" % path, "iflag=%s" % DIRECTFLAG, + "of=/dev/null", "bs=%d" % buffersize, "count=1"] + + log.debug("Running %s", utils.list2cmdline(cmd)) + p = cpopen.CPopen(cmd, close_fds=True) + try: + out, err = p.communicate() + if p.returncode: + log.error("Unable to read file '%s'", path) + raise se.MiscFileReadException(path) + finally: + if p.returncode is None: + p.kill()
try: # The statistics are located in the last line: - m = _readspeed_regex.match(err[-1]) + statsLine = err.splitlines()[-1] + m = _readspeed_regex.match(statsLine) except IndexError: log.error("Unable to find dd statistics to parse") raise se.MiscFileReadException(path)
if m is None: - log.error("Unable to parse dd output: '%s'", err[-1]) + log.error("Unable to parse dd output: '%s'", statsLine) raise se.MiscFileReadException(path)
return {
oVirt Jenkins CI Server has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8718/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/8850/ : FAILURE
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/7928/ : SUCCESS
oVirt Jenkins CI Server has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8718/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/7928/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/8852/ : FAILURE
oVirt Jenkins CI Server has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8718/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/7928/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/8853/ : FAILURE
oVirt Jenkins CI Server has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
Build Successful
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8718/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/7928/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/8855/ : SUCCESS
Alon Bar-Lev has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
I do not understand how os.read() will produce different results.
Nir Soffer has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
I dont understand your comment
Alon Bar-Lev has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
why do you execute dd and not use python os.read() in a loop with O_DIRECT or any other flag that you may want.
Nir Soffer has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
We do not access shared storage directly from vdsm, since io operations may block, and bring vdsm into D state. The current solution is running dd and other tools when accessing storage.
Alon Bar-Lev has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
not sure I understand, you use su to run this dd? I do not see that.
if not, you can wrap os.read() within os.fork(), much more efficient.
Alon Bar-Lev has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
anyway, you are free to ignore my comments... my ability to help vdsm is limited.
Federico Simoncelli has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
(1 comment)
http://gerrit.ovirt.org/#/c/27553/1/vdsm/storage/misc.py File vdsm/storage/misc.py:
Line 231: cmd = [constants.EXT_DD, "if=%s" % path, "iflag=%s" % DIRECTFLAG, Line 232: "of=/dev/null", "bs=%d" % buffersize, "count=1"] Line 233: Line 234: log.debug("Running %s", utils.list2cmdline(cmd)) Line 235: p = cpopen.CPopen(cmd, close_fds=True) Here you're just re-implementing execCmd except for AsyncProc, therefore I think that the correct fix would be trying to not use AsyncProc in execCmd when sync=True.
The performance improvement of that change would be much wider in VDSM. Line 236: try: Line 237: out, err = p.communicate() Line 238: if p.returncode: Line 239: log.error("Unable to read file '%s'", path)
Nir Soffer has posted comments on this change.
Change subject: misc: Faster version of readspeed ......................................................................
Patch Set 1:
(1 comment)
http://gerrit.ovirt.org/#/c/27553/1/vdsm/storage/misc.py File vdsm/storage/misc.py:
Line 231: cmd = [constants.EXT_DD, "if=%s" % path, "iflag=%s" % DIRECTFLAG, Line 232: "of=/dev/null", "bs=%d" % buffersize, "count=1"] Line 233: Line 234: log.debug("Running %s", utils.list2cmdline(cmd)) Line 235: p = cpopen.CPopen(cmd, close_fds=True)
Here you're just re-implementing execCmd except for AsyncProc, therefore I
Good idea - I'll check this direction. Line 236: try: Line 237: out, err = p.communicate() Line 238: if p.returncode: Line 239: log.error("Unable to read file '%s'", path)
Nir Soffer has posted comments on this change.
Change subject: misc: Decrease cpu usage when executing commands ......................................................................
Patch Set 2:
This version minimize the patch and cpu usage, thanks to Federico suggestion.
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 3:
This version remove the readspeed optimization, which is not related to this change, and will be sent in a separate patch.
Federico Simoncelli has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 3: Code-Review+1
Looks good to me but I want Saggi's opinion as he implemented AsyncProc and he knows best what we could actually lose here.
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 2:
Build Successful
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8769/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/8905/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/7979/ : SUCCESS
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 3:
Build Successful
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8771/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/8907/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/7981/ : SUCCESS
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 4:
Rebase over dependent patch, no code change.
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 4:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8808/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/8944/ : FAILURE
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8018/ : SUCCESS
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 4: Verified+1
Verified by running profiling sessions on RHEL 6.5 and Fedora 19, and by running sanity tests (creating/running/removing vm).
Antoni Segura Puimedon has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 4: Code-Review+1
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 4:
While at it, I also tested the migrating a machine few times while it is running yum update, still works :-)
Yaniv Bronhaim has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 4:
(1 comment)
http://gerrit.ovirt.org/#/c/27553/4/lib/vdsm/utils.py File lib/vdsm/utils.py:
Line 716 Line 717 Line 718 Line 719 Line 720 communicate is AsyncProc's function, don't we get AttributeError error if sync=True?
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 4:
(1 comment)
http://gerrit.ovirt.org/#/c/27553/4/lib/vdsm/utils.py File lib/vdsm/utils.py:
Line 716 Line 717 Line 718 Line 719 Line 720
communicate is AsyncProc's function, don't we get AttributeError error if s
No, communicate is subprocess.Popen api: https://docs.python.org/2.6/library/subprocess.html#subprocess.Popen.communi...
Yaniv Bronhaim has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 4:
(1 comment)
http://gerrit.ovirt.org/#/c/27553/4/lib/vdsm/utils.py File lib/vdsm/utils.py:
Line 716 Line 717 Line 718 Line 719 Line 720
No, communicate is subprocess.Popen api:
right.
Saggi Mizrahi has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 4: Code-Review-2
Sorry, no cigar. Python's implementation is know to break under scale.
Might have been fixed in python3 but for 2 it's a known issue.
We might need to make a sync path so that we don't use pythons communicate but don't pay the price of a the fully async algorithms.
Please open an RFE about that.
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 4:
What can break with Popen.communicate?
Do you have any relevant bugs that prove your point?
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 6:
Fix the commit message - the description seems to confuse people.
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 5:
Build Successful
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8834/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/8970/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8044/ : SUCCESS
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 6:
Build Successful
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8837/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/8973/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8047/ : SUCCESS
Saggi Mizrahi has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 4:
Sadly, Tabula Rasa ate the actual commit so I can't find the bug report. It was years ago.
But it's an issue with 2.6 and some versions of 2.7 with the loop that reads the file descriptors it failed to use poll or in some cases used it incorrectly and cause errors for client.
Once we stop supporting EL6 we might try and consider retesting against the python version in EL7 but I would still like to just use our own path since it's pretty critical and python's standard library is know to be quite bad when it comes to scale.
You would need a very large scale test for this, you need about a 1000 running subprocesses for the bug to show it's face.
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 6:
Thanks Saggi! Is this old bug still relevant in the current version we support?
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 6:
Seems that Saggi is referring to commit 812a1dd0faaac6046f960e912f5f1c2f4f838171, related to https://bugzilla.redhat.com/666227
But the bug is not related to this, it seems to be an issue with dd process bs parameter.
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 7: Verified+1
This version adds stress tests to address concerned about Popen.communicate() reliability when running many commands in parallel.
No code change.
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 8:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8909/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9045/ : FAILURE
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8119/ : FAILURE
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 8: Verified+1
The tests read and write more data now, so we have more process running in the same time.
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 7:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8908/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9044/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8118/ : FAILURE
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 9: Verified+1
Fixed tests on EL, where dd lives in /bin.
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 9:
Build Successful
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8910/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9046/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8120/ : SUCCESS
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 9:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8910/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8120/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9050/ : FAILURE
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 9:
The test failure is not related to this patch.
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 10: Verified+1
This version separated the tests to a different patch, so we can use the same tests with the original implementation, and ensure that this patch did not introduce any regression.
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 10:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8924/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9062/ : FAILURE
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8134/ : SUCCESS
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 10:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8924/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8134/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9065/ : FAILURE
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 10:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8924/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8134/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9066/ : FAILURE
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 10:
Build Successful
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8924/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8134/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9067/ : SUCCESS
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 11:
Rebase, no code change.
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 11:
Build Successful
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/8927/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9068/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8139/ : SUCCESS
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 11:
Note that the new crazy execCmd tests using 200 threads pass now even on jenkins.
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 12:
Build Successful
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/9099/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9240/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8311/ : SUCCESS
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 12:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/9099/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8311/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9242/ : FAILURE
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 12:
Build Successful
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/9099/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8311/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9243/ : SUCCESS
Nir Soffer has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 13:
Rebase, no code change.
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 13:
Build Failed
http://jenkins.ovirt.org/job/vdsm_master_pep8_gerrit/9200/ : SUCCESS
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit/9343/ : FAILURE
http://jenkins.ovirt.org/job/vdsm_master_unit_tests_gerrit_el/8412/ : SUCCESS
Federico Simoncelli has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 13:
Ping Saggi? Can you point us to any issue/bug we were addressing with AsyncProc?
Saggi Mizrahi has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 13: Code-Review+2
Dan Kenigsberg has submitted this change and it was merged.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
utils: Decrease cpu usage when executing commands
After optimizing list2cmdline, we can see that the profile is dominated by utils.execCmd() and related functions such as AsyncProc._processStreams(). This code is quite complex, using fancy classes such as AsyncProc and _streamWrapper, and using epoll to poll for 3 file descriptors. These are useful when reading asynchronously from multiple streams without risk of deadlock. However, for invoking commands synchronously, polling 2 file descriptors, CPopen.communicate, using poll, is safe and much more efficient.
This patch avoids wrapping of the CPopen object with AsyncProc when executing commands in sync mode.
I tested this on two identical RHEL 6.5 machines connected to 32 storage domains. Each one run 5 minutes as spm, and 5 minutes as hsm during 10 minutes profiling session. The first system was running the previous patch in this branch:
Tue May 13 09:47:10 2014 /var/run/vdsm/vdsmd.prof
8410533 function calls (8466483 primitive calls) in 70.879 CPU seconds
Ordered by: internal time List reduced from 1872 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function) 1281887 3.404 0.000 6.038 0.000 utils.py:557(AsyncProc._processStreams) 131670 2.162 0.000 2.174 0.000 pthread.py:98(Lock.unlock) 24898 2.134 0.000 10.016 0.000 utils.py:466(_streamWrapper._readNonBlock) 114437 1.992 0.000 2.018 0.000 pthread.py:95(Lock.lock) 17996 1.916 0.000 21.293 0.001 io.py:492(BufferedReader.readline) 98/136 1.912 0.020 23.986 0.176 threading.py:481(Thread.run) 5918 1.829 0.000 6.438 0.001 misc.py:125(findCaller) 57658 1.738 0.000 1.821 0.000 genericpath.py:85(_splitext) 10005 1.644 0.000 3.479 0.000 __init__.py:226(LogRecord.__init__) 2452 1.497 0.001 8.357 0.003 utils.py:623(AsyncProc.wait)
Ordered by: cumulative time List reduced from 1872 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function) 34/36 0.007 0.000 68.214 1.895 utils.py:770(wrapper) 32 0.069 0.002 67.969 2.124 domainMonitor.py:163(DomainMonitorThread._monitorLoop) 985/2040 0.728 0.001 67.471 0.033 domainMonitor.py:186(DomainMonitorThread._monitorDomain) 2450 0.447 0.000 53.669 0.022 utils.py:666(execCmd) 2040 0.093 0.000 46.161 0.023 blockSD.py:594(BlockStorageDomain.getReadDelay) 2040 0.131 0.000 45.845 0.022 misc.py:222(readspeed) 2040 0.310 0.000 45.696 0.022 misc.py:192(_readfile) 2447 0.133 0.000 33.060 0.014 utils.py:633(AsyncProc.communicate) 98/136 1.912 0.020 23.986 0.176 threading.py:481(Thread.run) 17994/17996 0.250 0.000 21.544 0.001 io.py:532(BufferedReader.next)
The seconds system was running with this patch:
Tue May 13 09:47:04 2014 /var/run/vdsm/vdsmd.prof
1988663 function calls (2044070 primitive calls) in 36.675 CPU seconds
Ordered by: internal time List reduced from 1871 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function) 98/136 6.643 0.068 19.059 0.140 threading.py:481(Thread.run) 9508 1.566 0.000 2.801 0.000 __init__.py:226(LogRecord.__init__) 5795 1.511 0.000 4.948 0.001 misc.py:125(findCaller) 56250 1.312 0.000 1.405 0.000 genericpath.py:85(_splitext) 2361 1.306 0.001 2.084 0.001 subprocess.py:1344(CPopen._communicate_with_poll) 38915 0.881 0.000 2.766 0.000 misc.py:110(_shouldLogSkip) 56233/56250 0.827 0.000 2.239 0.000 posixpath.py:94(splitext) 9508 0.713 0.000 5.644 0.001 __init__.py:1204(Logger.callHandlers) 32083 0.598 0.000 0.598 0.000 misc.py:84(checkForSkip) 6953/6965 0.591 0.000 0.627 0.000 pthread.py:133(Cond.timedwait)
Ordered by: cumulative time List reduced from 1871 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function) 34/36 0.001 0.000 27.957 0.777 utils.py:770(wrapper) 32 0.041 0.001 27.767 0.868 domainMonitor.py:163(DomainMonitorThread._monitorLoop) 840/1957 0.404 0.000 27.454 0.014 domainMonitor.py:186(DomainMonitorThread._monitorDomain) 98/136 6.643 0.068 19.059 0.140 threading.py:481(Thread.run) 2365 0.338 0.000 17.226 0.007 utils.py:666(execCmd) 9507/9508 0.187 0.000 14.434 0.002 __init__.py:1155(Logger._log) 8640/8738 0.243 0.000 14.430 0.002 __init__.py:1034(Logger.debug) 1957 0.067 0.000 13.107 0.007 blockSD.py:594(BlockStorageDomain.getReadDelay) 1957 0.101 0.000 12.933 0.007 misc.py:222(readspeed) 1957 0.131 0.000 12.815 0.007 misc.py:192(_readfile)
Comparing the profiles show:
- Number of function calls dropped from 8410533 to 1988663 (-76%) - Number of cpu seconds dropped from 70.8 to 36.6 (-48%) - Time spent in execCmd dropped from 53.6 to 17.2 seconds (-67%)
Change-Id: I7ecf1f27d8434aeae672e92ec7adb12e52e419a9 Signed-off-by: Nir Soffer nsoffer@redhat.com Reviewed-on: http://gerrit.ovirt.org/27553 Reviewed-by: Saggi Mizrahi smizrahi@redhat.com --- M lib/vdsm/utils.py 1 file changed, 1 insertion(+), 1 deletion(-)
Approvals: Nir Soffer: Verified Saggi Mizrahi: Looks good to me, approved
oVirt Jenkins CI Server has posted comments on this change.
Change subject: utils: Decrease cpu usage when executing commands ......................................................................
Patch Set 14:
Build Successful
http://jenkins.ovirt.org/job/vdsm_master_create-rpms_merged/1390/ : SUCCESS
vdsm-patches@lists.fedorahosted.org