[ovirt-users] [ovirt-devel] ovirt-engine-sdk-python too slow
John Hunter
zhjwpku at gmail.com
Sun Nov 29 08:57:33 UTC 2015
So is this a bug or something?
Can I do something to fix the bug?
btw, adding Michael Pasternak
On Thu, Nov 26, 2015 at 7:52 PM, Nir Soffer <nsoffer at redhat.com> wrote:
> Thanks John, very interesting results.
>
> On Thu, Nov 26, 2015 at 3:17 AM, John Hunter <zhjwpku at gmail.com> wrote:
>
>> 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
>>
>
>
--
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/20151129/0ae071c3/attachment-0001.html>
More information about the Users
mailing list