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 <[email protected]> wrote: > Thanks John, very interesting results. > > On Thu, Nov 26, 2015 at 3:17 AM, John Hunter <[email protected]> wrote: > >> Hi Juan, >> >> On Thu, Nov 26, 2015 at 2:15 AM, Juan Hernández <[email protected]> >> 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 <[email protected] >>> > <mailto:[email protected]>> 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 <[email protected] >>> > <mailto:[email protected]>> wrote: >>> > >>> > On Tue, Nov 24, 2015 at 3:49 PM, John Hunter < >>> [email protected] >>> > <mailto:[email protected]>> wrote: >>> > >>> > >>> > >>> > On Tue, Nov 24, 2015 at 9:15 PM, Juan Hernández >>> > <[email protected] <mailto:[email protected]>> wrote: >>> > >>> > On 11/24/2015 01:40 PM, John Hunter wrote: >>> > > Hi, >>> > > >>> > > On Tue, Nov 24, 2015 at 5:18 PM, Oved Ourfali < >>> [email protected] <mailto:[email protected]> >>> > > <mailto:[email protected] <mailto: >>> [email protected]>>> 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 < >>> [email protected] <mailto:[email protected]> >>> > > <mailto:[email protected] <mailto: >>> [email protected]>>> 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 [email protected] http://lists.ovirt.org/mailman/listinfo/users
