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

Hi Juan, On Thu, Nov 26, 2015 at 2:15 AM, Juan Hernández <jhernand(a)redhat.com&gt; 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(a)gmail.com > > <mailto:zhjwpku@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(a)redhat.com > > <mailto:nsoffer@redhat.com>> wrote: > > > > On Tue, Nov 24, 2015 at 3:49 PM, John Hunter <zhjwpku(a)gmail.com > > <mailto:zhjwpku@gmail.com>> wrote: > > > > > > > > On Tue, Nov 24, 2015 at 9:15 PM, Juan Hernández > > <jhernand(a)redhat.com <mailto:jhernand@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(a)redhat.com <mailto:oourfali@redhat.com> > > > <mailto:oourfali@redhat.com <mailto: > oourfali(a)redhat.com&gt;&gt;&gt; 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(a)gmail.com <mailto:zhjwpku@gmail.com> > > > <mailto:zhjwpku@gmail.com <mailto: > zhjwpku(a)gmail.com&gt;&gt;&gt; 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