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

Thanks John, very interesting results. On Thu, Nov 26, 2015 at 3:17 AM, John Hunter <zhjwpku(a)gmail.com&gt; wrote: > 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 >