Dan Kenigsberg has submitted this change and it was merged.
Change subject: utils: Correct and faster list2cmdline ......................................................................
utils: Correct and faster list2cmdline
subprocess.list2cmdline dominates the profile on idle vdsm with many storage domains, using more than 10% of cpu time. We use this function to format commands in the log, so it is possible to copy the command to the shell and run for debugging.
Turns out that this is undocumented function used on Windows to convert argument list to string compatible with the MS C runtime. Using repr(), it works on Linux for simple commands, but does not get quoting right with complex commands.
This patch replaces the function with a correct, simple and efficient implementation compatible with Linux shells. The new function should not be used with repr(), which render its output useless.
I tested this patch on Fedora 19 machine connected to 30 storage domains, running 10 minutes profiling session as spm. Without this patch subprocess.list2cmdline() is the most expensive function responsible for 12.5% of cpu time:
Thu Jun 5 23:15:18 2014 vdsmd.prof
2139104 function calls (2202966 primitive calls) in 16.652 seconds
Ordered by: internal time List reduced from 1785 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function) 2151 1.816 0.001 2.140 0.001 subprocess.py:579(list2cmdline) 97/128 1.407 0.015 11.004 0.086 threading.py:753(Thread.run) 10221 0.494 0.000 1.028 0.000 __init__.py:242(LogRecord.__init__) 5397 0.478 0.000 1.575 0.000 misc.py:125(findCaller) 8508 0.422 0.000 0.641 0.000 spark.py:211(Parser.buildState) 50336 0.404 0.000 0.463 0.000 genericpath.py:85(_splitext) 32657/32664 0.273 0.000 0.815 0.000 misc.py:110(_shouldLogSkip) 50095 0.271 0.000 0.271 0.000 pthread.py:95(Lock.lock) 2147 0.266 0.000 0.517 0.000 subprocess.py:1406(CPopen._communicate_with_poll) 50331/50336 0.238 0.000 0.708 0.000 posixpath.py:104(splitext)
With this patch, utils._list2cmdline() uses only fraction of the cpu time:
2158 0.085 0.000 0.118 0.000 utils.py:652(_list2cmdline)
Note: the profile was performed with older version of this patch, the current version is simpler more efficient.
Change-Id: Ibfc7819c126fe51cc068cc6f9f85b1002878385b Signed-off-by: Nir Soffer nsoffer@redhat.com Reviewed-on: http://gerrit.ovirt.org/27548 Reviewed-by: Federico Simoncelli fsimonce@redhat.com --- M lib/vdsm/utils.py M tests/utilsTests.py 2 files changed, 59 insertions(+), 3 deletions(-)
Approvals: Nir Soffer: Verified Federico Simoncelli: Looks good to me, approved