<div dir="ltr">So is this a bug or something?<div><br></div><div>Can I do something to fix the bug?</div><div><br></div><div>btw, adding <span style="color:rgb(46,52,54);font-family:'Source Sans Pro',sans-serif;font-size:14px;line-height:20px">Michael Pasternak</span></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Thu, Nov 26, 2015 at 7:52 PM, Nir Soffer <span dir="ltr"><<a href="mailto:nsoffer@redhat.com" target="_blank">nsoffer@redhat.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Thanks John, very interesting results.</div><div class="HOEnZb"><div class="h5"><div class="gmail_extra"><br><div class="gmail_quote">On Thu, Nov 26, 2015 at 3:17 AM, John Hunter <span dir="ltr"><<a href="mailto:zhjwpku@gmail.com" target="_blank">zhjwpku@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hi Juan,<br><div class="gmail_extra"><br><div class="gmail_quote"><div><div>On Thu, Nov 26, 2015 at 2:15 AM, Juan Hernández <span dir="ltr"><<a href="mailto:jhernand@redhat.com" target="_blank">jhernand@redhat.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div><div>On 11/25/2015 06:45 PM, Nir Soffer wrote:<br>
> $ ./profile-stats -c myscript.prof<br>
><br>
> Wed Nov 25 10:40:11 2015 myscript.prof<br>
><br>
> 7892315 function calls (7891054 primitive calls) in 7.940 seconds<br>
><br>
> Ordered by: internal time<br>
> List reduced from 1518 to 20 due to restriction <20><br>
><br>
> ncalls tottime percall cumtime percall filename:lineno(function)<br>
> 9086 2.693 0.000 6.706 0.001 inspect.py:247(getmembers)<br>
> 1952494 1.394 0.000 1.880 0.000 inspect.py:59(isclass)<br>
> 9092 1.030 0.000 1.030 0.000 {dir}<br>
> 1952642 0.600 0.000 0.600 0.000 {getattr}<br>
> 1972765 0.504 0.000 0.504 0.000 {isinstance}<br>
> 3 0.334 0.111 0.334 0.111 {method 'perform' of<br>
> 'pycurl.Curl' objects}<br>
> 1883918 0.284 0.000 0.284 0.000 {method 'append' of 'list'<br>
> objects}<br>
> 9087 0.221 0.000 0.221 0.000 {method 'sort' of 'list'<br>
> objects}<br>
> 9051 0.172 0.000 6.911 0.001<br>
> reflectionhelper.py:51(isModuleMember)<br>
> 1 0.124 0.124 0.354 0.354 errors.py:17(<module>)<br>
> 1 0.088 0.088 0.230 0.230 params.py:8(<module>)<br>
> 8879 0.070 0.000 6.998 0.001 params.py:367(__setattr__)<br>
> 1 0.047 0.047 5.182 5.182 api.py:23(<module>)<br>
> 1 0.025 0.025 4.743 4.743 brokers.py:22(<module>)<br>
> 1 0.023 0.023 0.030 0.030<br>
> connectionspool.py:17(<module>)<br>
> 1 0.022 0.022 0.053 0.053<br>
> lxml.etree.pyx:1(PyMODINIT_FUNC PyInit_etree(void))<br>
> 118 0.019 0.000 4.684 0.040 params.py:45277(__init__)<br>
> 5 0.015 0.003 0.024 0.005 {built-in method strptime}<br>
> 1 0.012 0.012 0.013 0.013 socket.py:45(<module>)<br>
> 10 0.011 0.001 0.015 0.002 collections.py:288(namedtuple)<br>
><br>
> So it is not the classes, it is the code inspecting them on import.<br>
><br>
<br>
</div></div>The script doesn't contain only the imports, it is also calling the<br>
server, and we know parsing the result is slow, due to the excesive use<br>
of "inspect", as I mentioned before:<br>
<span><br>
[RFE][performance] - generate large scale list running to slow.<br>
</span> <a href="https://bugzilla.redhat.com/show_bug.cgi?id=1221238#c2" rel="noreferrer" target="_blank">https://bugzilla.redhat.com/show_bug.cgi?id=1221238#c2</a><br>
<br>
In the profiling information seems to corresponds to the script before<br>
commenting out the part that lists all the VMs, as it looks like the<br>
constructor of the VM class was called 21 times (you probably have 21 VMs):<br>
<br>
21 0.004 1.308<br>
build/bdist.linux-x86_64/egg/ovirtsdk/infrastructure/brokers.py:29139(VM)<br>
<span><br></span></blockquote></div></div><div>Actually I only have one VM running on the server. </div><div>This time it contains only the import in the script, not calling the server. It shows:</div><div> 21 0.005 1.666 brokers.py:29139(VM)</div><div><br></div><div>$./profile-stats -c myscript_contains_only_import.prof</div><div><br></div><div><div>Thu Nov 26 09:11:59 2015 myscript_contains_only_import.prof</div><div><br></div><div> 5453977 function calls (5452849 primitive calls) in 5.463 seconds</div><div><br></div><div> Ordered by: internal time</div><div> List reduced from 1083 to 20 due to restriction <20></div><span><div><br></div><div> ncalls tottime percall cumtime percall filename:lineno(function)</div></span><div> 7468 2.029 0.000 4.914 0.001 inspect.py:247(getmembers)</div><div> 1348678 0.975 0.000 1.342 0.000 inspect.py:59(isclass)</div><div> 7474 0.737 0.000 0.737 0.000 {dir}</div><div> 1348825 0.433 0.000 0.433 0.000 {getattr}</div><div> 1365970 0.383 0.000 0.383 0.000 {isinstance}</div><div> 1293455 0.211 0.000 0.211 0.000 {method 'append' of 'list' objects}</div><div> 7469 0.163 0.000 0.163 0.000 {method 'sort' of 'list' objects}</div><div> 7434 0.139 0.000 5.082 0.001 reflectionhelper.py:51(isModuleMember)</div><div> 7670 0.061 0.000 5.158 0.001 params.py:367(__setattr__)</div><div> 1 0.043 0.043 5.463 5.463 api.py:23(<module>)</div><div> 1 0.042 0.042 0.139 0.139 errors.py:17(<module>)</div><div> 1 0.027 0.027 5.248 5.248 brokers.py:22(<module>)</div><div> 1 0.026 0.026 0.097 0.097 params.py:8(<module>)</div><div> 118 0.023 0.000 5.187 0.044 params.py:45277(__init__)</div><div> 1 0.018 0.018 0.025 0.025 connectionspool.py:17(<module>)</div><div> 1 0.013 0.013 0.013 0.013 socket.py:45(<module>)</div><div> 10 0.010 0.001 0.013 0.001 collections.py:288(namedtuple)</div><div> 13637 0.009 0.000 0.009 0.000 {method 'lower' of 'str' objects}</div><div> 35 0.009 0.000 0.035 0.001 reflectionhelper.py:28(getClasses)</div><div> 173/27 0.008 0.000 0.019 0.001 sre_parse.py:388(_parse)</div><div><br></div><div><br></div><div> Ordered by: internal time</div><div> List reduced from 1083 to 20 due to restriction <20></div><div><br></div><div>Function was called by...</div><div> ncalls tottime cumtime</div><div>inspect.py:247(getmembers) <- 35 0.009 0.022 reflectionhelper.py:28(getClasses)</div><div> 7433 2.019 4.891 reflectionhelper.py:51(isModuleMember)</div><div>inspect.py:59(isclass) <- 1348678 0.975 1.342 inspect.py:247(getmembers)</div><div>{dir} <- 7468 0.737 0.737 inspect.py:247(getmembers)</div><div> 1 0.000 0.000 os.py:35(_get_exports_list)</div><div> 4 0.000 0.000 ssl.py:111(_import_symbols)</div><div> 1 0.000 0.000 tokenize.py:23(<module>)</div><div>{getattr} <- 1 0.000 0.000 <string>:1(<module>)</div><div> 19 0.000 0.000 abc.py:86(__new__)</div><div> 48 0.000 0.000 abc.py:89(<genexpr>)</div><div> 8 0.000 0.000 abc.py:148(__subclasscheck__)</div><div> 5 0.000 0.000 functools.py:17(update_wrapper)</div><div> 1348678 0.433 0.433 inspect.py:247(getmembers)</div><div> 16 0.000 0.000 socket.py:45(<module>)</div><div> 50 0.000 0.000 ssl.py:111(_import_symbols)</div><div>{isinstance} <- 1 0.000 0.000 __init__.py:49(normalize_encoding)</div><div> 1 0.000 0.000 __init__.py:71(search_function)</div><div> 8 0.000 0.000 abc.py:105(register)</div><div> 10 0.000 0.000 collections.py:288(namedtuple)</div><div> 1348678 0.367 0.367 inspect.py:59(isclass)</div><div> 15576 0.015 0.015 params.py:367(__setattr__)</div><div> 24 0.000 0.000 re.py:230(_compile)</div><div> 60 0.000 0.000 sre_compile.py:546(isstring)</div><div> 1608 0.001 0.001 sre_parse.py:139(__getitem__)</div><div> 4 0.000 0.000 warnings.py:46(filterwarnings)</div><div>{method 'append' of 'list' objects} <- 1288934 0.210 0.210 inspect.py:247(getmembers)</div><div> 8 0.000 0.000 opcode.py:5(<module>)</div><div> 11 0.000 0.000 opcode.py:31(name_op)</div><div> 6 0.000 0.000 opcode.py:35(jrel_op)</div><div> 6 0.000 0.000 opcode.py:39(jabs_op)</div><div> 2294 0.001 0.001 sre_compile.py:64(_compile)</div><div> 575 0.000 0.000 sre_compile.py:228(_compile_charset)</div><div> 416 0.000 0.000 sre_compile.py:256(_optimize_charset)</div><div> 132 0.000 0.000 sre_compile.py:433(_compile_info)</div><div> 24 0.000 0.000 sre_compile.py:552(_code)</div><div> 60 0.000 0.000 sre_parse.py:72(opengroup)</div><div> 485 0.000 0.000 sre_parse.py:147(append)</div><div> 175 0.000 0.000 sre_parse.py:310(_parse_sub)</div><div> 329 0.000 0.000 sre_parse.py:388(_parse)</div><div>{method 'sort' of 'list' objects} <- 1 0.000 0.000 base64.py:3(<module>)</div><div> 7468 0.163 0.163 inspect.py:247(getmembers)</div><div>reflectionhelper.py:51(isModuleMember) <- 7434 0.139 5.082 params.py:367(__setattr__)</div><div>params.py:367(__setattr__) <- 236 0.003 0.206 params.py:6749(__init__)</div><div> 944 0.007 0.571 params.py:6836(__init__)</div><div> 6490 0.051 4.381 params.py:45277(__init__)</div><div>api.py:23(<module>) <- 1 0.043 5.463 myscript_contains_only_import.py:3(<module>)</div><div>errors.py:17(<module>) <- 1 0.042 0.139 api.py:23(<module>)</div><div>brokers.py:22(<module>) <- 1 0.027 5.248 api.py:23(<module>)</div><div>params.py:8(<module>) <- 1 0.026 0.097 errors.py:17(<module>)</div><div>params.py:45277(__init__) <- 1 0.000 0.007 brokers.py:256(Cluster)</div><div> 3 0.000 0.022 brokers.py:988(ClusterGlusterHook)</div><div> 12 0.001 0.090 brokers.py:1228(ClusterGlusterVolume)</div><div> 1 0.000 0.008 brokers.py:1631(ClusterGlusterVolumeGlusterBrick)</div><div> 1 0.000 0.011 brokers.py:3183(DataCenter)</div><div> 1 0.000 0.011 brokers.py:3271(DataCenterCluster)</div><div> 3 0.000 0.038 brokers.py:3999(DataCenterClusterGlusterHook)</div><div> 12 0.002 0.155 brokers.py:4234(DataCenterClusterGlusterVolume)</div><div> 1 0.000 0.013 brokers.py:4594(DataCenterClusterGlusterVolumeGlusterBrick)</div><div> 2 0.002 0.050 brokers.py:9475(DataCenterStorageDomain)</div><div> 3 0.000 0.073 brokers.py:9578(DataCenterStorageDomainDisk)</div><div> 3 0.000 0.079 brokers.py:10455(Disk)</div><div> 2 0.000 0.061 brokers.py:11899(ExternalHostProvider)</div><div> 15 0.003 0.546 brokers.py:13663(Host)</div><div> 2 0.001 0.095 brokers.py:15163(HostNIC)</div><div> 1 0.000 0.045 brokers.py:15634(HostNICs)</div><div> 2 0.000 0.104 brokers.py:18386(Job)</div><div> 1 0.000 0.050 brokers.py:18464(JobStep)</div><div> 2 0.000 0.104 brokers.py:20102(OpenStackImageProvider)</div><div> 1 0.000 0.052 brokers.py:20371(OpenStackImageProviderOpenStackImage)</div><div> 2 0.000 0.106 brokers.py:20641(OpenStackNetworkProvider)</div><div> 2 0.000 0.109 brokers.py:21324(OpenStackVolumeProvider)</div><div> 1 0.000 0.063 brokers.py:23499(StorageConnection)</div><div> 2 0.001 0.125 brokers.py:23706(StorageDomain)</div><div> 3 0.001 0.173 brokers.py:23871(StorageDomainDisk)</div><div> 1 0.000 0.060 brokers.py:24962(StorageDomainImage)</div><div> 2 0.000 0.125 brokers.py:25499(StorageDomainTemplate)</div><div> 2 0.000 0.138 brokers.py:25857(StorageDomainVM)</div><div> 1 0.000 0.076 brokers.py:26550(Template)</div><div> 3 0.001 0.227 brokers.py:26852(TemplateDisk)</div><div> <b> 21 0.005 1.666 brokers.py:29139(VM)</b></div><div> 5 0.001 0.375 brokers.py:30244(VMDisk)</div><div> 2 0.000 0.146 brokers.py:31461(VMNIC)</div><div> 1 0.000 0.088 brokers.py:32478(VMSnapshot)</div><div> 1 0.000 0.096 brokers.py:34300(VmPool)</div><div>connectionspool.py:17(<module>) <- 1 0.018 0.025 api.py:23(<module>)</div><div>socket.py:45(<module>) <- 1 0.013 0.013 urllib.py:23(<module>)</div><div>collections.py:288(namedtuple) <- 6 0.005 0.007 inspect.py:25(<module>)</div><div> 2 0.003 0.003 ssl.py:88(<module>)</div><div> 2 0.002 0.003 urlparse.py:29(<module>)</div><div>{method 'lower' of 'str' objects} <- 6202 0.004 0.004 reflectionhelper.py:28(getClasses)</div><div> 7434 0.006 0.006 reflectionhelper.py:51(isModuleMember)</div><div> 1 0.000 0.000 socket.py:45(<module>)</div><div>reflectionhelper.py:28(getClasses) <- 35 0.009 0.035 reflectionhelper.py:51(isModuleMember)</div><div>sre_parse.py:388(_parse) <- 173/27 0.008 0.019 sre_parse.py:310(_parse_sub)</div></div><div><div><div><br></div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><span>
> Nir<br>
><br>
> On Wed, Nov 25, 2015 at 7:49 AM, John Hunter <<a href="mailto:zhjwpku@gmail.com" target="_blank">zhjwpku@gmail.com</a><br>
</span><span>> <mailto:<a href="mailto:zhjwpku@gmail.com" target="_blank">zhjwpku@gmail.com</a>>> wrote:<br>
><br>
> Hi Nir,<br>
><br>
> Attachment is my script and its profile.<br>
> Thanks a lot about your help!<br>
><br>
> On Wed, Nov 25, 2015 at 5:49 AM, Nir Soffer <<a href="mailto:nsoffer@redhat.com" target="_blank">nsoffer@redhat.com</a><br>
</span><span>> <mailto:<a href="mailto:nsoffer@redhat.com" target="_blank">nsoffer@redhat.com</a>>> wrote:<br>
><br>
> On Tue, Nov 24, 2015 at 3:49 PM, John Hunter <<a href="mailto:zhjwpku@gmail.com" target="_blank">zhjwpku@gmail.com</a><br>
</span><span>> <mailto:<a href="mailto:zhjwpku@gmail.com" target="_blank">zhjwpku@gmail.com</a>>> wrote:<br>
><br>
><br>
><br>
> On Tue, Nov 24, 2015 at 9:15 PM, Juan Hernández<br>
</span><span>> <<a href="mailto:jhernand@redhat.com" target="_blank">jhernand@redhat.com</a> <mailto:<a href="mailto:jhernand@redhat.com" target="_blank">jhernand@redhat.com</a>>> wrote:<br>
><br>
> On 11/24/2015 01:40 PM, John Hunter wrote:<br>
> > Hi,<br>
> ><br>
> > On Tue, Nov 24, 2015 at 5:18 PM, Oved Ourfali <<a href="mailto:oourfali@redhat.com" target="_blank">oourfali@redhat.com</a> <mailto:<a href="mailto:oourfali@redhat.com" target="_blank">oourfali@redhat.com</a>><br>
</span><div><div>> > <mailto:<a href="mailto:oourfali@redhat.com" target="_blank">oourfali@redhat.com</a> <mailto:<a href="mailto:oourfali@redhat.com" target="_blank">oourfali@redhat.com</a>>>> wrote:<br>
> ><br>
> > Hi<br>
> ><br>
> > I discussed it with Juan (cc-ed).<br>
> ><br>
> > There used to be a bug in the JDBC authenticion extension that<br>
> > artificially delayed RESTAPI responses by 5 seconds:<br>
> ><br>
> > brute force prevention login delay should not be applied to successful<br>
> > login requests<br>
> > <a href="https://bugzilla.redhat.com/1255814" rel="noreferrer" target="_blank">https://bugzilla.redhat.com/1255814</a><br>
> ><br>
> > That matches the description of the issue, but in theory it has been<br>
> > fixed. I would suggest him to check that he is using the right version<br>
> > of the extension.<br>
> ><br>
> > I did not use the extension ovirt-engine-extension-aaa-jdbc, and I don't<br>
> > think this bug matches my problem, because even there is only one line<br>
> > in the python script, it still cost like 3 seconds, I don't think this is a<br>
> > reasonable time as when I import other package, it cost almost no time.<br>
> ><br>
> > Can you explain why this import line costs so much time?<br>
> ><br>
><br>
> If you are using 3.6 then you are using<br>
> ovirt-engine-extension-aaa-jdbc,<br>
> as it is enabled by default, but looks like it isn't<br>
> related to your<br>
> problem.<br>
><br>
> That line takes a long time to execute because it has to<br>
> process two<br>
> large Python modules: the "params" module that contains<br>
> a class per each<br>
> type used by the API (393 classes) and the "brokers"<br>
> module that<br>
> contains a class per each resource used by the API (358<br>
> classes). That<br>
> makes a total of 751 classes. In my environment it takes<br>
> 0.9 seconds,<br>
> approx. You may want to use the python profile in your<br>
> environment and<br>
> share the results:<br>
><br>
> $ cat > profile.py <<.<br>
> import cProfile<br>
> cProfile.run("from ovirtsdk.api import API")<br>
> .<br>
><br>
> $ python profile.py<br>
><br>
> I won't be surprised to see this taking those 3 seconds<br>
> in a slower<br>
> environment.<br>
><br>
> But even if this takes those 3 seconds it shouldn't be a<br>
> big problem,<br>
> because you shouldn't be running that "from ... import<br>
> ..." line<br>
> frequently. Your program should do this once only, when<br>
> it starts.<br>
><br>
> Assume that I have two functions to implement, one is to<br>
> list all the vms belong<br>
> to the user, and the other is to retrieve one vm's<br>
> virt-viewer connection file, as<br>
> far as I can see, I have to write two python scripts and<br>
> import the ovirtsdk.api in both<br>
> scripts, each script has to take the 3 seconds :(<br>
><br>
><br>
> No, you have two functions, which can be in the same module, or<br>
> in different modules, depending on how you want to organize your<br>
> code.<br>
><br>
> Python imports are done only once, on the first time you import<br>
> a module anywhere. The module is stored in sys.modules, and the<br>
> next import fetch the module object from sys.modules.<br>
><br>
> Can you share a profile of a simple script importing the Python sdk?<br>
><br>
> Do:<br>
><br>
> python -m cProfile -o myscript.prof myscript.py<br>
><br>
> The profile will be stored in myscript.prof.<br>
><br>
> For viewing the profile, I recommend to use the profile-stats tool:<br>
> <a href="https://github.com/oVirt/vdsm/blob/master/contrib/profile-stats" rel="noreferrer" target="_blank">https://github.com/oVirt/vdsm/blob/master/contrib/profile-stats</a><br>
><br>
><br>
><br>
> How can I run the "from ... import ..." just once ?<br>
><br>
><br>
> ><br>
> > In addition we also know that retrieving large lists of objects with the<br>
> > SDK is slow:<br>
> ><br>
> > [RFE][performance] - generate large scale list running to slow.<br>
> > <a href="https://bugzilla.redhat.com/1221238" rel="noreferrer" target="_blank">https://bugzilla.redhat.com/1221238</a><br>
> ><br>
> > We don't have a solution for that yet.<br>
> ><br>
> > CC-ing Juan in case you have additional questions.<br>
> ><br>
> ><br>
> > On Mon, Nov 23, 2015 at 11:27 AM, John Hunter <<a href="mailto:zhjwpku@gmail.com" target="_blank">zhjwpku@gmail.com</a> <mailto:<a href="mailto:zhjwpku@gmail.com" target="_blank">zhjwpku@gmail.com</a>><br>
</div></div><div><div>> > <mailto:<a href="mailto:zhjwpku@gmail.com" target="_blank">zhjwpku@gmail.com</a> <mailto:<a href="mailto:zhjwpku@gmail.com" target="_blank">zhjwpku@gmail.com</a>>>> wrote:<br>
> ><br>
> > Hi guys,<br>
> ><br>
> > I am using the ovirt-engine-sdk-python to communicate with the<br>
> > ovirt-engine,<br>
> > I am ok to list the vms but the processing time is too long,<br>
> > like 4.5 seconds,<br>
> > and this line:<br>
> > from ovirtsdk.api import API<br>
> > take almost 3 seconds.<br>
> ><br>
> > This seems a little bit longer than I expected it to be, so I am<br>
> > asking is there<br>
> > a quicker way to communicate with the ovirt-engine?<br>
> ><br>
><br>
<br>
--<br>
Dirección Comercial: C/Jose Bardasano Baos, 9, Edif. Gorbea 3, planta<br>
3ºD, 28016 Madrid, Spain<br>
Inscrita en el Reg. Mercantil de Madrid – C.I.F. B82657941 - Red Hat S.L.<br>
</div></div></blockquote></div></div></div><br><br clear="all"><span><div><br></div>-- <br><div><div dir="ltr"><div><div dir="ltr"><div>Best regards<br></div><div>Junwang Zhao</div><div>Department of Computer Science &Technology</div><div>Peking University</div><div>Beijing, 100871, PRC</div></div></div></div></div>
</span></div></div>
</blockquote></div><br></div>
</div></div></blockquote></div><br><br clear="all"><div><br></div>-- <br><div class="gmail_signature"><div dir="ltr"><div><div dir="ltr"><div>Best regards<br></div><div>Junwang Zhao</div><div>Department of Computer Science &Technology</div><div>Peking University</div><div>Beijing, 100871, PRC</div></div></div></div></div>
</div>