[ovirt-users] [ovirt-devel] ovirt-engine-sdk-python too slow
John Hunter
zhjwpku at gmail.com
Thu Nov 26 01:17:31 UTC 2015
Hi Juan,
On Thu, Nov 26, 2015 at 2:15 AM, Juan Hernández <jhernand at redhat.com> wrote:
> On 11/25/2015 06:45 PM, Nir Soffer wrote:
> > $ ./profile-stats -c myscript.prof
> >
> > Wed Nov 25 10:40:11 2015 myscript.prof
> >
> > 7892315 function calls (7891054 primitive calls) in 7.940
> seconds
> >
> > Ordered by: internal time
> > List reduced from 1518 to 20 due to restriction <20>
> >
> > ncalls tottime percall cumtime percall filename:lineno(function)
> > 9086 2.693 0.000 6.706 0.001 inspect.py:247(getmembers)
> > 1952494 1.394 0.000 1.880 0.000 inspect.py:59(isclass)
> > 9092 1.030 0.000 1.030 0.000 {dir}
> > 1952642 0.600 0.000 0.600 0.000 {getattr}
> > 1972765 0.504 0.000 0.504 0.000 {isinstance}
> > 3 0.334 0.111 0.334 0.111 {method 'perform' of
> > 'pycurl.Curl' objects}
> > 1883918 0.284 0.000 0.284 0.000 {method 'append' of 'list'
> > objects}
> > 9087 0.221 0.000 0.221 0.000 {method 'sort' of 'list'
> > objects}
> > 9051 0.172 0.000 6.911 0.001
> > reflectionhelper.py:51(isModuleMember)
> > 1 0.124 0.124 0.354 0.354 errors.py:17(<module>)
> > 1 0.088 0.088 0.230 0.230 params.py:8(<module>)
> > 8879 0.070 0.000 6.998 0.001 params.py:367(__setattr__)
> > 1 0.047 0.047 5.182 5.182 api.py:23(<module>)
> > 1 0.025 0.025 4.743 4.743 brokers.py:22(<module>)
> > 1 0.023 0.023 0.030 0.030
> > connectionspool.py:17(<module>)
> > 1 0.022 0.022 0.053 0.053
> > lxml.etree.pyx:1(PyMODINIT_FUNC PyInit_etree(void))
> > 118 0.019 0.000 4.684 0.040 params.py:45277(__init__)
> > 5 0.015 0.003 0.024 0.005 {built-in method strptime}
> > 1 0.012 0.012 0.013 0.013 socket.py:45(<module>)
> > 10 0.011 0.001 0.015 0.002
> collections.py:288(namedtuple)
> >
> > So it is not the classes, it is the code inspecting them on import.
> >
>
> The script doesn't contain only the imports, it is also calling the
> server, and we know parsing the result is slow, due to the excesive use
> of "inspect", as I mentioned before:
>
> [RFE][performance] - generate large scale list running to slow.
> https://bugzilla.redhat.com/show_bug.cgi?id=1221238#c2
>
> In the profiling information seems to corresponds to the script before
> commenting out the part that lists all the VMs, as it looks like the
> constructor of the VM class was called 21 times (you probably have 21 VMs):
>
> 21 0.004 1.308
> build/bdist.linux-x86_64/egg/ovirtsdk/infrastructure/brokers.py:29139(VM)
>
> Actually I only have one VM running on the server.
This time it contains only the import in the script, not calling the
server. It shows:
21 0.005 1.666 brokers.py:29139(VM)
$./profile-stats -c myscript_contains_only_import.prof
Thu Nov 26 09:11:59 2015 myscript_contains_only_import.prof
5453977 function calls (5452849 primitive calls) in 5.463 seconds
Ordered by: internal time
List reduced from 1083 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
7468 2.029 0.000 4.914 0.001 inspect.py:247(getmembers)
1348678 0.975 0.000 1.342 0.000 inspect.py:59(isclass)
7474 0.737 0.000 0.737 0.000 {dir}
1348825 0.433 0.000 0.433 0.000 {getattr}
1365970 0.383 0.000 0.383 0.000 {isinstance}
1293455 0.211 0.000 0.211 0.000 {method 'append' of 'list'
objects}
7469 0.163 0.000 0.163 0.000 {method 'sort' of 'list'
objects}
7434 0.139 0.000 5.082 0.001
reflectionhelper.py:51(isModuleMember)
7670 0.061 0.000 5.158 0.001 params.py:367(__setattr__)
1 0.043 0.043 5.463 5.463 api.py:23(<module>)
1 0.042 0.042 0.139 0.139 errors.py:17(<module>)
1 0.027 0.027 5.248 5.248 brokers.py:22(<module>)
1 0.026 0.026 0.097 0.097 params.py:8(<module>)
118 0.023 0.000 5.187 0.044 params.py:45277(__init__)
1 0.018 0.018 0.025 0.025
connectionspool.py:17(<module>)
1 0.013 0.013 0.013 0.013 socket.py:45(<module>)
10 0.010 0.001 0.013 0.001 collections.py:288(namedtuple)
13637 0.009 0.000 0.009 0.000 {method 'lower' of 'str'
objects}
35 0.009 0.000 0.035 0.001
reflectionhelper.py:28(getClasses)
173/27 0.008 0.000 0.019 0.001 sre_parse.py:388(_parse)
Ordered by: internal time
List reduced from 1083 to 20 due to restriction <20>
Function was called by...
ncalls tottime cumtime
inspect.py:247(getmembers) <- 35 0.009 0.022
reflectionhelper.py:28(getClasses)
7433 2.019 4.891
reflectionhelper.py:51(isModuleMember)
inspect.py:59(isclass) <- 1348678 0.975 1.342
inspect.py:247(getmembers)
{dir} <- 7468 0.737 0.737
inspect.py:247(getmembers)
1 0.000 0.000
os.py:35(_get_exports_list)
4 0.000 0.000
ssl.py:111(_import_symbols)
1 0.000 0.000
tokenize.py:23(<module>)
{getattr} <- 1 0.000 0.000
<string>:1(<module>)
19 0.000 0.000
abc.py:86(__new__)
48 0.000 0.000
abc.py:89(<genexpr>)
8 0.000 0.000
abc.py:148(__subclasscheck__)
5 0.000 0.000
functools.py:17(update_wrapper)
1348678 0.433 0.433
inspect.py:247(getmembers)
16 0.000 0.000
socket.py:45(<module>)
50 0.000 0.000
ssl.py:111(_import_symbols)
{isinstance} <- 1 0.000 0.000
__init__.py:49(normalize_encoding)
1 0.000 0.000
__init__.py:71(search_function)
8 0.000 0.000
abc.py:105(register)
10 0.000 0.000
collections.py:288(namedtuple)
1348678 0.367 0.367
inspect.py:59(isclass)
15576 0.015 0.015
params.py:367(__setattr__)
24 0.000 0.000
re.py:230(_compile)
60 0.000 0.000
sre_compile.py:546(isstring)
1608 0.001 0.001
sre_parse.py:139(__getitem__)
4 0.000 0.000
warnings.py:46(filterwarnings)
{method 'append' of 'list' objects} <- 1288934 0.210 0.210
inspect.py:247(getmembers)
8 0.000 0.000
opcode.py:5(<module>)
11 0.000 0.000
opcode.py:31(name_op)
6 0.000 0.000
opcode.py:35(jrel_op)
6 0.000 0.000
opcode.py:39(jabs_op)
2294 0.001 0.001
sre_compile.py:64(_compile)
575 0.000 0.000
sre_compile.py:228(_compile_charset)
416 0.000 0.000
sre_compile.py:256(_optimize_charset)
132 0.000 0.000
sre_compile.py:433(_compile_info)
24 0.000 0.000
sre_compile.py:552(_code)
60 0.000 0.000
sre_parse.py:72(opengroup)
485 0.000 0.000
sre_parse.py:147(append)
175 0.000 0.000
sre_parse.py:310(_parse_sub)
329 0.000 0.000
sre_parse.py:388(_parse)
{method 'sort' of 'list' objects} <- 1 0.000 0.000
base64.py:3(<module>)
7468 0.163 0.163
inspect.py:247(getmembers)
reflectionhelper.py:51(isModuleMember) <- 7434 0.139 5.082
params.py:367(__setattr__)
params.py:367(__setattr__) <- 236 0.003 0.206
params.py:6749(__init__)
944 0.007 0.571
params.py:6836(__init__)
6490 0.051 4.381
params.py:45277(__init__)
api.py:23(<module>) <- 1 0.043 5.463
myscript_contains_only_import.py:3(<module>)
errors.py:17(<module>) <- 1 0.042 0.139
api.py:23(<module>)
brokers.py:22(<module>) <- 1 0.027 5.248
api.py:23(<module>)
params.py:8(<module>) <- 1 0.026 0.097
errors.py:17(<module>)
params.py:45277(__init__) <- 1 0.000 0.007
brokers.py:256(Cluster)
3 0.000 0.022
brokers.py:988(ClusterGlusterHook)
12 0.001 0.090
brokers.py:1228(ClusterGlusterVolume)
1 0.000 0.008
brokers.py:1631(ClusterGlusterVolumeGlusterBrick)
1 0.000 0.011
brokers.py:3183(DataCenter)
1 0.000 0.011
brokers.py:3271(DataCenterCluster)
3 0.000 0.038
brokers.py:3999(DataCenterClusterGlusterHook)
12 0.002 0.155
brokers.py:4234(DataCenterClusterGlusterVolume)
1 0.000 0.013
brokers.py:4594(DataCenterClusterGlusterVolumeGlusterBrick)
2 0.002 0.050
brokers.py:9475(DataCenterStorageDomain)
3 0.000 0.073
brokers.py:9578(DataCenterStorageDomainDisk)
3 0.000 0.079
brokers.py:10455(Disk)
2 0.000 0.061
brokers.py:11899(ExternalHostProvider)
15 0.003 0.546
brokers.py:13663(Host)
2 0.001 0.095
brokers.py:15163(HostNIC)
1 0.000 0.045
brokers.py:15634(HostNICs)
2 0.000 0.104
brokers.py:18386(Job)
1 0.000 0.050
brokers.py:18464(JobStep)
2 0.000 0.104
brokers.py:20102(OpenStackImageProvider)
1 0.000 0.052
brokers.py:20371(OpenStackImageProviderOpenStackImage)
2 0.000 0.106
brokers.py:20641(OpenStackNetworkProvider)
2 0.000 0.109
brokers.py:21324(OpenStackVolumeProvider)
1 0.000 0.063
brokers.py:23499(StorageConnection)
2 0.001 0.125
brokers.py:23706(StorageDomain)
3 0.001 0.173
brokers.py:23871(StorageDomainDisk)
1 0.000 0.060
brokers.py:24962(StorageDomainImage)
2 0.000 0.125
brokers.py:25499(StorageDomainTemplate)
2 0.000 0.138
brokers.py:25857(StorageDomainVM)
1 0.000 0.076
brokers.py:26550(Template)
3 0.001 0.227
brokers.py:26852(TemplateDisk)
* 21 0.005 1.666
brokers.py:29139(VM)*
5 0.001 0.375
brokers.py:30244(VMDisk)
2 0.000 0.146
brokers.py:31461(VMNIC)
1 0.000 0.088
brokers.py:32478(VMSnapshot)
1 0.000 0.096
brokers.py:34300(VmPool)
connectionspool.py:17(<module>) <- 1 0.018 0.025
api.py:23(<module>)
socket.py:45(<module>) <- 1 0.013 0.013
urllib.py:23(<module>)
collections.py:288(namedtuple) <- 6 0.005 0.007
inspect.py:25(<module>)
2 0.003 0.003
ssl.py:88(<module>)
2 0.002 0.003
urlparse.py:29(<module>)
{method 'lower' of 'str' objects} <- 6202 0.004 0.004
reflectionhelper.py:28(getClasses)
7434 0.006 0.006
reflectionhelper.py:51(isModuleMember)
1 0.000 0.000
socket.py:45(<module>)
reflectionhelper.py:28(getClasses) <- 35 0.009 0.035
reflectionhelper.py:51(isModuleMember)
sre_parse.py:388(_parse) <- 173/27 0.008 0.019
sre_parse.py:310(_parse_sub)
> > Nir
> >
> > On Wed, Nov 25, 2015 at 7:49 AM, John Hunter <zhjwpku at gmail.com
> > <mailto:zhjwpku at gmail.com>> wrote:
> >
> > Hi Nir,
> >
> > Attachment is my script and its profile.
> > Thanks a lot about your help!
> >
> > On Wed, Nov 25, 2015 at 5:49 AM, Nir Soffer <nsoffer at redhat.com
> > <mailto:nsoffer at redhat.com>> wrote:
> >
> > On Tue, Nov 24, 2015 at 3:49 PM, John Hunter <zhjwpku at gmail.com
> > <mailto:zhjwpku at gmail.com>> wrote:
> >
> >
> >
> > On Tue, Nov 24, 2015 at 9:15 PM, Juan Hernández
> > <jhernand at redhat.com <mailto:jhernand at redhat.com>> wrote:
> >
> > On 11/24/2015 01:40 PM, John Hunter wrote:
> > > Hi,
> > >
> > > On Tue, Nov 24, 2015 at 5:18 PM, Oved Ourfali <
> oourfali at redhat.com <mailto:oourfali at redhat.com>
> > > <mailto:oourfali at redhat.com <mailto:
> oourfali at redhat.com>>> wrote:
> > >
> > > Hi
> > >
> > > I discussed it with Juan (cc-ed).
> > >
> > > There used to be a bug in the JDBC authenticion
> extension that
> > > artificially delayed RESTAPI responses by 5
> seconds:
> > >
> > > brute force prevention login delay should not be
> applied to successful
> > > login requests
> > > https://bugzilla.redhat.com/1255814
> > >
> > > That matches the description of the issue, but in
> theory it has been
> > > fixed. I would suggest him to check that he is
> using the right version
> > > of the extension.
> > >
> > > I did not use the extension
> ovirt-engine-extension-aaa-jdbc, and I don't
> > > think this bug matches my problem, because even there
> is only one line
> > > in the python script, it still cost like 3 seconds, I
> don't think this is a
> > > reasonable time as when I import other package, it
> cost almost no time.
> > >
> > > Can you explain why this import line costs so much
> time?
> > >
> >
> > If you are using 3.6 then you are using
> > ovirt-engine-extension-aaa-jdbc,
> > as it is enabled by default, but looks like it isn't
> > related to your
> > problem.
> >
> > That line takes a long time to execute because it has to
> > process two
> > large Python modules: the "params" module that contains
> > a class per each
> > type used by the API (393 classes) and the "brokers"
> > module that
> > contains a class per each resource used by the API (358
> > classes). That
> > makes a total of 751 classes. In my environment it takes
> > 0.9 seconds,
> > approx. You may want to use the python profile in your
> > environment and
> > share the results:
> >
> > $ cat > profile.py <<.
> > import cProfile
> > cProfile.run("from ovirtsdk.api import API")
> > .
> >
> > $ python profile.py
> >
> > I won't be surprised to see this taking those 3 seconds
> > in a slower
> > environment.
> >
> > But even if this takes those 3 seconds it shouldn't be a
> > big problem,
> > because you shouldn't be running that "from ... import
> > ..." line
> > frequently. Your program should do this once only, when
> > it starts.
> >
> > Assume that I have two functions to implement, one is to
> > list all the vms belong
> > to the user, and the other is to retrieve one vm's
> > virt-viewer connection file, as
> > far as I can see, I have to write two python scripts and
> > import the ovirtsdk.api in both
> > scripts, each script has to take the 3 seconds :(
> >
> >
> > No, you have two functions, which can be in the same module, or
> > in different modules, depending on how you want to organize your
> > code.
> >
> > Python imports are done only once, on the first time you import
> > a module anywhere. The module is stored in sys.modules, and the
> > next import fetch the module object from sys.modules.
> >
> > Can you share a profile of a simple script importing the Python
> sdk?
> >
> > Do:
> >
> > python -m cProfile -o myscript.prof myscript.py
> >
> > The profile will be stored in myscript.prof.
> >
> > For viewing the profile, I recommend to use the profile-stats
> tool:
> > https://github.com/oVirt/vdsm/blob/master/contrib/profile-stats
> >
> >
> >
> > How can I run the "from ... import ..." just once ?
> >
> >
> > >
> > > In addition we also know that retrieving large
> lists of objects with the
> > > SDK is slow:
> > >
> > > [RFE][performance] - generate large scale list
> running to slow.
> > > https://bugzilla.redhat.com/1221238
> > >
> > > We don't have a solution for that yet.
> > >
> > > CC-ing Juan in case you have additional questions.
> > >
> > >
> > > On Mon, Nov 23, 2015 at 11:27 AM, John Hunter <
> zhjwpku at gmail.com <mailto:zhjwpku at gmail.com>
> > > <mailto:zhjwpku at gmail.com <mailto:
> zhjwpku at gmail.com>>> wrote:
> > >
> > > Hi guys,
> > >
> > > I am using the ovirt-engine-sdk-python to
> communicate with the
> > > ovirt-engine,
> > > I am ok to list the vms but the processing
> time is too long,
> > > like 4.5 seconds,
> > > and this line:
> > > from ovirtsdk.api import API
> > > take almost 3 seconds.
> > >
> > > This seems a little bit longer than I expected
> it to be, so I am
> > > asking is there
> > > a quicker way to communicate with the
> ovirt-engine?
> > >
> >
>
> --
> Dirección Comercial: C/Jose Bardasano Baos, 9, Edif. Gorbea 3, planta
> 3ºD, 28016 Madrid, Spain
> Inscrita en el Reg. Mercantil de Madrid – C.I.F. B82657941 - Red Hat S.L.
>
--
Best regards
Junwang Zhao
Department of Computer Science &Technology
Peking University
Beijing, 100871, PRC
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/users/attachments/20151126/b9938916/attachment-0001.html>
-------------- next part --------------
#!/usr/bin/python
from ovirtsdk.api import API
-------------- next part --------------
A non-text attachment was scrubbed...
Name: myscript_contains_only_import.prof
Type: application/octet-stream
Size: 255961 bytes
Desc: not available
URL: <http://lists.ovirt.org/pipermail/users/attachments/20151126/b9938916/attachment-0001.obj>
More information about the Users
mailing list