Darren,
The two cases you ran have almost identical timing, so the problem is
not in reading matplotlib.conf. Instead, it seems to be in the
initialization of all the machinery, and I suspect that something may
be getting run many times in a loop instead of just once. I used the
profile.py script method to profile the whole simple_plot.py demo
modified to use Agg, with NEWCONFIG True versus False. Attached are the
top 100 lines of the output, sorted by cumulative time, with "new"
meaning NEWCONFIG=True. The execution time of the new version is 3.2
seconds versus 1.8 for the old. (Both are pretty slow for making a
minimal plot from a script.)
Looking at the profile outputs, a couple of things stand out in the new
version. First, various Traits things are prominent near the top.
Second, look at the lines for posixpath functions, which are taking
quite a bit of time. Here are two examples:
5651 0.108 0.000 0.188 0.000 posixpath.py:56(join)
[...]
273 0.012 0.000 0.164 0.001 posixpath.py:410(realpath)
If I understand correctly, path.join is being called 5651 times! And
realpath is being called 273 times! Now, these calls are contributing
only a little to the total time difference between the mpl versions, but
they may be providing clues as to what is wrong. My guess is that there
is a glitch in the program logic that is causing some operations that
should be done once or a few times to be done hundreds or thousands of
times, and this will turn out to be the biggest factor in the slowdown.
If so, then we will still have to see whether a significant slowdown
remains after the glitch is corrected.
I don't have a lot of experience with profiling, but it seems to me that
ordering results by cumulative time is good for finding the major
operations that are slow, whereas ordering by time is good for finding
the lowest-level functions that are holding things up. Ordering by time
shows these as the top two for the new system:
32581/31616 0.152 0.000 0.168 0.000 :0(len)
98 0.132 0.001 0.372 0.004 has_traits.py:558(__init__)
This doesn't mean that the len builtin is too slow, but that it is
getting called a lot of times, and we have to look elsewhere to figure
out how to reduce that, if possible. The second line, however, suggests
to me that even after the glitch problem is solved, we will be stuck
with a distressing startup overhead from using traits. This line is
saying that we are initializing 98 trait instances, and this
initialization alone is taking 0.37 seconds, of which 0.13 seconds is in
the init code, not in functions that it is calling. If you look at the
code for that __init__, you will see that it is huge. It may be that
the traits overhead is small once a program is up and running, but it
certainly looks to me like the startup overhead is a killer if more than
a few traits are to be used.
I would not like to see mpl become a library that is painfully sluggish
to start up; it is already too slow for my liking, with font setup being
a major contributor.
Eric
Darren Dale wrote:
On Monday 30 July 2007 07:10:01 pm Eric Firing wrote:
Darren Dale wrote:
I just committed changes in svn that will allow matplotlib to use the
experimental traited mplconfig module. The traited config object itself
is called mplConfig, but I wrapped it in an object called rcParams to
make it compatible with matplotlib, so we can kick the tires without
extensive changes.
Darren,
There is *major* speed problem. Running "backend_driver.py Template":
0.95 minutes with NEWCONFIG = True
0.51 minutes False
I used the following script in the matplotlib/config directory to profile the
mplconfig module:
def main():
import mplconfig
if __name__=='__main__':
import profile
import pstats
profile.run('main()', 'config.prof')
p = pstats.Stats('config.prof')
p.sort_stats('cumulative').print_stats(55)
I am attaching the results for two different tests. One is loading the default
mpl-data/matplotlib.conf, the other is loading an empty
~/.matplotlib/matplotlib.conf. I haven't done much work with profiling, maybe
others can make some comments about the results.
/home/efiring/programs/py/mpl/tests/matplotlibrc converted to
/home/efiring/programs/py/mpl/tests/matplotlib.conf
276205 function calls (272272 primitive calls) in 3.248 CPU seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.008 0.008 3.248 3.248 simple_plot.py:5(<module>)
1 0.000 0.000 3.248 3.248 :0(execfile)
137/1 0.000 0.000 3.248 3.248 <string>:1(<module>)
1 0.000 0.000 3.248 3.248
profile:0(execfile('simple_plot.py'))
1 0.004 0.004 1.648 1.648 __init__.py:55(<module>)
1 0.000 0.000 1.592 1.592 __init__.py:3(<module>)
1 0.004 0.004 1.576 1.576 mplconfig.py:2(<module>)
1 0.000 0.000 1.224 1.224 pylab.py:1(<module>)
1 0.012 0.012 1.224 1.224 pylab.py:198(<module>)
41/9 0.004 0.000 1.004 0.112 :0(__import__)
1 0.004 0.004 0.708 0.708 axes.py:1(<module>)
1 0.000 0.000 0.660 0.660 mplconfig.py:22(MPLConfig)
330/245 0.004 0.000 0.636 0.003 traits.py:1423(Trait)
330/245 0.000 0.000 0.600 0.002 traits.py:1545(__init__)
330/245 0.028 0.000 0.596 0.002 traits.py:1553(define)
246/135 0.000 0.000 0.576 0.004 traits.py:328(__call__)
1 0.000 0.000 0.560 0.560 axis.py:3(<module>)
203/139 0.012 0.000 0.548 0.004 traits.py:1686(do_list)
397 0.004 0.000 0.544 0.001 re.py:219(_compile)
70 0.004 0.000 0.540 0.008 sre_compile.py:501(compile)
1 0.000 0.000 0.532 0.532 traits.py:1169(File)
1 0.000 0.000 0.532 0.532 mplconfig.py:272(verbose)
144/45 0.000 0.000 0.532 0.012 traits.py:337(trait_factory)
69 0.000 0.000 0.532 0.008 re.py:178(compile)
1 0.000 0.000 0.520 0.520 editors.py:124(FileEditor)
1 0.000 0.000 0.484 0.484 font_manager.py:34(<module>)
1 0.000 0.000 0.484 0.484 font_manager.py:810(__init__)
4 0.004 0.001 0.468 0.117
font_manager.py:186(findSystemFonts)
1 0.000 0.000 0.416 0.416 toolkit.py:49(toolkit)
1 0.000 0.000 0.416 0.416 toolkit.py:19(<module>)
3 0.000 0.000 0.416 0.139 __init__.py:19(<module>)
23 0.000 0.000 0.412 0.018 __init__.py:6(<module>)
1 0.004 0.004 0.408 0.408 pkg_resources.py:14(<module>)
97 0.012 0.000 0.392 0.004 has_traits.py:513(__new__)
98 0.132 0.001 0.376 0.004 has_traits.py:558(__init__)
120 0.016 0.000 0.344 0.003 :0(map)
70 0.004 0.000 0.336 0.005 sre_parse.py:669(parse)
251/70 0.004 0.000 0.324 0.005 sre_parse.py:307(_parse_sub)
349/75 0.072 0.000 0.324 0.004 sre_parse.py:385(_parse)
1 0.000 0.000 0.300 0.300 figure.py:736(savefig)
1 0.000 0.000 0.300 0.300 pylab.py:744(savefig)
1 0.000 0.000 0.300 0.300 backend_agg.py:412(print_figure)
1 0.000 0.000 0.244 0.244 api.py:16(<module>)
1 0.000 0.000 0.236 0.236 cm.py:3(<module>)
1 0.004 0.004 0.228 0.228 api.py:23(<module>)
2 0.000 0.000 0.224 0.112
font_manager.py:172(x11FontDirectory)
78/4 0.044 0.001 0.220 0.055 posixpath.py:271(walk)
1 0.000 0.000 0.212 0.212 backend_agg.py:376(draw)
1 0.000 0.000 0.212 0.212 pkg_resources.py:593(subscribe)
1 0.000 0.000 0.208 0.208 figure.py:578(draw)
55 0.000 0.000 0.208 0.004 pkg_resources.py:2042(activate)
55 0.000 0.000 0.208 0.004 pkg_resources.py:2499(<lambda>)
1 0.000 0.000 0.204 0.204 axes.py:1273(draw)
70 0.000 0.000 0.196 0.003 sre_compile.py:486(_code)
2 0.000 0.000 0.192 0.096 axis.py:567(draw)
5651 0.108 0.000 0.188 0.000 posixpath.py:56(join)
164 0.012 0.000 0.180 0.001 glob.py:9(glob)
1 0.000 0.000 0.176 0.176 backend_agg.py:70(<module>)
1 0.008 0.008 0.176 0.176 mathtext.py:130(<module>)
1 0.000 0.000 0.176 0.176 __init__.py:18(pylab_setup)
1 0.000 0.000 0.168 0.168 trait_db.py:15(<module>)
1 0.000 0.000 0.168 0.168 inspect.py:24(<module>)
1 0.000 0.000 0.168 0.168 colors.py:35(<module>)
530 0.000 0.000 0.168 0.000 glob.py:17(iglob)
1 0.004 0.004 0.164 0.164 tokenize.py:23(<module>)
1 0.000 0.000 0.164 0.164 tconfig.py:53(<module>)
4 0.000 0.000 0.164 0.041 __init__.py:17(<module>)
273 0.012 0.000 0.164 0.001 posixpath.py:410(realpath)
1 0.000 0.000 0.160 0.160 configobj.py:19(<module>)
1 0.000 0.000 0.160 0.160 pyparsing.py:59(<module>)
2 0.032 0.016 0.156 0.078 __init__.py:14(<module>)
17 0.000 0.000 0.156 0.009 axis.py:50(__init__)
30605/29640 0.148 0.000 0.152 0.000 :0(len)
81 0.000 0.000 0.152 0.002 pkg_resources.py:346(add_entry)
190 0.044 0.000 0.144 0.001
pkg_resources.py:1563(find_on_path)
692/70 0.052 0.000 0.144 0.002 sre_compile.py:38(_compile)
153 0.004 0.000 0.144 0.001 pkg_resources.py:1620(_handle_ns)
1 0.000 0.000 0.140 0.140 configobj.py:1027(ConfigObj)
164 0.004 0.000 0.136 0.001 glob.py:48(glob1)
11 0.000 0.000 0.136 0.012 artist.py:709(kwdoc)
4519 0.028 0.000 0.124 0.000 sre_parse.py:207(get)
109 0.056 0.001 0.116 0.001 cbook.py:536(dedent)
1 0.000 0.000 0.116 0.116 handler.py:21(<module>)
5137 0.068 0.000 0.116 0.000 sre_parse.py:188(__next)
1 0.064 0.064 0.112 0.112 _core.py:4(<module>)
23091 0.112 0.000 0.112 0.000 :0(append)
1 0.000 0.000 0.108 0.108 group.py:18(<module>)
54/24 0.000 0.000 0.108 0.005
pkg_resources.py:1641(declare_namespace)
1 0.000 0.000 0.104 0.104 toolkit.py:467(file_editor)
1 0.000 0.000 0.104 0.104 file_editor.py:19(<module>)
15891 0.100 0.000 0.100 0.000 :0(isinstance)
120 0.008 0.000 0.100 0.001 lines.py:385(set_data)
2 0.000 0.000 0.100 0.050 axis.py:713(get_major_ticks)
151 0.004 0.000 0.100 0.001 pkgutil.py:176(find_module)
155356 function calls (152979 primitive calls) in 1.844 CPU seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.004 0.004 1.844 1.844 simple_plot.py:5(<module>)
1 0.000 0.000 1.844 1.844 :0(execfile)
137/1 0.000 0.000 1.844 1.844 <string>:1(<module>)
1 0.000 0.000 1.844 1.844
profile:0(execfile('simple_plot.py'))
1 0.004 0.004 1.368 1.368 pylab.py:1(<module>)
1 0.000 0.000 1.364 1.364 pylab.py:198(<module>)
1 0.016 0.016 0.632 0.632 axes.py:1(<module>)
1 0.008 0.008 0.516 0.516 axis.py:3(<module>)
1 0.000 0.000 0.452 0.452 font_manager.py:34(<module>)
1 0.000 0.000 0.452 0.452 font_manager.py:810(__init__)
4 0.008 0.002 0.436 0.109
font_manager.py:186(findSystemFonts)
1 0.004 0.004 0.424 0.424 cm.py:3(<module>)
4 0.008 0.002 0.348 0.087 __init__.py:17(<module>)
1 0.000 0.000 0.348 0.348 colors.py:35(<module>)
1 0.000 0.000 0.308 0.308 pylab.py:744(savefig)
1 0.000 0.000 0.308 0.308 backend_agg.py:412(print_figure)
1 0.000 0.000 0.308 0.308 figure.py:736(savefig)
155 0.004 0.000 0.300 0.002 re.py:219(_compile)
39 0.004 0.000 0.292 0.007 sre_compile.py:501(compile)
38 0.000 0.000 0.292 0.008 re.py:178(compile)
9 0.000 0.000 0.264 0.029 __init__.py:1(<module>)
1 0.000 0.000 0.220 0.220 backend_agg.py:376(draw)
1 0.000 0.000 0.220 0.220 figure.py:578(draw)
164 0.000 0.000 0.216 0.001 glob.py:9(glob)
530 0.016 0.000 0.216 0.000 glob.py:17(iglob)
1 0.000 0.000 0.216 0.216 axes.py:1273(draw)
2 0.000 0.000 0.208 0.104 axis.py:567(draw)
164 0.000 0.000 0.192 0.001 glob.py:48(glob1)
17 0.000 0.000 0.180 0.011 axis.py:50(__init__)
123/39 0.004 0.000 0.172 0.004 sre_parse.py:307(_parse_sub)
39 0.000 0.000 0.172 0.004 sre_parse.py:669(parse)
2 0.000 0.000 0.172 0.086
font_manager.py:172(x11FontDirectory)
78/4 0.052 0.001 0.172 0.043 posixpath.py:271(walk)
194/44 0.036 0.000 0.164 0.004 sre_parse.py:385(_parse)
1 0.000 0.000 0.164 0.164 backend_agg.py:70(<module>)
1 0.000 0.000 0.164 0.164 __init__.py:18(pylab_setup)
1 0.008 0.008 0.164 0.164 mathtext.py:130(<module>)
7 0.000 0.000 0.164 0.023 :0(__import__)
1 0.000 0.000 0.156 0.156 utils.py:1(<module>)
1 0.000 0.000 0.156 0.156 inspect.py:24(<module>)
1 0.000 0.000 0.156 0.156 pyparsing.py:59(<module>)
120 0.000 0.000 0.156 0.001 lines.py:385(set_data)
120 0.024 0.000 0.156 0.001 lines.py:401(recache)
1 0.000 0.000 0.152 0.152 tokenize.py:23(<module>)
110 0.088 0.001 0.152 0.001 cbook.py:536(dedent)
9 0.000 0.000 0.144 0.016 :0(map)
87 0.016 0.000 0.120 0.001 lines.py:171(__init__)
11 0.000 0.000 0.116 0.011 artist.py:709(kwdoc)
39 0.000 0.000 0.116 0.003 sre_compile.py:486(_code)
17610/16787 0.108 0.000 0.116 0.000 :0(len)
1 0.000 0.000 0.108 0.108 pylab.py:2058(plot)
1 0.004 0.004 0.104 0.104 polynomial.py:3(<module>)
1 0.000 0.000 0.100 0.100 axes.py:444(__init__)
1 0.000 0.000 0.100 0.100 figure.py:506(add_subplot)
7 0.000 0.000 0.100 0.014 pylab.py:816(gca)
1 0.000 0.000 0.100 0.100 pylab.py:883(ishold)
1 0.000 0.000 0.100 0.100 axes.py:5152(__init__)
7 0.000 0.000 0.100 0.014 figure.py:713(gca)
2 0.044 0.022 0.100 0.050 machar.py:50(__init__)
2 0.000 0.000 0.100 0.050 getlimits.py:63(_init)
2 0.000 0.000 0.100 0.050 getlimits.py:36(__new__)
2 0.000 0.000 0.100 0.050 axis.py:713(get_major_ticks)
164 0.048 0.000 0.096 0.001 fnmatch.py:40(filter)
165 0.036 0.000 0.092 0.001 :0(filter)
9 0.004 0.000 0.092 0.010 axis.py:980(_get_tick)
8 0.000 0.000 0.092 0.012 axis.py:1167(_get_tick)
1 0.088 0.088 0.088 0.088 :0(write_png)
4 0.000 0.000 0.088 0.022 axis.py:526(cla)
11 0.012 0.001 0.084 0.008 artist.py:549(pprint_setters)
401/39 0.024 0.000 0.084 0.002 sre_compile.py:38(_compile)
1 0.004 0.004 0.072 0.072 _cm.py:10(<module>)
496 0.016 0.000 0.072 0.000 ma.py:537(__init__)
16695 0.068 0.000 0.068 0.000 :0(append)
3977 0.052 0.000 0.068 0.000 posixpath.py:56(join)
58 0.032 0.001 0.060 0.001 _cm.py:5950(revcmap)
6 0.008 0.001 0.060 0.010 __init__.py:2(<module>)
7112 0.056 0.000 0.056 0.000 glob.py:56(<lambda>)
1 0.000 0.000 0.056 0.056 __init__.py:55(<module>)
1642 0.008 0.000 0.056 0.000 sre_parse.py:207(get)
9 0.000 0.000 0.052 0.006 pyparsing.py:1314(__init__)
496 0.012 0.000 0.052 0.000 ma.py:1312(set_fill_value)
6632 0.052 0.000 0.052 0.000 :0(isinstance)
89 0.032 0.000 0.052 0.001
transforms.py:424(blend_xy_sep_transform)
240 0.008 0.000 0.052 0.000 ma.py:1815(ravel)
10894 0.048 0.000 0.048 0.000 :0(startswith)
1 0.000 0.000 0.048 0.048 axes.py:543(_init_axis)
2 0.000 0.000 0.048 0.024 axis.py:494(__init__)
1985 0.020 0.000 0.048 0.000 sre_parse.py:188(__next)
34 0.000 0.000 0.048 0.001 text.py:876(__init__)
1 0.000 0.000 0.048 0.048 axes.py:718(cla)
2024 0.024 0.000 0.048 0.000 fromnumeric.py:672(any)
278 0.008 0.000 0.044 0.000 artist.py:487(get_valid_values)
10 0.004 0.000 0.044 0.004 pyparsing.py:1434(__init__)
242 0.000 0.000 0.044 0.000 ma.py:2116(asarray)
7265 0.040 0.000 0.040 0.000 :0(match)
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop.
Now Search log events and configuration files using AJAX and a browser.
Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
Matplotlib-devel mailing list
Matplotlib-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/matplotlib-devel
