matplotlib-devel Mailing List for matplotlib

On Tuesday 31 July 2007 02:12:06 pm you wrote:
> Looking at the profile outputs, a couple of things stand out in the new
> version. =A0First, various Traits things are prominent near the top.
pycachegrind is telling me that traits_db is responsible for about 20%,=20
configobj is responsible for about 30%, and the config package another 30%.
> Second, look at the lines for posixpath functions, which are taking
> quite a bit of time. =A0Here are two examples:
>
> =A0 =A0 =A0 5651 =A0 =A00.108 =A0 =A00.000 =A0 =A00.188 =A0 =A00.000 posi=
xpath.py:56(join)
> [...]
> =A0 =A0 =A0 =A0273 =A0 =A00.012 =A0 =A00.000 =A0 =A00.164 =A0 =A00.001 po=
sixpath.py:410(realpath)
>
> If I understand correctly, path.join is being called 5651 times! =A0And
> realpath is being called 273 times! =A0
I think the posix_path stuff is being called most often by python while it=
=20
attempts to locate modules.=20
[...]
> 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.
I agree.
Darren

On 7/31/07, Michael Droettboom <md...@st...> wrote:
> Eric Firing wrote:
> > I don't have a lot of experience with profiling...
> Slightly OT, but I do have a recommendation for anyone doing Python
> profiling. I don't usually get very excited about GUI tools, but
> KCachegrind (Linux only) is very slick and works great with Python.
> It's really handy to be able to "browse" the calltree interactively to
> explore what's going on.
>
> The trick (which is very non-obvious from the documentation), is that
> you use Python's 'hotspot' profiler, then convert that to 'calltree'
> format using hotspot2calltree (included with KCachegrind), and then load
> that with KCachegrind.
>
> Just my two cents for something you may want to try,
Yup. The link I posted earlier is basically a little wrapper that
does all that. I wrote it so you wouldn't have to think :)
I keep it in my path and can profile any python script with
kcachegrind just by running one command. And yes, kcachegrind rocks.
I'm also very much a non-gui person, yet I've found it invaluable for
doing really complex profiling of very large python codes.
Cheers,
f

Eric Firing wrote:
> I don't have a lot of experience with profiling...
Slightly OT, but I do have a recommendation for anyone doing Python 
profiling. I don't usually get very excited about GUI tools, but 
KCachegrind (Linux only) is very slick and works great with Python. 
It's really handy to be able to "browse" the calltree interactively to 
explore what's going on.
The trick (which is very non-obvious from the documentation), is that 
you use Python's 'hotspot' profiler, then convert that to 'calltree' 
format using hotspot2calltree (included with KCachegrind), and then load 
that with KCachegrind.
Just my two cents for something you may want to try,
Mike

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.

On 7/31/07, Darren Dale <dd...@co...> wrote:
> 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.
I'm afraid I can't help with this right now, but you may want to look at
http://amath.colorado.edu/faculty/fperez/python/profiling/
the little code I put in there makes using kcachegrind very easy for
python profiling, and it's really a useful tool for analyzing
profiling info.
Cheers,
f

On Tuesday 31 July 2007 11:08:42 am 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)
sorry, that should say 'time' instead of 'cumulative'
> 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.

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.

Hi Eric,
On Monday 30 July 2007 10:14:22 pm Eric Firing wrote:
> I have not made any matplotlib.conf other than the one that is now being
> installed correctly in mpl-data, and it contains
>
> # display grid on regular or polar axes
> grid = False
> polargrid = True
>
> grep indicates the True value is coming from mplconfig:
>
> config/mplconfig.py: grid = T.Trait(True, mplT.BoolHandler())
>
> config/rcsetup.py: 'axes.grid' : [False, validate_bool]
>
> so it looks like somehow this mplconfig initialization is overriding the
> value in matplotlib.conf.
Ok, sorry for the confusion. There were two problems: 
-The .conf file in mpl-data was not being read. It is fixed in svn 3645.
-The .conf file is not auto-generated by setup.py. This is a more difficult 
problem, so I am not going to work on it unless we decide to adopt the new 
module. In the mean time, the file can be auto-generated by running 
mplconfig.
Darren

Darren Dale wrote:
> On Monday 30 July 2007 6:58:17 pm Eric Firing wrote:
>> Darren,
>>
>> It looks like there is a problem with the grid lines. Although the
>> matplotlib.conf file is specifying linestyle = ':', and False for the
>> axes.grid parameter, everything is coming up with solid lines (see
>> barh_demo.py, for example) by default. It looks like those two keys are
>> not setting their respective rcParams entries.
> 
> barh_demo turns the grid on. I accidentally set the default linestyle to '-' 
> in mplconfig for the grids, thats been fixed.
Darren,
barh_demo turns the grid on for the first plot only, but the grid is 
shown for both. ipython -pylab also plots with a grid by default, and 
shows
In [3]:rcParams['axes.grid']
Out[3]:True
I have not made any matplotlib.conf other than the one that is now being 
installed correctly in mpl-data, and it contains
 # display grid on regular or polar axes
 grid = False
 polargrid = True
grep indicates the True value is coming from mplconfig:
config/mplconfig.py: grid = T.Trait(True, mplT.BoolHandler())
config/rcsetup.py: 'axes.grid' : [False, validate_bool]
so it looks like somehow this mplconfig initialization is overriding the 
value in matplotlib.conf.
Eric