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.