4:17 a.m.
Hi Juan,
On Thu, Nov 26, 2015 at 2:15 AM, Juan Hernández <jhernand(a)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(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>>> 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>>> 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