12:38 a.m.
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)
8:58 a.m.
----- Original Message -----
From: "Nir Soffer" <nsoffer(a)redhat.com>
To: "devel" <devel(a)ovirt.org>, "Francesco Romani"
<fromani(a)redhat.com>, "Eldad Marciano" <emarcian(a)redhat.com>,
"Vinzenz Feenstra" <vfeenstr(a)redhat.com>, "Dan Kenigsberg"
<danken(a)redhat.com>, "Piotr Kliczewski"
<pkliczew(a)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
10:03 a.m.
On Thu, Feb 18, 2016 at 12:38 AM, Nir Soffer <nsoffer(a)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.
11:02 a.m.
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)
11:11 a.m.
--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(a)redhat.com> =
wrote:
=20
=20
=20
On Thu, Feb 18, 2016 at 12:38 AM, Nir Soffer <nsoffer(a)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(a)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(a)redhat.com</a>&gt;=
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(a)redhat.com</a>&gt;</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(a)ovirt.org</a><br =
class=3D"">http://lists.ovirt.org/mailman/listinfo/devel<...
</div><br class=3D""></body></html>=
--Apple-Mail=_12636B45-D88C-4B3D-B1A6-38675D0DBE7C--
1:50 p.m.
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(a)redhat.com> wrote:
On Thu, Feb 18, 2016 at 12:38 AM, Nir Soffer <nsoffer(a)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(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel
2993
days inactive
2994
days old
6 comments
7 participants
participants (7)
-
emarcian -
Francesco Romani -
Martin Sivak -
Michal Skrivanek -
Nir Soffer -
Petr Horacek -
Piotr Kliczewski