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 <[email protected]>
---
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 {
--
To view, visit http://gerrit.ovirt.org/27553
To unsubscribe, visit http://gerrit.ovirt.org/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: I7ecf1f27d8434aeae672e92ec7adb12e52e419a9
Gerrit-PatchSet: 1
Gerrit-Project: vdsm
Gerrit-Branch: master
Gerrit-Owner: Nir Soffer <[email protected]>
_______________________________________________
vdsm-patches mailing list
[email protected]
https://lists.fedorahosted.org/mailman/listinfo/vdsm-patches
