Change in vdsm[master]: utils: Decrease cpu usage when executing commands
danken at redhat.com
danken at redhat.com
Thu Jun 5 14:17:09 UTC 2014
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 at redhat.com>
Reviewed-on: http://gerrit.ovirt.org/27553
Reviewed-by: Saggi Mizrahi <smizrahi at 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
--
To view, visit http://gerrit.ovirt.org/27553
To unsubscribe, visit http://gerrit.ovirt.org/settings
Gerrit-MessageType: merged
Gerrit-Change-Id: I7ecf1f27d8434aeae672e92ec7adb12e52e419a9
Gerrit-PatchSet: 14
Gerrit-Project: vdsm
Gerrit-Branch: master
Gerrit-Owner: Nir Soffer <nsoffer at redhat.com>
Gerrit-Reviewer: Adam Litke <alitke at redhat.com>
Gerrit-Reviewer: Allon Mureinik <amureini at redhat.com>
Gerrit-Reviewer: Alon Bar-Lev <alonbl at redhat.com>
Gerrit-Reviewer: Antoni Segura Puimedon <asegurap at redhat.com>
Gerrit-Reviewer: Dan Kenigsberg <danken at redhat.com>
Gerrit-Reviewer: Federico Simoncelli <fsimonce at redhat.com>
Gerrit-Reviewer: Nir Soffer <nsoffer at redhat.com>
Gerrit-Reviewer: Saggi Mizrahi <smizrahi at redhat.com>
Gerrit-Reviewer: Yaniv Bronhaim <ybronhei at redhat.com>
Gerrit-Reviewer: automation at ovirt.org
Gerrit-Reviewer: oVirt Jenkins CI Server
More information about the vdsm-patches
mailing list