Re: [ovirt-devel] [VDSM] [JSONRPC] early, coarse grained benchmarks

Hi everyone, I'd like to share initial profiles of VDSM comparing XMLRPC and JSONRPC, plus two patches optimizing the latter. While the low-level profiler (yappi) is now working nicely, and this is a good building block, I'm not really satisfied about the testcase - altough it is a fair approximation of reality; most important, I'm not satisfied about benchmark driver, which is too coarse grained. The benchmark driver is a simple python script using the REST APIs of Engine. I'd like to be able to bypass Engine, but vdsClient is not good enough: no JSONRPC option yet.

I haven't found yet a good way to rule out noise and stress only the getStats flow. Out of necessity, either recover[1] or start/stop get in the way. I'm working on that. Profiles are meant as rough comparison, I cannot yet answer to question 'how xmlrpc and jsonrpc compare performancewise?'. To properly answer we need better tools. I'll work on that. Out of necessity, the testcase is: - on RHEL 6.5 server host (update to 6.6 ASAP) - on a freshly started VDSM, - serially boot 100 VMs, each one 1 core, 16 MiB ram, 1GB disk on ISCSI, no OS installed -thus no guest agent - after every VM is booted, let them run for 10 (ten) minutes, let Engine poll them with default settings (e.g. poll interval) - serially stop all the VMs - stop VDSM, collect profile. - profiling options in vdsm.conf: profile_enable = true profile_builtin = true So, in attachment we have: xmlrpc.txt: xmlrpc, default settings jsonrpc.txt: jsonrpc, default settings jsonrpc_cmod.txt: jsonrpc + simplejson 2.0.9 (patch discussed [2] not yet on gerrit) jsonrpc_cmod_hack.txt: jsonrpc + simplejson 2.0.9 + replaced deepcopy: patch isn't ready to be reviewd, http://gerrit.ovirt.org/#/c/34989/ to be discussed in a separate topic To ease the discussion, I'm pasting the top 10 most expensive calls for each of the profiles. xmlrpc: 45222158 function calls (65166621 primitive calls) in 783.999 CPU seconds ncalls tottime percall cumtime percall filename:lineno(function) 78/100 304.985 3.910 155.030 1.550 /usr/lib/python2.6/site-packages/mom/GuestMonitor.py:51(GuestMonitor.run) 110/125 136.121 1.237 167.478 1.340 /usr/lib64/python2.6/threading.py:481(Thread.run) 99/100 61.620 0.622 114.241 1.142 /usr/share/vdsm/virt/sampling.py:433(VmStatsThread.run) 88713/1231936 30.654 0.000 189.426 0.000 /usr/lib64/python2.6/copy.py:251(_deepcopy_dict) 54150 20.575 0.000 67.119 0.001 /usr/share/vdsm/virt/vm.py:2912(Vm._getRunningVmStats) 1445/3413514 16.291 0.011 0.052 0.000 /usr/share/vdsm/protocoldetector.py:94(MultiProtocolAcceptor._process_events) 100 8.570 0.086 69.581 0.696 /usr/share/vdsm/virt/sampling.py:452(VmStatsThread.collect) 1168251 7.756 0.000 7.756 0.000 /usr/lib/python2.6/site-packages/vdsm/utils.py:424(convertToStr) 10480836 6.313 0.000 6.313 0.000 /usr/lib64/python2.6/copy.py:197(_deepcopy_atomic) 155426 5.701 0.000 10.339 0.000 /usr/lib64/python2.6/xml/dom/expatbuilder.py:743(ExpatBuilderNS.start_element_handler) jsonrpc: 60351712 function calls (96981783 primitive calls) in 823.499 CPU seconds ncalls tottime percall cumtime percall filename:lineno(function) 98/100 197.061 2.011 265.583 2.656 /usr/lib/python2.6/site-packages/mom/GuestMonitor.py:51(GuestMonitor.run) 13331/13412 117.132 0.009 294.482 0.022 /usr/lib64/python2.6/threading.py:481(Thread.run) 97439/12454808 71.739 0.001 193.515 0.000 /usr/lib64/python2.6/copy.py:144(deepcopy) 100 38.230 0.382 103.942 1.039 /usr/share/vdsm/virt/sampling.py:433(VmStatsThread.run) 96751/1103236 30.798 0.000 191.919 0.000 /usr/lib64/python2.6/copy.py:251(_deepcopy_dict) 66286 24.808 0.000 82.338 0.001 /usr/share/vdsm/virt/vm.py:2912(Vm._getRunningVmStats) 4107389/16859232 23.189 0.000 48.677 0.000 /usr/lib64/python2.6/json/encoder.py:284(JSONEncoder._iterencode) 4107412/10861908 17.214 0.000 44.677 0.000 /usr/lib64/python2.6/json/encoder.py:213(JSONEncoder._iterencode_dict) 100 9.888 0.099 77.989 0.780 /usr/share/vdsm/virt/sampling.py:452(VmStatsThread.collect) 1435169/1435182 9.272 0.000 9.313 0.000 /usr/lib/python2.6/site-packages/vdsm/utils.py:424(convertToStr) jsonrpc + simplejson 2.0.9: 50417851 function calls (64835240 primitive calls) in 651.791 CPU seconds ncalls tottime percall cumtime percall filename:lineno(function) 98/100 171.140 1.746 240.428 2.404 /usr/lib/python2.6/site-packages/mom/GuestMonitor.py:51(GuestMonitor.run) 97345/12686631 70.419 0.001 170.315 0.000 /usr/lib64/python2.6/copy.py:144(deepcopy) 13636/13711 39.225 0.003 189.352 0.014 /usr/lib64/python2.6/threading.py:481(Thread.run) 10429451 28.526 0.000 40.548 0.000 /usr/lib64/python2.6/copy.py:261(_keep_alive) 96639/1122019 23.297 0.000 168.826 0.000 /usr/lib64/python2.6/copy.py:251(_deepcopy_dict) 65621 22.852 0.000 75.526 0.001 /usr/share/vdsm/virt/vm.py:2912(Vm._getRunningVmStats) 2566920/2566921 18.205 0.000 26.546 0.000 /usr/share/vdsm/protocoldetector.py:94(MultiProtocolAcceptor._process_events) 100 9.077 0.091 73.731 0.737 /usr/share/vdsm/virt/sampling.py:452(VmStatsThread.collect) 1420035 8.615 0.000 8.615 0.000 /usr/lib/python2.6/site-packages/vdsm/utils.py:424(convertToStr) 27178 6.568 0.000 15.722 0.001 /usr/lib64/python2.6/inspect.py:247(getmembers) jsonrpc + simplejson 2.0.9 + replaced deepcopy: 29976206 function calls (33600497 primitive calls) in 343.227 CPU seconds ncalls tottime percall cumtime percall filename:lineno(function) 16504/16584 28.458 0.002 89.572 0.005 /usr/lib64/python2.6/threading.py:481(Thread.run) 68344 24.167 0.000 77.159 0.001 /usr/share/vdsm/virt/vm.py:2911(Vm._getRunningVmStats) 9393/2746299 13.395 0.001 0.210 0.000 /usr/share/vdsm/protocoldetector.py:94(MultiProtocolAcceptor._process_events) 81/100 11.606 0.143 67.946 0.679 /usr/lib/python2.6/site-packages/mom/GuestMonitor.py:51(GuestMonitor.run) 1478844/1478858 9.112 0.000 9.118 0.000 /usr/lib/python2.6/site-packages/vdsm/utils.py:425(convertToStr) 100 7.838 0.078 68.841 0.688 /usr/share/vdsm/virt/sampling.py:452(VmStatsThread.collect) 32923/32924 7.245 0.000 17.585 0.001 /usr/lib64/python2.6/inspect.py:247(getmembers) 68300 5.182 0.000 10.420 0.000 /usr/share/vdsm/virt/vm.py:531(VmStatsThread._getDiskStats) 68344 4.696 0.000 6.360 0.000 /usr/share/vdsm/virt/vm.py:2990(Vm._getGraphicsStats) 806634/806638 4.499 0.000 5.986 0.000 /usr/lib64/python2.6/inspect.py:59(isclass) +++ [1] which is painfully slow, but this is another topic [2] http://lists.ovirt.org/pipermail/devel/2014-November/009208.html -- Francesco Romani RedHat Engineering Virtualization R & D Phone: 8261328 IRC: fromani _______________________________________________ Devel mailing list Devel(a)ovirt.org http://lists.ovirt.org/mailman/listinfo/devel