[ovirt-devel] [VDSM] [JSONRPC] early, coarse grained benchmarks
Francesco Romani
fromani at redhat.com
Thu Nov 13 16:47:04 UTC 2014
----- Original Message -----
> From: "Piotr Kliczewski" <piotr.kliczewski at gmail.com>
> To: "Francesco Romani" <fromani at redhat.com>
> Cc: "engine-devel at ovirt.org" <devel at ovirt.org>
> Sent: Monday, November 10, 2014 4:06:38 PM
> Subject: Re: [ovirt-devel] [VDSM] [JSONRPC] early, coarse grained benchmarks
>
> Great work!
>
> On Mon, Nov 10, 2014 at 3:50 PM, Francesco Romani <fromani at redhat.com> wrote:
> > 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.
> >
>
> Once I have a bit o time will work on it.
Well, it's on my list as well since long time so no pressure.
I'm profiling four major flows at the moment, and improving tools along the way.
Here's my series, still being worked on and not yet ready for review (still draft for this reason)
http://gerrit.ovirt.org/#/q/status:open+project:vdsm+branch:master+topic:profile_runtime,n,z
Here we have
1. one patch to start/stop profiling at runtime using vdsClient
2. one simple (simplistic?) benchmark runner script
more will come as need arises. A proper wiki page about how to profile VDSM is planned as well.
The flow which I'm testing are
1. VM startup
2. VM shutdown
3. VM list
4. VM getAllVmStats
with focus on VDSM side, not all the flow; thus, I'm intentionally ruling out Engine from the picture.
1 and 2 because of https://bugzilla.redhat.com/show_bug.cgi?id=1155146
3 and 4 because of https://bugzilla.redhat.com/show_bug.cgi?id=1110835
So far, the profile of #2 was the more puzzling, as no clear bottleneck emerged yet. A new deeper round
is scheduled ASAP.
I found optimizations that affect 1, 3, 4, especially with JSONRPC. Unfortunately, I can't yet test
with vdsClient (see above). Will follow up on that ASAP.
Patches, in order of readiness for review:
http://gerrit.ovirt.org/#/c/35024/
http://gerrit.ovirt.org/#/c/34989/
http://gerrit.ovirt.org/#/c/35139 (DRAFT)
http://gerrit.ovirt.org/#/c/35140 (DRAFT)
Let's see the effect of these in the #3 flows.
Scenario:
RHEL 6.5 on minidell running VDSM master + patches, with 150 VMs each one 1 VCPU, 16 MB (megs) RAM and 1 GB HDD
on ISCSI. Run 300 times
"vdsClient -s 0 list table"
vanilla VDSM:
average=6985ms min=3220ms max=11880ms
response time: percentage
<3000ms: 0.0
<3500ms: 8.3
<4000ms: 18.3
<4500ms: 23.0
<5000ms: 27.7
<5500ms: 31.0
<6000ms: 36.3
<6500ms: 41.0
<7000ms: 49.0
<7500ms: 54.7
<8000ms: 59.0
<8500ms: 66.0
<9000ms: 71.7
<9500ms: 79.7
<10000ms: 88.3
<10500ms: 96.3
<11000ms: 99.0
<11500ms: 99.7
<12000ms: 100.0
patched VDSM:
average=5761ms min=2830ms max=11450ms
response time: percentage
<3000ms: 0.3
<3500ms: 6.7
<4000ms: 20.7
<4500ms: 30.7
<5000ms: 39.7
<5500ms: 48.0
<6000ms: 56.3
<6500ms: 66.3
<7000ms: 72.3
<7500ms: 80.0
<8000ms: 87.7
<8500ms: 94.3
<9000ms: 97.7
<9500ms: 98.0
<10000ms: 98.7
<10500ms: 99.3
<11000ms: 99.7
<11500ms: 100.0
<12000ms: 100.0
See attachment for an oocalc spreadsheat with raw samples and graph
profiles.
Vanilla VDSM:
243874010 function calls (349761179 primitive calls) in 2612.654 seconds
Ordered by: internal time
List reduced from 883 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
196905/49111117 500.567 0.003 1002.618 0.000 copy.py:144(deepcopy)
120996/4106203 217.146 0.002 998.929 0.000 copy.py:251(_deepcopy_dict)
39443308 192.752 0.000 217.518 0.000 copy.py:261(_keep_alive)
859 149.007 0.173 149.466 0.174 storage_mailbox.py:621(SPM_MailMonitor._handleRequests)
601/1891502 147.901 0.246 579.963 0.000 xmlrpclib.py:765(Marshaller.dump_struct)
65493648 128.666 0.000 169.473 0.000 string.py:511(replace)
7858586/32213416 95.784 0.000 209.567 0.000 encoder.py:284(JSONEncoder._iterencode)
21831216 89.865 0.000 259.338 0.000 xmlrpclib.py:167(escape)
7858587/20679836 80.741 0.000 196.755 0.000 encoder.py:213(JSONEncoder._iterencode_dict)
601/12515060 66.632 0.111 579.970 0.000 xmlrpclib.py:683(Marshaller.__dump)
227968 50.938 0.000 59.783 0.000 __init__.py:764(UserGroupEnforcingHandler.emit)
155279 45.445 0.000 5.345 0.000 posixpath.py:94(splitext)
133463 45.351 0.000 104.987 0.001 __init__.py:1175(Logger.handle)
7290900 45.228 0.000 149.552 0.000 xmlrpclib.py:744(Marshaller.dump_unicode)
601 43.538 0.072 1.056 0.002 socket.py:196(_socketobject.accept)
35095608 31.967 0.000 31.967 0.000 copy.py:197(_deepcopy_atomic)
50498 24.912 0.000 55.671 0.001 inspect.py:247(getmembers)
7479142/8217142 24.764 0.000 150.280 0.000 encoder.py:180(JSONEncoder._iterencode_list)
75750 19.871 0.000 75.819 0.001 vm.py:2271(Vm._getRunningVmStats)
4447686 17.603 0.000 17.603 0.000 sampling.py:323(AdvancedStatsFunction.interval)
Patched VDSM:
165586271 function calls (181657572 primitive calls) in 2406.080 seconds
Ordered by: internal time
List reduced from 1045 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
51229/51594 198.728 0.004 184.402 0.004 Monitor.py:182(GuestMonitor._should_run)
234244 183.784 0.001 570.998 0.002 vm.py:2274(Vm._getRunningVmStats)
647/1891502 173.119 0.268 671.222 0.000 xmlrpclib.py:765(Marshaller.dump_struct)
66247525/66247536 150.364 0.000 192.790 0.000 string.py:511(replace)
653 118.867 0.182 119.219 0.183 storage_mailbox.py:621(SPM_MailMonitor._handleRequests)
22052164/22082512 90.992 0.000 294.362 0.000 xmlrpclib.py:167(escape)
637/12640708 75.551 0.119 671.442 0.000 xmlrpclib.py:683(Marshaller.__dump)
5096229/5096259 66.229 0.000 64.007 0.000 utils.py:296(convertToStr)
7200900 49.677 0.000 161.784 0.000 xmlrpclib.py:744(Marshaller.dump_unicode)
1318320 39.141 0.000 39.141 0.000 vm.py:610(compute_latency)
57937/57940 37.975 0.001 80.458 0.001 inspect.py:247(getmembers)
234244 36.289 0.000 155.929 0.001 vm.py:519(VmStatsThread._getDiskStats)
234244 35.013 0.000 46.974 0.000 vm.py:2359(Vm._getGraphicsStats)
365102 24.819 0.000 106.858 0.000 glob.py:18(iglob)
234244 23.588 0.000 32.139 0.000 vm.py:402(VmStatsThread._getBalloonStats)
439440 22.295 0.000 22.295 0.000 vm.py:595(_calcDiskRate)
439440 22.178 0.000 61.320 0.000 vm.py:607(_calcDiskLatency)
834132 21.402 0.000 21.402 0.000 vm.py:1311(Vm._get_lastStatus)
1071684 19.455 0.000 24.374 0.000 pthreading.py:77(Lock.release)
2961805 18.907 0.000 61.027 0.000 xmlrpclib.py:737(Marshaller.dump_string)
Open points:
* profile remaining flows again and report like this (in progress for getAllVmStats)
* add wiki page
* find out why there is a so high minimum price for list verb
* profile JSONRPC (needs patches to vdsClient)
Bests,
--
Francesco Romani
RedHat Engineering Virtualization R & D
Phone: 8261328
IRC: fromani
-------------- next part --------------
A non-text attachment was scrubbed...
Name: opts20141113.ods
Type: application/vnd.oasis.opendocument.spreadsheet
Size: 71033 bytes
Desc: not available
URL: <http://lists.ovirt.org/pipermail/devel/attachments/20141113/14680103/attachment-0001.ods>
More information about the Devel
mailing list