[ovirt-users] [ovirt-devel] ovirt-engine-sdk-python too slow
Nir Soffer
nsoffer at redhat.com
Thu Nov 26 11:52:20 UTC 2015
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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/users/attachments/20151126/05423b4d/attachment-0001.html>
More information about the Users
mailing list