[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/devel/attachments/20151129/0ae071c3/attachment-0001.html>


More information about the Devel mailing list