[VDSM] Profiling results - 144 cores, 144 vms
Hi all, I noticed that Eldad posted profiling result from 144 cores / 144 vms run: See https://bugzilla.redhat.com/attachment.cgi?id=1128028 Looking at the profile bellow: 1. Why _rtnl_link_alloc_cache is so expensive? called only 389 times, but the most expensive call 2. Creating DomainDescriptor seems expensive - is this xml.minidom? 3. guestagent.py:84(filt) is very expensive - we probbaly want to backport 7091bde guestagent: Speed up xml character filtering, can shave about 17% of cpu time in this run. 4. pthread.py function will disapper from the profile if we replace pthreading with cthreading: https://github.com/nirs/cthreading 5. Why do we see xmlrpc at the top of the profile? Is this the cost of mom calls? Eldad, can you repeat the same test with current master? Nir ---- Thu Feb 18 00:50:24 2016 vdsm_144vms_1800sec_2.prof 29858105 function calls (34034631 primitive calls) in 1049.574 seconds Ordered by: internal time List reduced from 2420 to 20 due to restriction <20> ncalls tottime percall cumtime percall filename:lineno(function) 389 64.937 0.167 64.941 0.167 link.py:133(_rtnl_link_alloc_cache) 598438 64.176 0.000 87.888 0.000 domain_descriptor.py:23(DomainDescriptor) 1535528 38.922 0.001 176.177 0.000 guestagent.py:84(filt) 57106 31.545 0.001 31.560 0.001 decoder.py:371(JSONDecoder.raw_decode) 168463 25.961 0.234 119.004 0.001 xmlrpclib.py:721(Marshaller.dump_struct) 4312452 25.095 0.000 77.012 0.000 utf_8.py:15(decode) 7341795 21.934 0.000 41.507 0.000 string.py:511(replace) 28881 18.092 0.001 19.921 0.001 pthread.py:133(Cond.timedwait) 386282 17.509 0.000 17.509 0.000 pthread.py:95(Lock.lock) 46277 16.798 0.000 45.280 0.001 guestagent.py:254(GuestAgent._handleMessage) 48090 16.298 0.000 37.809 0.001 expatbuilder.py:743(ExpatBuilderNS.start_element_handler) 2447266 14.128 0.000 55.635 0.000 httplib.py:331(HTTPResponse) 339514 13.689 0.014 20.629 0.000 password.py:69(_walk) 78549 12.450 0.000 12.635 0.000 minidom.py:344(Attr.__init__) 20117 12.381 0.001 20.961 0.001 vm.py:181(SetLinkAndNetworkError) 14470 12.224 0.001 12.802 0.001 xmlbuilder.py:1(<module>) 21404 11.527 0.001 36.225 0.002 vmstats.py:240(disks) 87612 11.441 0.000 35.701 0.000 sampling.py:59(InterfaceSample.readIfaceStat) 39924 11.323 0.000 23.047 0.001 __init__.py:242(LogRecord.__init__) 14509 10.816 0.001 96.236 0.007 xmlbuilder.py:12(Options)
----- Original Message -----
From: "Nir Soffer" <nsoffer@redhat.com> To: "devel" <devel@ovirt.org>, "Francesco Romani" <fromani@redhat.com>, "Eldad Marciano" <emarcian@redhat.com>, "Vinzenz Feenstra" <vfeenstr@redhat.com>, "Dan Kenigsberg" <danken@redhat.com>, "Piotr Kliczewski" <pkliczew@redhat.com> Sent: Thursday, February 18, 2016 12:38:44 AM Subject: [VDSM] Profiling results - 144 cores, 144 vms
Hi all,
I noticed that Eldad posted profiling result from 144 cores / 144 vms run: See https://bugzilla.redhat.com/attachment.cgi?id=1128028
Looking at the profile bellow:
2. Creating DomainDescriptor seems expensive - is this xml.minidom?
Let's look at DomainDescriptor's __init__ class DomainDescriptor(object): def __init__(self, xmlStr): self._xml = xmlStr self._dom = xml.dom.minidom.parseString(xmlStr) self._devices = self._first_element_by_tag_name('devices') self._devices_hash = hash(self._devices.toxml() if self._devices is not None else '') so we parse using the slow minidom _and_ we do toxml() on a subset of the xml tree. Both operations are expensive (and quite memory expensive). Milan is already working on moving from minidom to etree, I think we are on good track here for 4.0. -- Francesco Romani RedHat Engineering Virtualization R & D Phone: 8261328 IRC: fromani
On Thu, Feb 18, 2016 at 12:38 AM, Nir Soffer <nsoffer@redhat.com> wrote:
5. Why do we see xmlrpc at the top of the profile? Is this the cost of mom calls?
There is local connection every ~15 seconds. I am not sure what it is but it maybe responsible for having xmlrpc so high in profile list.
--Apple-Mail=_12636B45-D88C-4B3D-B1A6-38675D0DBE7C Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8
On 18 Feb 2016, at 10:03, Piotr Kliczewski <pkliczew@redhat.com> = wrote: =20 =20 =20 On Thu, Feb 18, 2016 at 12:38 AM, Nir Soffer <nsoffer@redhat.com = <mailto:nsoffer@redhat.com>> wrote: =20 5. Why do we see xmlrpc at the top of the profile? Is this the cost of mom calls? =20 =20 There is local connection every ~15 seconds. I am not sure what it is = but it maybe responsible for having xmlrpc so high in profile list.
I manually glanced over the host with and without mom, yeah=E2=80=A6.not = surprisingly mom is still quite a hog
=20 _______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
--Apple-Mail=_12636B45-D88C-4B3D-B1A6-38675D0DBE7C Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8 <html><head><meta http-equiv=3D"Content-Type" content=3D"text/html = charset=3Dutf-8"></head><body style=3D"word-wrap: break-word; = -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;" = class=3D""><br class=3D""><div><blockquote type=3D"cite" class=3D""><div = class=3D"">On 18 Feb 2016, at 10:03, Piotr Kliczewski <<a = href=3D"mailto:pkliczew@redhat.com" class=3D"">pkliczew@redhat.com</a>>= wrote:</div><br class=3D"Apple-interchange-newline"><div class=3D""><div = dir=3D"ltr" class=3D""><br class=3D""><div class=3D"gmail_extra"><br = class=3D""><div class=3D"gmail_quote">On Thu, Feb 18, 2016 at 12:38 AM, = Nir Soffer <span dir=3D"ltr" class=3D""><<a = href=3D"mailto:nsoffer@redhat.com" target=3D"_blank" = class=3D"">nsoffer@redhat.com</a>></span> wrote:<br class=3D""><div = class=3D""> </div><blockquote class=3D"gmail_quote" style=3D"margin:0= 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"> 5. Why do we see xmlrpc at the top of the profile? Is this the cost<br = class=3D""> of mom calls?<br class=3D""> <br class=3D""></blockquote></div><br class=3D""></div><div = class=3D"gmail_extra">There is local connection every ~15 seconds. I am = not sure what it is but it maybe responsible for<br class=3D""></div><div = class=3D"gmail_extra">having xmlrpc so high in profile list.<br = class=3D""></div></div></div></blockquote><div><br class=3D""></div>I = manually glanced over the host with and without mom, yeah=E2=80=A6.not = surprisingly mom is still quite a hog</div><div><br class=3D""><blockquote= type=3D"cite" class=3D""><div class=3D""><div dir=3D"ltr" class=3D""><div= class=3D"gmail_extra"><br class=3D""></div></div> _______________________________________________<br class=3D"">Devel = mailing list<br class=3D""><a href=3D"mailto:Devel@ovirt.org" = class=3D"">Devel@ovirt.org</a><br = class=3D"">http://lists.ovirt.org/mailman/listinfo/devel</div></blockquote=
</div><br class=3D""></body></html>=
--Apple-Mail=_12636B45-D88C-4B3D-B1A6-38675D0DBE7C--
I would assume the KSM stats collector. And it retrieves mom stats using xml-rpc. It is a constant time cost though, it should not depend on the amount of VMs too much. Martin On Thu, Feb 18, 2016 at 10:03 AM, Piotr Kliczewski <pkliczew@redhat.com> wrote:
On Thu, Feb 18, 2016 at 12:38 AM, Nir Soffer <nsoffer@redhat.com> wrote:
5. Why do we see xmlrpc at the top of the profile? Is this the cost of mom calls?
There is local connection every ~15 seconds. I am not sure what it is but it maybe responsible for having xmlrpc so high in profile list.
_______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
Thanks Nir for this analysis. we currently focusing on bug verification for 3.6, afterwards, we can prioritiez this effort. master branch includes some changes related to these topics? i think it will be better to open a bug for each of the bullets, i'll take care of it. Adding Gil, to mail thread -Eldad On 02/18/2016 01:38 AM, Nir Soffer wrote:
Hi all,
I noticed that Eldad posted profiling result from 144 cores / 144 vms run: See https://bugzilla.redhat.com/attachment.cgi?id=1128028
Looking at the profile bellow:
1. Why _rtnl_link_alloc_cache is so expensive? called only 389 times, but the most expensive call
2. Creating DomainDescriptor seems expensive - is this xml.minidom?
3. guestagent.py:84(filt) is very expensive - we probbaly want to backport 7091bde guestagent: Speed up xml character filtering, can shave about 17% of cpu time in this run.
4. pthread.py function will disapper from the profile if we replace pthreading with cthreading: https://github.com/nirs/cthreading
5. Why do we see xmlrpc at the top of the profile? Is this the cost of mom calls?
Eldad, can you repeat the same test with current master?
Nir
----
Thu Feb 18 00:50:24 2016 vdsm_144vms_1800sec_2.prof
29858105 function calls (34034631 primitive calls) in 1049.574 seconds
Ordered by: internal time List reduced from 2420 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function) 389 64.937 0.167 64.941 0.167 link.py:133(_rtnl_link_alloc_cache) 598438 64.176 0.000 87.888 0.000 domain_descriptor.py:23(DomainDescriptor) 1535528 38.922 0.001 176.177 0.000 guestagent.py:84(filt) 57106 31.545 0.001 31.560 0.001 decoder.py:371(JSONDecoder.raw_decode) 168463 25.961 0.234 119.004 0.001 xmlrpclib.py:721(Marshaller.dump_struct) 4312452 25.095 0.000 77.012 0.000 utf_8.py:15(decode) 7341795 21.934 0.000 41.507 0.000 string.py:511(replace) 28881 18.092 0.001 19.921 0.001 pthread.py:133(Cond.timedwait) 386282 17.509 0.000 17.509 0.000 pthread.py:95(Lock.lock) 46277 16.798 0.000 45.280 0.001 guestagent.py:254(GuestAgent._handleMessage) 48090 16.298 0.000 37.809 0.001 expatbuilder.py:743(ExpatBuilderNS.start_element_handler) 2447266 14.128 0.000 55.635 0.000 httplib.py:331(HTTPResponse) 339514 13.689 0.014 20.629 0.000 password.py:69(_walk) 78549 12.450 0.000 12.635 0.000 minidom.py:344(Attr.__init__) 20117 12.381 0.001 20.961 0.001 vm.py:181(SetLinkAndNetworkError) 14470 12.224 0.001 12.802 0.001 xmlbuilder.py:1(<module>) 21404 11.527 0.001 36.225 0.002 vmstats.py:240(disks) 87612 11.441 0.000 35.701 0.000 sampling.py:59(InterfaceSample.readIfaceStat) 39924 11.323 0.000 23.047 0.001 __init__.py:242(LogRecord.__init__) 14509 10.816 0.001 96.236 0.007 xmlbuilder.py:12(Options)
participants (7)
-
emarcian -
Francesco Romani -
Martin Sivak -
Michal Skrivanek -
Nir Soffer -
Petr Horacek -
Piotr Kliczewski