[ovirt-users] [ovirt-devel] ovirt-engine-sdk-python too slow

Juan Hernández jhernand at redhat.com
Mon Nov 30 09:21:03 UTC 2015


On 11/29/2015 09:57 AM, John Hunter wrote:
> So is this a bug or something?
> 
> Can I do something to fix the bug?
> 
> btw, adding Michael Pasternak
> 

It is this bug:

  [RFE][performance] - generate large scale list running to slow.
  https://bugzilla.redhat.com/1221238

We don't have any concrete plans to fix it.

You can try to fix it yourself, but it is in a very fragile part of the
SDK, chances of causing regressions are very high. I'd rather suggest
you to avoid calling the SDK multiple times, or just avoid the SDK and
use some other solution.

> On Thu, Nov 26, 2015 at 7:52 PM, Nir Soffer <nsoffer at redhat.com
> <mailto: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
>     <mailto:zhjwpku at gmail.com>> wrote:
> 
>         Hi Juan,
> 
>         On Thu, Nov 26, 2015 at 2:15 AM, Juan Hernández
>         <jhernand at redhat.com <mailto: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>
>             > <mailto: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>
>             >     <mailto: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>
>             >         <mailto: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>
>             <mailto: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>>
>             >                 > <mailto: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>>
>             >                 >     <mailto: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
> 
> 
> _______________________________________________
> Users mailing list
> Users at ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users
> 


-- 
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.



More information about the Users mailing list