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