speeding up log plots

Fernando sent me some test scripts and profile information which set
me on a path to enhance log plot performance. The biggest hit was
coming from the large number of tick labels which were formatted as
mathtext. mathtext is faster now than it used to be, but it is still
slow. I emailed the pyparsing Paul Mcguire and he's going to try and
take another look for some performance enhancements.

But superscript layout for mathtext is relatively easy, eg $10^{-4}$
and so I special-cased this in the text module using a regex and did
the layout "by hand". I also changed the default behavior of the subs
property in the log tick locator. The value None now means to
autosub. If the number of decades is small, you'll get full subbing
for minor ticks as before. If the number of decades is large, you'll
get no minor ticks. You can override the default by explicitly
setting subs in semilogx and friends.

I also inlined some of the num -> string conversions in backend ps.
These were being done by a function that called another function and
the profiler indicated we were paying a big hit.

There are more big gains to be had -- eg backend ps could implement
the various collection draw methods and the lines module could use
collections for drawing markers. But that is for another day.

For Fernando's test case, I was able to reduce the typical run time
from 1.02s to 0.2s for PNGs and 1.35s to 0.26s for PS . Here are my
notes on the various changes and the gains they brought. With
collections, I think we could halve this again for PS, or at the very
least get this down to agg speeds.

Baseline
  plot: 1.15 s
  png : 1.02 s
  eps : 1.35 s

Skipping layout of empty strings
  plot: 0.8 s
  png : 0.67 s
  eps : 1.02 s

Using dot rather than Matrix
  plot: 0.74 s
  png : 0.62 s
  eps : 0.97 s

Optimizing super script drawing by skipping mathtext parser
  png : 0.46 s
  eps : 0.62 s

Implemented autosubbing to reduce the number of subticks for large
decade ranges
  png : 0.21 s
  eps : 0.36 s

Inline num2str backend ps draw_lines and draw_line
  png : 0.20 s
  eps : 0.26 s

and here is the final profiler output of the newly optimized code

         58247 function calls (58081 primitive calls) in 0.980 CPU seconds

   Ordered by: standard name

   ncalls tottime percall cumtime percall filename:lineno(function)
      3/1 0.000 0.000 0.980 0.980 <string>:1(?)
        1 0.000 0.000 0.000 0.000 ArrayPrinter.py:7(?)
        1 0.000 0.000 0.000 0.000 FFT.py:21(?)
        1 0.000 0.000 0.000 0.000 LinearAlgebra.py:14(LinAlgError)
        1 0.010 0.010 0.010 0.010 LinearAlgebra.py:6(?)
        1 0.000 0.000 0.000 0.000 MLab.py:9(?)
        1 0.010 0.010 0.020 0.020 Matrix.py:1(?)
        1 0.000 0.000 0.000 0.000 Matrix.py:66(Matrix)
      710 0.000 0.000 0.000 0.000 Numeric.py:130(asarray)
      131 0.000 0.000 0.000 0.000 Numeric.py:146(repeat)
        1 0.000 0.000 0.000 0.000 Numeric.py:492(Unpickler)
        1 0.000 0.000 0.000 0.000 Numeric.py:499(Pickler)
      131 0.000 0.000 0.000 0.000 Numeric.py:561(nonzero)
      127 0.010 0.000 0.010 0.000 Numeric.py:593(ones)
        1 0.010 0.010 0.030 0.030 Numeric.py:85(?)
        5 0.000 0.000 0.000 0.000 Precision.py:15(_get_precisions)
        1 0.000 0.000 0.000 0.000 Precision.py:21(_fill_table)
        1 0.000 0.000 0.000 0.000 Precision.py:28(PrecisionError)
       23 0.000 0.000 0.000 0.000 Precision.py:31(_lookup)
        1 0.000 0.000 0.000 0.000 Precision.py:7(?)
        1 0.000 0.000 0.000 0.000 RandomArray.py:1(?)
        1 0.000 0.000 0.000 0.000 RandomArray.py:13(ArgumentError)
        1 0.000 0.000 0.000 0.000 RandomArray.py:16(seed)
        1 0.000 0.000 0.000 0.000 StringIO.py:30(?)
        1 0.000 0.000 0.000 0.000 StringIO.py:38(StringIO)
        1 0.000 0.000 0.000 0.000 UTC.py:1(?)
        1 0.000 0.000 0.000 0.000 UTC.py:5(UTC)
        1 0.000 0.000 0.000 0.000 UserArray.py:1(?)
        1 0.000 0.000 0.000 0.000 UserArray.py:4(UserArray)
        2 0.000 0.000 0.000 0.000 UserDict.py:19(__getitem__)
        9 0.000 0.000 0.000 0.000 UserDict.py:41(has_key)
        1 0.000 0.000 0.000 0.000 __future__.py:48(?)
        1 0.000 0.000 0.000 0.000 __future__.py:66(_Feature)
        3 0.000 0.000 0.000 0.000 __future__.py:67(__init__)
        1 0.000 0.000 0.000 0.000 __init__.py:0(?)
        5 0.000 0.000 0.050 0.010 __init__.py:1(?)
        1 0.000 0.000 0.000 0.000 __init__.py:12(?)
        1 0.000 0.000 0.050 0.050 __init__.py:15(?)
        1 0.000 0.000 0.000 0.000 __init__.py:187(Verbose)
        1 0.000 0.000 0.000 0.000 __init__.py:206(__init__)
        1 0.000 0.000 0.000 0.000 __init__.py:21(?)
        2 0.000 0.000 0.000 0.000 __init__.py:211(set_level)
     2279 0.010 0.000 0.020 0.000 __init__.py:220(report)
        1 0.000 0.000 0.000 0.000 __init__.py:243(wrap)
        4 0.000 0.000 0.000 0.000 __init__.py:253(wrapper)
     2279 0.010 0.000 0.010 0.000 __init__.py:264(ge)
        1 0.000 0.000 0.000 0.000 __init__.py:27(timezone)
        2 0.000 0.000 0.000 0.000 __init__.py:271(get_home)
        4 0.000 0.000 0.000 0.000 __init__.py:290(_get_data_path)
        1 0.010 0.010 0.010 0.010 __init__.py:30(?)
        9 0.000 0.000 0.000 0.000 __init__.py:333(validate_bool)
       12 0.000 0.000 0.000 0.000 __init__.py:341(validate_float)
        1 0.000 0.000 0.000 0.000 __init__.py:347(validate_int)
        1 0.000 0.000 0.000 0.000 __init__.py:353(validate_numerix)
        1 0.000 0.000 0.000 0.000 __init__.py:361(validate_toolbar)
        1 0.000 0.000 0.000 0.000 __init__.py:372(validate_nseq_float)
        1 0.000 0.000 0.000 0.000 __init__.py:373(__init__)
        1 0.000 0.000 0.000 0.000 __init__.py:375(__call__)
       15 0.000 0.000 0.000 0.000 __init__.py:384(validate_color)
      196 0.000 0.000 0.000 0.000 __init__.py:40(dot)
        5 0.000 0.000 0.000 0.000 __init__.py:414(validate_comma_sep_str)
        4 0.000 0.000 0.000 0.000 __init__.py:428(validate_fontsize)
        1 0.000 0.000 0.000 0.000 __init__.py:438(validate_verbose)
        1 0.000 0.000 0.000 0.000 __init__.py:443(validate_verbose_fileo)
        1 0.000 0.000 0.000 0.000 __init__.py:458(validate_verbose_erro)
        4 0.000 0.000 0.000 0.000 __init__.py:48(draw_if_interactive)
        1 0.000 0.000 0.000 0.000 __init__.py:49(show)
        1 0.000 0.000 0.000 0.000 __init__.py:578(matplotlib_fname)
        1 0.000 0.000 0.000 0.000 __init__.py:6(?)
        1 0.010 0.010 0.010 0.010 __init__.py:615(rc_params)
        1 0.000 0.000 0.000 0.000 __init__.py:63(_munge_zone)
        2 0.000 0.000 0.000 0.000 __init__.py:683(rc)
        2 0.000 0.000 0.000 0.000 __init__.py:803(get_backend)
        1 0.000 0.000 0.000 0.000 __init__.py:839(MPLError)
        1 0.000 0.000 0.000 0.000 __init__.py:9(?)
        1 0.000 0.000 0.000 0.000 _contour.py:1(?)
        1 0.000 0.000 0.000 0.000 _image.py:1(?)
        1 0.000 0.000 0.000 0.000 _mathtext_data.py:3(?)
        1 0.000 0.000 0.000 0.000 _nc_imports.py:1(?)
        1 0.000 0.000 0.000 0.000 _nc_imports.py:5(_TypeNamespace)
        1 0.000 0.000 0.000 0.000 _pylab_helpers.py:1(?)
        1 0.000 0.000 0.000 0.000 _pylab_helpers.py:11(get_fig_manager)
        1 0.000 0.000 0.000 0.000 _pylab_helpers.py:37(get_all_fig_managers)
       12 0.000 0.000 0.000 0.000 _pylab_helpers.py:46(get_active)
        1 0.000 0.000 0.000 0.000 _pylab_helpers.py:52(set_active)
        1 0.000 0.000 0.000 0.000 _pylab_helpers.py:6(Gcf)
        1 0.000 0.000 0.000 0.000 _transforms.py:1(?)
        1 0.000 0.000 0.000 0.000 afm.py:257(AFM)
        1 0.000 0.000 0.000 0.000 afm.py:35(?)
        1 0.000 0.000 0.000 0.000 artist.py:1(?)
        2 0.000 0.000 0.000 0.000 artist.py:146(get_label)
        2 0.000 0.000 0.000 0.000 artist.py:148(set_label)
      182 0.000 0.000 0.000 0.000 artist.py:166(update_from)
        1 0.000 0.000 0.000 0.000 artist.py:23(Artist)
      281 0.000 0.000 0.040 0.000 artist.py:30(__init__)
        3 0.000 0.000 0.000 0.000 artist.py:42(is_transform_set)
      233 0.000 0.000 0.000 0.000 artist.py:46(set_transform)
        3 0.000 0.000 0.000 0.000 artist.py:55(get_transform)
      284 0.000 0.000 0.000 0.000 artist.py:66(set_figure)
       46 0.000 0.000 0.000 0.000 artist.py:74(set_clip_box)
      177 0.000 0.000 0.000 0.000 artist.py:90(get_visible)
      468 0.000 0.000 0.000 0.000 artist.py:94(get_clip_on)
        1 0.010 0.010 0.080 0.080 axes.py:1(?)
        1 0.000 0.000 0.000 0.000 axes.py:113(_process_plot_var_args)
        3 0.000 0.000 0.680 0.227 axes.py:1237(draw)
        2 0.000 0.000 0.000 0.000 axes.py:127(__init__)
        2 0.000 0.000 0.000 0.000 axes.py:131(_clear_color_cycle)
        2 0.000 0.000 0.000 0.000 axes.py:146(__call__)
        1 0.000 0.000 0.000 0.000 axes.py:1505(get_ylim)
        2 0.000 0.000 0.000 0.000 axes.py:151(set_lineprops)
        2 0.000 0.000 0.000 0.000 axes.py:1525(grid)
        2 0.000 0.000 0.000 0.000 axes.py:1552(hold)
        1 0.000 0.000 0.000 0.000 axes.py:170(is_filled)
        1 0.000 0.000 0.000 0.000 axes.py:1706(legend)
        2 0.000 0.000 0.000 0.000 axes.py:1771(get_handles)
        1 0.000 0.000 0.000 0.000 axes.py:195(_plot_2_args)
        2 0.000 0.000 0.010 0.005 axes.py:2227(plot)
        1 0.000 0.000 0.000 0.000 axes.py:235(_plot_3_args)
        4 0.000 0.000 0.000 0.000 axes.py:260(_grab_next_args)
        1 0.000 0.000 0.000 0.000 axes.py:2694(semilogy)
        2 0.000 0.000 0.000 0.000 axes.py:2768(_send_xlim_event)
        2 0.000 0.000 0.000 0.000 axes.py:2772(_send_ylim_event)
        2 0.000 0.000 0.000 0.000 axes.py:2777(set_xlim)
        2 0.000 0.000 0.000 0.000 axes.py:2860(set_ylim)
        1 0.000 0.000 0.000 0.000 axes.py:2872(set_yscale)
        4 0.000 0.000 0.000 0.000 axes.py:289(makeValue)
        1 0.010 0.010 0.010 0.010 axes.py:297(Axes)
        2 0.000 0.000 0.000 0.000 axes.py:2971(ishold)
        1 0.000 0.000 0.010 0.010 axes.py:313(__init__)
        1 0.000 0.000 0.000 0.000 axes.py:3299(SubplotBase)
        1 0.000 0.000 0.000 0.000 axes.py:3314(__init__)
        1 0.000 0.000 0.000 0.000 axes.py:3369(Subplot)
        1 0.000 0.000 0.010 0.010 axes.py:3383(__init__)
        1 0.000 0.000 0.000 0.000 axes.py:3389(PolarAxes)
        1 0.000 0.000 0.010 0.010 axes.py:344(_init_axis)
        1 0.000 0.000 0.000 0.000 axes.py:349(set_figure)
        1 0.000 0.000 0.000 0.000 axes.py:3704(PolarSubplot)
        1 0.000 0.000 0.000 0.000 axes.py:375(_set_lim_and_transforms)
        1 0.000 0.000 0.010 0.010 axes.py:408(axhline)
        1 0.000 0.000 0.000 0.000 axes.py:50(_process_plot_format)
        2 0.000 0.000 0.000 0.000 axes.py:592(has_data)
        3 0.000 0.000 0.000 0.000 axes.py:601(_set_artist_props)
        1 0.000 0.000 0.000 0.000 axes.py:608(cla)
        2 0.000 0.000 0.000 0.000 axes.py:681(update_datalim)
        2 0.010 0.005 0.010 0.005 axes.py:689(add_line)
        1 0.000 0.000 0.000 0.000 axes.py:705(_get_verts_in_data_coords)
        2 0.000 0.000 0.000 0.000 axes.py:729(autoscale_view)
       69 0.000 0.000 0.000 0.000 axis.py:125(get_loc)
       69 0.000 0.000 0.160 0.002 axis.py:129(draw)
       69 0.000 0.000 0.000 0.000 axis.py:158(set_label1)
       69 0.000 0.000 0.000 0.000 axis.py:165(set_label2)
      220 0.000 0.000 0.000 0.000 axis.py:173(_set_artist_props)
        1 0.000 0.000 0.000 0.000 axis.py:183(XTick)
       12 0.000 0.000 0.020 0.002 axis.py:189(_get_text1)
       12 0.010 0.001 0.010 0.001 axis.py:215(_get_text2)
        1 0.000 0.000 0.000 0.000 axis.py:23(Tick)
       12 0.000 0.000 0.010 0.001 axis.py:236(_get_tick1line)
       12 0.000 0.000 0.000 0.000 axis.py:251(_get_tick2line)
       12 0.000 0.000 0.000 0.000 axis.py:266(_get_gridline)
       27 0.000 0.000 0.010 0.000 axis.py:282(update_position)
       27 0.000 0.000 0.000 0.000 axis.py:294(get_view_interval)
        1 0.000 0.000 0.060 0.060 axis.py:3(?)
        1 0.000 0.000 0.000 0.000 axis.py:303(YTick)
       32 0.000 0.000 0.000 0.000 axis.py:311(_get_text1)
       32 0.000 0.000 0.000 0.000 axis.py:333(_get_text2)
       32 0.000 0.000 0.020 0.001 axis.py:353(_get_tick1line)
       32 0.000 0.000 0.000 0.000 axis.py:367(_get_tick2line)
       32 0.000 0.000 0.000 0.000 axis.py:381(_get_gridline)
       42 0.000 0.000 0.000 0.000 axis.py:399(update_position)
       42 0.000 0.000 0.000 0.000 axis.py:412(get_view_interval)
        1 0.000 0.000 0.000 0.000 axis.py:421(Ticker)
        1 0.000 0.000 0.000 0.000 axis.py:426(Axis)
        2 0.000 0.000 0.010 0.005 axis.py:436(__init__)
       44 0.000 0.000 0.070 0.002 axis.py:44(__init__)
        4 0.000 0.000 0.010 0.003 axis.py:453(cla)
        6 0.000 0.000 0.000 0.000 axis.py:484(_set_artist_props)
        6 0.010 0.002 0.240 0.040 axis.py:488(draw)
       36 0.000 0.000 0.000 0.000 axis.py:595(_copy_tick_props)
        4 0.000 0.000 0.000 0.000 axis.py:610(get_major_locator)
        6 0.000 0.000 0.040 0.007 axis.py:626(get_major_ticks)
        6 0.000 0.000 0.020 0.003 axis.py:645(get_minor_ticks)
        4 0.000 0.000 0.000 0.000 axis.py:659(grid)
        5 0.000 0.000 0.000 0.000 axis.py:680(set_major_formatter)
        4 0.000 0.000 0.000 0.000 axis.py:689(set_minor_formatter)
        5 0.000 0.000 0.000 0.000 axis.py:699(set_major_locator)
        5 0.000 0.000 0.000 0.000 axis.py:709(set_minor_locator)
        1 0.000 0.000 0.000 0.000 axis.py:760(XAxis)
       12 0.000 0.000 0.040 0.003 axis.py:763(_get_tick)
        1 0.000 0.000 0.000 0.000 axis.py:766(_get_label)
        3 0.000 0.000 0.000 0.000 axis.py:801(_update_label_postion)
       11 0.000 0.000 0.000 0.000 axis.py:848(get_view_interval)
        8 0.000 0.000 0.000 0.000 axis.py:852(get_data_interval)
        1 0.000 0.000 0.000 0.000 axis.py:858(YAxis)
       32 0.000 0.000 0.030 0.001 axis.py:861(_get_tick)
        1 0.000 0.000 0.000 0.000 axis.py:865(_get_label)
        3 0.000 0.000 0.000 0.000 axis.py:902(_update_label_postion)
       14 0.000 0.000 0.000 0.000 axis.py:949(get_view_interval)
       11 0.000 0.000 0.000 0.000 axis.py:953(get_data_interval)
        1 0.000 0.000 0.000 0.000 backend_agg.py:100(__init__)
     1940 0.110 0.000 0.120 0.000 backend_agg.py:140(draw_line)
       78 0.010 0.000 0.020 0.000 backend_agg.py:185(draw_text)
       43 0.000 0.000 0.020 0.000 backend_agg.py:206(get_text_width_height)
       36 0.000 0.000 0.000 0.000 backend_agg.py:223(get_canvas_width_height)
      121 0.020 0.000 0.030 0.000 backend_agg.py:228(_get_agg_font)
       84 0.000 0.000 0.000 0.000 backend_agg.py:249(points_to_pixels)
        1 0.000 0.000 0.000 0.000 backend_agg.py:274(new_figure_manager)
        1 0.000 0.000 0.000 0.000 backend_agg.py:286(FigureCanvasAgg)
        2 0.000 0.000 0.320 0.160 backend_agg.py:297(draw)
        2 0.060 0.030 0.760 0.380 backend_agg.py:326(print_figure)
        1 0.010 0.010 0.020 0.020 backend_agg.py:70(?)
        1 0.000 0.000 0.000 0.000 backend_agg.py:93(RendererAgg)
        1 0.000 0.000 0.000 0.000 backend_bases.py:16(RendererBase)
       84 0.000 0.000 0.000 0.000 backend_bases.py:20(open_group)
       84 0.000 0.000 0.000 0.000 backend_bases.py:26(close_group)
      312 0.000 0.000 0.000 0.000 backend_bases.py:332(new_gc)
        1 0.000 0.000 0.000 0.000 backend_bases.py:339(GraphicsContextBase)
      468 0.000 0.000 0.000 0.000 backend_bases.py:351(__init__)
     1037 0.000 0.000 0.000 0.000 backend_bases.py:385(get_capstyle)
     1037 0.000 0.000 0.000 0.000 backend_bases.py:391(get_clip_rectangle)
     1037 0.000 0.000 0.000 0.000 backend_bases.py:397(get_dashes)
        1 0.000 0.000 0.000 0.000 backend_bases.py:4(?)
     1037 0.000 0.000 0.000 0.000 backend_bases.py:407(get_joinstyle)
     1037 0.000 0.000 0.000 0.000 backend_bases.py:420(get_linewidth)
     1076 0.000 0.000 0.000 0.000 backend_bases.py:426(get_rgb)
       36 0.000 0.000 0.000 0.000 backend_bases.py:43(flipy)
      276 0.000 0.000 0.000 0.000 backend_bases.py:433(set_alpha)
      201 0.000 0.000 0.000 0.000 backend_bases.py:440(set_antialiased)
      201 0.000 0.000 0.000 0.000 backend_bases.py:449(set_capstyle)
      144 0.000 0.000 0.000 0.000 backend_bases.py:458(set_clip_rectangle)
      256 0.000 0.000 0.000 0.000 backend_bases.py:464(set_dashes)
       42 0.000 0.000 0.000 0.000 backend_bases.py:47(points_to_pixels)
      468 0.000 0.000 0.020 0.000 backend_bases.py:472(set_foreground)
       60 0.000 0.000 0.000 0.000 backend_bases.py:493(set_joinstyle)
      393 0.000 0.000 0.000 0.000 backend_bases.py:502(set_linewidth)
      192 0.000 0.000 0.000 0.000 backend_bases.py:508(set_linestyle)
        1 0.000 0.000 0.000 0.000 backend_bases.py:521(Event)
        1 0.000 0.000 0.000 0.000 backend_bases.py:534(LocationEvent)
        1 0.000 0.000 0.000 0.000 backend_bases.py:577(MouseEvent)
        1 0.000 0.000 0.000 0.000 backend_bases.py:623(KeyEvent)
        1 0.000 0.000 0.000 0.000 backend_bases.py:647(FigureCanvasBase)
        2 0.000 0.000 0.000 0.000 backend_bases.py:664(__init__)
        1 0.000 0.000 0.000 0.000 backend_bases.py:739(switch_backends)
        1 0.000 0.000 0.000 0.000 backend_bases.py:751(mpl_connect)
        1 0.000 0.000 0.000 0.000 backend_bases.py:787(FigureManagerBase)
        1 0.000 0.000 0.000 0.000 backend_bases.py:795(__init__)
        1 0.000 0.000 0.000 0.000 backend_bases.py:821(Cursors)
        1 0.000 0.000 0.000 0.000 backend_bases.py:827(NavigationToolbar2)
     1079 0.000 0.000 0.000 0.000 backend_ps.py:103(set_color)
     1037 0.000 0.000 0.000 0.000 backend_ps.py:111(set_linewidth)
     1037 0.000 0.000 0.000 0.000 backend_ps.py:116(set_linejoin)
     1037 0.020 0.000 0.020 0.000 backend_ps.py:121(set_linecap)
     1037 0.010 0.000 0.020 0.000 backend_ps.py:126(set_linedash)
       39 0.000 0.000 0.000 0.000 backend_ps.py:138(set_font)
       41 0.010 0.000 0.010 0.000 backend_ps.py:150(get_text_width_height)
       25 0.000 0.000 0.000 0.000 backend_ps.py:167(flipy)
       80 0.000 0.000 0.000 0.000 backend_ps.py:171(_get_font)
      970 0.020 0.000 0.270 0.000 backend_ps.py:276(draw_line)
       64 0.010 0.000 0.010 0.000 backend_ps.py:283(_draw_lines)
       64 0.000 0.000 0.010 0.000 backend_ps.py:292(draw_lines)
        3 0.000 0.000 0.000 0.000 backend_ps.py:312(draw_polygon)
       39 0.000 0.000 0.010 0.000 backend_ps.py:337(draw_text)
      156 0.000 0.000 0.000 0.000 backend_ps.py:363(new_gc)
     1037 0.100 0.000 0.250 0.000 backend_ps.py:385(_draw_ps)
        1 0.000 0.000 0.000 0.000 backend_ps.py:4(?)
     3947 0.040 0.000 0.100 0.000 backend_ps.py:41(_num_to_str)
        1 0.000 0.000 0.000 0.000 backend_ps.py:420(GraphicsContextPS)
       64 0.000 0.000 0.000 0.000 backend_ps.py:422(set_linestyle)
        1 0.020 0.020 0.020 0.020 backend_ps.py:437(encodeTTFasPS)
      991 0.020 0.000 0.120 0.000 backend_ps.py:50(_nums_to_str)
        1 0.000 0.000 0.000 0.000 backend_ps.py:514(FigureCanvasPS)
        1 0.000 0.000 0.380 0.380 backend_ps.py:520(print_figure)
       39 0.000 0.000 0.000 0.000 backend_ps.py:53(quote_ps_string)
        1 0.000 0.000 0.000 0.000 backend_ps.py:645(FigureManagerPS)
     1036 0.010 0.000 0.010 0.000 backend_ps.py:66(seq_allequal)
        1 0.000 0.000 0.000 0.000 backend_ps.py:83(RendererPS)
        1 0.000 0.000 0.000 0.000 backend_ps.py:89(__init__)
        1 0.000 0.000 0.000 0.000 bisect.py:1(?)
        1 0.000 0.000 0.000 0.000 calendar.py:30(_localized_month)
        2 0.000 0.000 0.000 0.000 calendar.py:31(__init__)
        1 0.000 0.000 0.000 0.000 calendar.py:43(_localized_day)
        2 0.000 0.000 0.000 0.000 calendar.py:44(__init__)
        1 0.000 0.000 0.000 0.000 calendar.py:6(?)
        1 0.000 0.000 0.000 0.000 cbook.py:101(Sorter)
        1 0.000 0.000 0.000 0.000 cbook.py:11(silent_list)
        1 0.000 0.000 0.000 0.000 cbook.py:151(Xlator)
        1 0.000 0.000 0.000 0.000 cbook.py:212(Null)
        1 0.000 0.000 0.000 0.000 cbook.py:236(dict_delall)
        1 0.000 0.000 0.000 0.000 cbook.py:243(RingBuffer)
        1 0.000 0.000 0.000 0.000 cbook.py:249(__Full)
      129 0.000 0.000 0.000 0.000 cbook.py:278(enumerate)
        1 0.000 0.000 0.000 0.000 cbook.py:34(Bunch)
        1 0.010 0.010 0.010 0.010 cbook.py:4(?)
        4 0.000 0.000 0.000 0.000 cbook.py:431(popd)
        1 0.000 0.000 0.000 0.000 cbook.py:457(Stack)
        1 0.000 0.000 0.000 0.000 cbook.py:464(__init__)
       10 0.000 0.000 0.000 0.000 cbook.py:468(__call__)
        2 0.000 0.000 0.000 0.000 cbook.py:484(push)
        3 0.000 0.000 0.000 0.000 cbook.py:503(clear)
        1 0.000 0.000 0.000 0.000 cbook.py:508(bubble)
        8 0.000 0.000 0.000 0.000 cbook.py:531(popall)
      281 0.000 0.000 0.000 0.000 cbook.py:54(iterable)
     4384 0.060 0.000 0.060 0.000 cbook.py:60(is_string_like)
        2 0.000 0.000 0.000 0.000 cbook.py:75(is_scalar)
        3 0.000 0.000 0.000 0.000 cbook.py:78(flatten)
        1 0.000 0.000 0.060 0.060 cm.py:3(?)
        1 0.000 0.000 0.000 0.000 cm.py:398(ScalarMappable)
        1 0.000 0.000 0.000 0.000 collections.py:159(PolyCollection)
        1 0.000 0.000 0.000 0.000 collections.py:21(Collection)
        1 0.000 0.000 0.000 0.000 collections.py:213(RegularPolyCollection)
        1 0.000 0.000 0.000 0.000 collections.py:276(LineCollection)
        1 0.000 0.000 0.000 0.000 collections.py:64(PatchCollection)
        1 0.000 0.000 0.000 0.000 collections.py:9(?)
        1 0.000 0.000 0.060 0.060 colors.py:30(?)
      333 0.010 0.000 0.010 0.000 colors.py:339(hex2color)
        1 0.000 0.000 0.000 0.000 colors.py:345(ColorConverter)
      477 0.010 0.000 0.020 0.000 colors.py:358(to_rgb)
        1 0.000 0.000 0.000 0.000 colors.py:458(Colormap)
        1 0.000 0.000 0.000 0.000 colors.py:469(LinearSegmentedColormap)
       14 0.000 0.000 0.000 0.000 colors.py:478(__init__)
        1 0.000 0.000 0.000 0.000 colors.py:530(normalize)
        2 0.000 0.000 0.000 0.000 copy.py:133(_copy_dict)
      162 0.000 0.000 0.000 0.000 copy.py:315(_reconstruct)
        1 0.000 0.000 0.000 0.000 copy.py:373(_EmptyClass)
        1 0.000 0.000 0.000 0.000 copy.py:49(?)
        1 0.000 0.000 0.000 0.000 copy.py:54(Error)
      164 0.000 0.000 0.000 0.000 copy.py:65(copy)
        2 0.000 0.000 0.000 0.000 copy_reg.py:14(pickle)
        2 0.000 0.000 0.000 0.000 copy_reg.py:27(constructor)
      162 0.000 0.000 0.000 0.000 copy_reg.py:91(__newobj__)
       12 0.000 0.000 0.000 0.000 copy_reg.py:94(_slotnames)
        1 0.000 0.000 0.000 0.000 dates.py:207(DateFormatter)
        1 0.000 0.000 0.000 0.000 dates.py:285(IndexDateFormatter)
        1 0.000 0.000 0.000 0.000 dates.py:308(rrulewrapper)
        1 0.000 0.000 0.000 0.000 dates.py:324(DateLocator)
        1 0.000 0.000 0.000 0.000 dates.py:347(RRuleLocator)
        1 0.000 0.000 0.000 0.000 dates.py:386(YearLocator)
        1 0.000 0.000 0.000 0.000 dates.py:446(MonthLocator)
        1 0.000 0.000 0.000 0.000 dates.py:463(WeekdayLocator)
        1 0.000 0.000 0.000 0.000 dates.py:484(DayLocator)
        1 0.000 0.000 0.000 0.000 dates.py:498(HourLocator)
        1 0.000 0.000 0.000 0.000 dates.py:516(MinuteLocator)
        1 0.000 0.000 0.000 0.000 dates.py:534(SecondLocator)
        1 0.000 0.000 0.000 0.000 dates.py:77(?)
        1 0.000 0.000 0.000 0.000 errors.py:15(DistutilsError)
        1 0.000 0.000 0.000 0.000 errors.py:19(DistutilsModuleError)
        1 0.000 0.000 0.000 0.000 errors.py:24(DistutilsClassError)
        1 0.000 0.000 0.000 0.000 errors.py:31(DistutilsGetoptError)
        1 0.000 0.000 0.000 0.000 errors.py:35(DistutilsArgError)
        1 0.000 0.000 0.000 0.000 errors.py:40(DistutilsFileError)
        1 0.000 0.000 0.000 0.000 errors.py:46(DistutilsOptionError)
        1 0.000 0.000 0.000 0.000 errors.py:55(DistutilsSetupError)
        1 0.000 0.000 0.000 0.000 errors.py:60(DistutilsPlatformError)
        1 0.000 0.000 0.000 0.000 errors.py:66(DistutilsExecError)
        1 0.000 0.000 0.000 0.000 errors.py:71(DistutilsInternalError)
        1 0.000 0.000 0.000 0.000 errors.py:76(DistutilsTemplateError)
        1 0.000 0.000 0.000 0.000 errors.py:81(CCompilerError)
        1 0.000 0.000 0.000 0.000 errors.py:84(PreprocessError)
        1 0.000 0.000 0.000 0.000 errors.py:87(CompileError)
        1 0.000 0.000 0.000 0.000 errors.py:9(?)
        1 0.000 0.000 0.000 0.000 errors.py:90(LibError)
        1 0.000 0.000 0.000 0.000 errors.py:94(LinkError)
        1 0.000 0.000 0.000 0.000 errors.py:98(UnknownFileError)
        1 0.000 0.000 0.000 0.000 figure.py:1(?)
        1 0.000 0.000 0.000 0.000 figure.py:16(Figure)
        1 0.000 0.000 0.000 0.000 figure.py:160(get_size_inches)
        3 0.000 0.000 0.000 0.000 figure.py:163(get_edgecolor)
        3 0.000 0.000 0.000 0.000 figure.py:167(get_facecolor)
        6 0.000 0.000 0.000 0.000 figure.py:171(set_edgecolor)
        6 0.000 0.000 0.000 0.000 figure.py:178(set_facecolor)
        1 0.000 0.000 0.000 0.000 figure.py:18(__init__)
        1 0.000 0.000 0.010 0.010 figure.py:243(add_subplot)
        1 0.000 0.000 0.000 0.000 figure.py:285(clf)
        3 0.000 0.000 0.680 0.227 figure.py:304(draw)
        1 0.000 0.000 0.000 0.000 figure.py:404(_set_artist_props)
        8 0.000 0.000 0.010 0.001 figure.py:416(gca)
        1 0.000 0.000 0.000 0.000 figure.py:424(sca)
        2 0.000 0.000 0.760 0.380 figure.py:435(savefig)
        2 0.000 0.000 0.000 0.000 figure.py:65(set_canvas)
        2 0.000 0.000 0.000 0.000 figure.py:69(hold)
        1 0.000 0.000 0.000 0.000 fnmatch.py:11(?)
       28 0.000 0.000 0.000 0.000 fnmatch.py:40(filter)
        2 0.000 0.000 0.000 0.000 fnmatch.py:72(translate)
        2 0.000 0.000 0.000 0.000 font_manager.py:124(x11FontDirectory)
        4 0.010 0.003 0.040 0.010 font_manager.py:145(findSystemFonts)
        6 0.000 0.000 0.000 0.000 font_manager.py:175(weight_as_number)
        1 0.010 0.010 0.010 0.010 font_manager.py:192(FontKey)
        6 0.000 0.000 0.000 0.000 font_manager.py:197(__init__)
        1 0.000 0.000 0.060 0.060 font_manager.py:34(?)
        6 0.000 0.000 0.000 0.000 font_manager.py:365(add_filename)
        1 0.000 0.000 0.000 0.000 font_manager.py:442(setWeights)
        1 0.000 0.000 0.000 0.000 font_manager.py:489(FontProperties)
      192 0.000 0.000 0.000 0.000 font_manager.py:544(__init__)
      357 0.000 0.000 0.000 0.000 font_manager.py:573(__hash__)
       12 0.000 0.000 0.000 0.000 font_manager.py:583(get_family)
        6 0.000 0.000 0.000 0.000 font_manager.py:594(get_style)
        6 0.000 0.000 0.000 0.000 font_manager.py:599(get_variant)
        6 0.000 0.000 0.000 0.000 font_manager.py:604(get_weight)
        6 0.000 0.000 0.000 0.000 font_manager.py:610(get_stretch)
       28 0.000 0.000 0.000 0.000 font_manager.py:683(set_size)
      275 0.000 0.000 0.000 0.000 font_manager.py:688(get_size_in_points)
      100 0.000 0.000 0.000 0.000 font_manager.py:702(copy)
        1 0.000 0.000 0.000 0.000 font_manager.py:711(ttfdict_to_fnames)
        1 0.000 0.000 0.000 0.000 font_manager.py:723(FontManager)
        1 0.010 0.010 0.050 0.050 font_manager.py:734(__init__)
      192 0.000 0.000 0.000 0.000 font_manager.py:811(get_default_size)
        6 0.000 0.000 0.010 0.002 font_manager.py:830(findfont)
        1 0.000 0.000 0.000 0.000 glob.py:1(?)
       30 0.020 0.001 0.030 0.001 glob.py:42(glob1)
     4092 0.010 0.000 0.010 0.000 glob.py:49(<lambda>)
       90 0.000 0.000 0.000 0.000 glob.py:55(has_magic)
       30 0.000 0.000 0.030 0.001 glob.py:9(glob)
        1 0.000 0.000 0.000 0.000 image.py:18(AxesImage)
        1 0.000 0.000 0.000 0.000 image.py:282(FigureImage)
        1 0.000 0.000 0.000 0.000 image.py:5(?)
        5 0.000 0.000 0.000 0.000 legend.py:160(_set_artist_props)
        3 0.000 0.000 0.000 0.000 legend.py:164(_approx_text_height)
        3 0.000 0.000 0.040 0.013 legend.py:168(draw)
        3 0.000 0.000 0.000 0.000 legend.py:191(_get_handle_text_bbox)
        1 0.000 0.000 0.000 0.000 legend.py:208(_get_handles)
        1 0.000 0.000 0.000 0.000 legend.py:22(?)
        1 0.000 0.000 0.000 0.000 legend.py:267(_get_texts)
        3 0.000 0.000 0.000 0.000 legend.py:294(_offset)
        3 0.000 0.000 0.020 0.007 legend.py:312(_update_positions)
        6 0.000 0.000 0.020 0.003 legend.py:316(get_tbounds)
        1 0.000 0.000 0.000 0.000 legend.py:40(Legend)
        1 0.000 0.000 0.000 0.000 legend.py:81(__init__)
        6 0.000 0.000 0.000 0.000 lines.py:146(get_window_extent)
      355 0.000 0.000 0.000 0.000 lines.py:168(set_data)
        2 0.000 0.000 0.000 0.000 lines.py:201(set_data_clipping)
      198 0.000 0.000 0.010 0.000 lines.py:215(_get_numeric_clipped_data_in_range)
      192 0.030 0.000 0.490 0.003 lines.py:250(draw)
        2 0.000 0.000 0.000 0.000 lines.py:293(get_markersize)
        8 0.000 0.000 0.000 0.000 lines.py:294(get_xdata)
        8 0.000 0.000 0.000 0.000 lines.py:295(get_ydata)
        1 0.000 0.000 0.000 0.000 lines.py:35(Line2D)
        1 0.000 0.000 0.000 0.000 lines.py:360(set_color)
        1 0.000 0.000 0.000 0.000 lines.py:368(set_linewidth)
      136 0.000 0.000 0.000 0.000 lines.py:385(set_marker)
        1 0.000 0.000 0.000 0.000 lines.py:4(?)
        2 0.000 0.000 0.000 0.000 lines.py:419(set_markersize)
       81 0.010 0.000 0.010 0.000 lines.py:427(set_xdata)
      132 0.000 0.000 0.000 0.000 lines.py:438(set_ydata)
       66 0.000 0.000 0.000 0.000 lines.py:487(_draw_nothing)
      132 0.010 0.000 0.020 0.000 lines.py:501(_draw_solid)
       60 0.010 0.000 0.010 0.000 lines.py:525(_draw_dotted)
       39 0.000 0.000 0.010 0.000 lines.py:689(_draw_tickleft)
       39 0.000 0.000 0.000 0.000 lines.py:694(_draw_tickright)
       21 0.010 0.000 0.010 0.000 lines.py:700(_draw_tickup)
       21 0.000 0.000 0.010 0.000 lines.py:706(_draw_tickdown)
        6 0.020 0.003 0.390 0.065 lines.py:711(_draw_plus)
      136 0.000 0.000 0.030 0.000 lines.py:75(__init__)
      110 0.000 0.000 0.000 0.000 lines.py:759(update_from)
        1 0.000 0.000 0.000 0.000 lines.py:799(set_lw)
        1 0.000 0.000 0.010 0.010 mathtext.py:141(?)
        1 0.000 0.000 0.000 0.000 mathtext.py:175(Fonts)
        1 0.000 0.000 0.000 0.000 mathtext.py:211(DummyFonts)
        1 0.000 0.000 0.000 0.000 mathtext.py:226(BakomaTrueTypeFonts)
        1 0.000 0.000 0.000 0.000 mathtext.py:334(BakomaPSFonts)
        1 0.000 0.000 0.000 0.000 mathtext.py:434(Element)
        1 0.000 0.000 0.000 0.000 mathtext.py:554(SpaceElement)
        1 0.000 0.000 0.000 0.000 mathtext.py:597(SymbolElement)
        1 0.000 0.000 0.000 0.000 mathtext.py:654(GroupElement)
        1 0.000 0.000 0.000 0.000 mathtext.py:719(ExpressionElement)
        1 0.000 0.000 0.000 0.000 mathtext.py:728(Handler)
        1 0.000 0.000 0.000 0.000 mlab.py:55(?)
        1 0.000 0.000 0.000 0.000 mlab.py:85(linspace)
        1 0.000 0.000 0.000 0.000 numeric_version.py:1(?)
        1 0.000 0.000 0.000 0.000 patches.py:1(?)
        1 0.000 0.000 0.000 0.000 patches.py:10(Patch)
        9 0.000 0.000 0.000 0.000 patches.py:115(draw)
        1 0.000 0.000 0.000 0.000 patches.py:184(Shadow)
        3 0.000 0.000 0.000 0.000 patches.py:19(__init__)
        1 0.000 0.000 0.000 0.000 patches.py:222(Rectangle)
        3 0.000 0.000 0.000 0.000 patches.py:229(__init__)
        9 0.000 0.000 0.000 0.000 patches.py:245(get_verts)
        3 0.000 0.000 0.000 0.000 patches.py:254(get_x)
        3 0.000 0.000 0.000 0.000 patches.py:258(get_y)
        3 0.000 0.000 0.000 0.000 patches.py:270(set_x)
        3 0.000 0.000 0.000 0.000 patches.py:278(set_y)
        3 0.000 0.000 0.000 0.000 patches.py:302(set_bounds)
        1 0.000 0.000 0.000 0.000 patches.py:317(RegularPolygon)
        1 0.000 0.000 0.000 0.000 patches.py:347(Polygon)
        1 0.000 0.000 0.000 0.000 patches.py:359(Wedge)
        1 0.000 0.000 0.000 0.000 patches.py:381(Circle)
        3 0.000 0.000 0.000 0.000 patches.py:60(get_edgecolor)
        3 0.000 0.000 0.000 0.000 patches.py:63(get_facecolor)
        6 0.000 0.000 0.000 0.000 patches.py:77(set_edgecolor)
        6 0.000 0.000 0.000 0.000 patches.py:85(set_facecolor)
        1 0.000 0.000 0.000 0.000 patches.py:93(set_linewidth)
        1 0.000 0.000 0.000 0.000 pickle.py:1273(_EmptyClass)
        1 0.000 0.000 0.000 0.000 pickle.py:172(Pickler)
        1 0.010 0.010 0.010 0.010 pickle.py:25(?)
        1 0.000 0.000 0.000 0.000 pickle.py:59(PickleError)
        1 0.000 0.000 0.000 0.000 pickle.py:63(PicklingError)
        1 0.000 0.000 0.000 0.000 pickle.py:70(UnpicklingError)
        1 0.000 0.000 0.000 0.000 pickle.py:83(_Stop)
        1 0.000 0.000 0.000 0.000 pickle.py:841(Unpickler)
        1 0.000 0.000 0.000 0.000 posixpath.py:117(dirname)
      192 0.000 0.000 0.000 0.000 posixpath.py:171(exists)
        4 0.000 0.000 0.000 0.000 posixpath.py:184(isdir)
        3 0.000 0.000 0.000 0.000 posixpath.py:197(isfile)
      146 0.000 0.000 0.000 0.000 posixpath.py:366(normpath)
       28 0.000 0.000 0.000 0.000 posixpath.py:39(normcase)
      144 0.000 0.000 0.000 0.000 posixpath.py:393(abspath)
      144 0.000 0.000 0.000 0.000 posixpath.py:47(isabs)
      181 0.000 0.000 0.000 0.000 posixpath.py:56(join)
       31 0.000 0.000 0.000 0.000 posixpath.py:74(split)
        3 0.000 0.000 0.000 0.000 posixpath.py:89(splitext)
        1 0.000 0.000 0.980 0.980 profile:0(execfile('testlog.py'))
        0 0.000 0.000 profile:0(profiler)
        1 0.000 0.000 0.200 0.200 pylab.py:1(?)
        1 0.000 0.000 0.000 0.000 pylab.py:1038(_ObjectInspector)
        1 0.000 0.000 0.010 0.010 pylab.py:1676(axhline)
        1 0.010 0.010 0.170 0.170 pylab.py:184(?)
        1 0.000 0.000 0.010 0.010 pylab.py:2204(semilogy)
        1 0.000 0.000 0.000 0.000 pylab.py:2349(grid)
        1 0.000 0.000 0.000 0.000 pylab.py:2362(legend)
        2 0.000 0.000 0.760 0.380 pylab.py:763(savefig)
        1 0.000 0.000 0.000 0.000 pylab.py:773(figure)
        8 0.000 0.000 0.010 0.001 pylab.py:834(gca)
       12 0.000 0.000 0.000 0.000 pylab.py:853(gcf)
        2 0.000 0.000 0.000 0.000 pylab.py:906(hold)
        2 0.000 0.000 0.010 0.005 pylab.py:921(ishold)
        1 0.000 0.000 0.000 0.000 pylab.py:938(load)
        2 0.000 0.000 0.000 0.000 pylab.py:993(rc)
        1 0.000 0.000 0.000 0.000 pyparsing.py:100(RecursiveGrammarException)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1004(StringStart)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1022(StringEnd)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1039(ParseExpression)
      103 0.000 0.000 0.000 0.000 pyparsing.py:1041(__init__)
    67/11 0.000 0.000 0.000 0.000 pyparsing.py:1058(leaveWhitespace)
        1 0.000 0.000 0.000 0.000 pyparsing.py:108(ParseResults)
     19/5 0.000 0.000 0.000 0.000 pyparsing.py:1087(streamline)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1127(And)
       40 0.000 0.000 0.000 0.000 pyparsing.py:1132(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1173(Or)
       15 0.000 0.000 0.000 0.000 pyparsing.py:1178(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1230(MatchFirst)
       48 0.000 0.000 0.000 0.000 pyparsing.py:1235(__init__)
      2/1 0.000 0.000 0.000 0.000 pyparsing.py:1269(__str__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1284(ParseElementEnhance)
       47 0.000 0.000 0.000 0.000 pyparsing.py:1286(__init__)
    28/12 0.000 0.000 0.000 0.000 pyparsing.py:1304(leaveWhitespace)
     15/5 0.000 0.000 0.000 0.000 pyparsing.py:1323(streamline)
        2 0.000 0.000 0.000 0.000 pyparsing.py:1342(__str__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1353(NotAny)
        5 0.000 0.000 0.000 0.000 pyparsing.py:1359(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1390(ZeroOrMore)
        5 0.000 0.000 0.000 0.000 pyparsing.py:1392(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1427(OneOrMore)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1460(Optional)
        9 0.000 0.000 0.000 0.000 pyparsing.py:1465(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1481(__str__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1491(SkipTo)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1531(Forward)
        4 0.000 0.000 0.000 0.000 pyparsing.py:1536(__init__)
        4 0.000 0.000 0.000 0.000 pyparsing.py:1539(__lshift__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1576(_ForwardNoRecurse)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1580(TokenConverter)
       21 0.000 0.000 0.000 0.000 pyparsing.py:1582(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1586(Upcase)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1592(Combine)
       10 0.000 0.000 0.000 0.000 pyparsing.py:1597(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1616(Group)
        8 0.000 0.000 0.000 0.000 pyparsing.py:1618(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1625(Dict)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1652(Suppress)
        1 0.000 0.000 0.000 0.000 pyparsing.py:1663(delimitedList)
        1 0.000 0.000 0.000 0.000 pyparsing.py:27(?)
        1 0.000 0.000 0.000 0.000 pyparsing.py:346(ParserElement)
      230 0.000 0.000 0.000 0.000 pyparsing.py:348(__init__)
       19 0.000 0.000 0.000 0.000 pyparsing.py:365(setName)
       10 0.000 0.000 0.000 0.000 pyparsing.py:383(setParseAction)
       40 0.000 0.000 0.000 0.000 pyparsing.py:548(__add__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:554(__radd__)
       48 0.000 0.000 0.000 0.000 pyparsing.py:560(__or__)
       15 0.000 0.000 0.000 0.000 pyparsing.py:572(__xor__)
        4 0.000 0.000 0.000 0.000 pyparsing.py:584(__invert__)
        2 0.000 0.000 0.000 0.000 pyparsing.py:588(suppress)
       81 0.000 0.000 0.000 0.000 pyparsing.py:594(leaveWhitespace)
       20 0.000 0.000 0.000 0.000 pyparsing.py:622(__str__)
       58 0.000 0.000 0.000 0.000 pyparsing.py:628(streamline)
        1 0.000 0.000 0.000 0.000 pyparsing.py:654(Token)
       80 0.000 0.000 0.000 0.000 pyparsing.py:656(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:660(setName)
        1 0.000 0.000 0.000 0.000 pyparsing.py:667(Empty)
        1 0.000 0.000 0.000 0.000 pyparsing.py:669(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:676(Literal)
       65 0.010 0.000 0.010 0.000 pyparsing.py:678(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:70(ParseException)
        1 0.000 0.000 0.000 0.000 pyparsing.py:707(CaselessLiteral)
        1 0.000 0.000 0.000 0.000 pyparsing.py:730(Word)
        8 0.000 0.000 0.000 0.000 pyparsing.py:737(__init__)
       85 0.000 0.000 0.000 0.000 pyparsing.py:75(__init__)
        8 0.000 0.000 0.000 0.000 pyparsing.py:785(__str__)
       10 0.000 0.000 0.000 0.000 pyparsing.py:794(charsAsStr)
        1 0.000 0.000 0.000 0.000 pyparsing.py:808(CharsNotIn)
        5 0.000 0.000 0.000 0.000 pyparsing.py:813(__init__)
        5 0.000 0.000 0.000 0.000 pyparsing.py:860(__str__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:874(White)
        1 0.000 0.000 0.000 0.000 pyparsing.py:931(PositionToken)
        1 0.000 0.000 0.000 0.000 pyparsing.py:932(__init__)
        1 0.000 0.000 0.000 0.000 pyparsing.py:937(GoToColumn)
        1 0.000 0.000 0.000 0.000 pyparsing.py:960(LineStart)
        1 0.000 0.000 0.000 0.000 pyparsing.py:983(LineEnd)
        1 0.000 0.000 0.000 0.000 pyparsing.py:985(__init__)
        1 0.000 0.000 0.000 0.000 random.py:40(?)
        1 0.000 0.000 0.000 0.000 random.py:624(WichmannHill)
        1 0.000 0.000 0.000 0.000 random.py:64(Random)
        1 0.000 0.000 0.000 0.000 random.py:81(__init__)
        1 0.000 0.000 0.000 0.000 random.py:90(seed)
        1 0.000 0.000 0.010 0.010 re.py:1(?)
        1 0.000 0.000 0.000 0.000 relativedelta.py:15(weekday)
        7 0.000 0.000 0.000 0.000 relativedelta.py:18(__init__)
        1 0.000 0.000 0.000 0.000 relativedelta.py:45(relativedelta)
        1 0.000 0.000 0.000 0.000 relativedelta.py:6(?)
        1 0.000 0.000 0.000 0.000 rrule.py:224(rrule)
        1 0.000 0.000 0.000 0.000 rrule.py:50(weekday)
        7 0.000 0.000 0.000 0.000 rrule.py:53(__init__)
        1 0.000 0.000 0.000 0.000 rrule.py:6(?)
        1 0.000 0.000 0.000 0.000 rrule.py:613(_iterinfo)
        1 0.000 0.000 0.000 0.000 rrule.py:80(rrulebase)
        1 0.000 0.000 0.000 0.000 rrule.py:807(rruleset)
        1 0.000 0.000 0.000 0.000 rrule.py:809(_genitem)
        1 0.000 0.000 0.000 0.000 rrule.py:876(_rrulestr)
        1 0.000 0.000 0.000 0.000 sets.py:393(ImmutableSet)
        1 0.000 0.000 0.000 0.000 sets.py:41(?)
        1 0.000 0.000 0.000 0.000 sets.py:418(Set)
        1 0.000 0.000 0.000 0.000 sets.py:564(_TemporarilyImmutableSet)
        1 0.000 0.000 0.000 0.000 sets.py:83(BaseSet)
      116 0.000 0.000 0.000 0.000 sre.py:129(match)
       39 0.000 0.000 0.000 0.000 sre.py:139(sub)
        8 0.000 0.000 0.010 0.001 sre.py:177(compile)
        8 0.000 0.000 0.000 0.000 sre.py:190(escape)
        8 0.000 0.000 0.000 0.000 sre.py:212(_join)
      163 0.000 0.000 0.010 0.000 sre.py:216(_compile)
        1 0.000 0.000 0.000 0.000 sre.py:277(Scanner)
        1 0.010 0.010 0.010 0.010 sre.py:94(?)
        1 0.000 0.000 0.000 0.000 sre_compile.py:11(?)
       17 0.000 0.000 0.000 0.000 sre_compile.py:151(_compile_charset)
       13 0.000 0.000 0.000 0.000 sre_compile.py:155(<lambda>)
       17 0.000 0.000 0.000 0.000 sre_compile.py:180(_optimize_charset)
        6 0.000 0.000 0.000 0.000 sre_compile.py:229(_mk_bitmap)
    35/11 0.000 0.000 0.000 0.000 sre_compile.py:24(_compile)
       13 0.000 0.000 0.000 0.000 sre_compile.py:322(_simple)
       11 0.000 0.000 0.000 0.000 sre_compile.py:329(_compile_info)
       71 0.000 0.000 0.000 0.000 sre_compile.py:42(<lambda>)
       21 0.000 0.000 0.000 0.000 sre_compile.py:438(isstring)
       11 0.000 0.000 0.000 0.000 sre_compile.py:444(_code)
       11 0.000 0.000 0.010 0.001 sre_compile.py:459(compile)
        1 0.000 0.000 0.000 0.000 sre_constants.py:12(?)
        3 0.000 0.000 0.000 0.000 sre_constants.py:146(makedict)
        1 0.000 0.000 0.000 0.000 sre_constants.py:25(error)
        1 0.000 0.000 0.000 0.000 sre_parse.py:11(?)
       62 0.000 0.000 0.000 0.000 sre_parse.py:133(__len__)
      100 0.000 0.000 0.000 0.000 sre_parse.py:137(__getitem__)
       13 0.000 0.000 0.000 0.000 sre_parse.py:139(__setitem__)
       13 0.000 0.000 0.000 0.000 sre_parse.py:141(__getslice__)
       57 0.000 0.000 0.000 0.000 sre_parse.py:145(append)
    48/24 0.000 0.000 0.000 0.000 sre_parse.py:147(getwidth)
        1 0.000 0.000 0.000 0.000 sre_parse.py:182(Tokenizer)
       11 0.000 0.000 0.000 0.000 sre_parse.py:183(__init__)
      199 0.000 0.000 0.000 0.000 sre_parse.py:187(__next)
      106 0.010 0.000 0.010 0.000 sre_parse.py:200(match)
      155 0.000 0.000 0.000 0.000 sre_parse.py:206(get)
        1 0.000 0.000 0.000 0.000 sre_parse.py:210(tell)
        1 0.000 0.000 0.000 0.000 sre_parse.py:212(seek)
        1 0.000 0.000 0.000 0.000 sre_parse.py:240(_class_escape)
       13 0.000 0.000 0.000 0.000 sre_parse.py:269(_escape)
    20/11 0.000 0.000 0.010 0.001 sre_parse.py:312(_parse_sub)
    21/11 0.000 0.000 0.010 0.001 sre_parse.py:367(_parse)
       11 0.000 0.000 0.010 0.001 sre_parse.py:614(parse)
        1 0.000 0.000 0.000 0.000 sre_parse.py:73(Pattern)
       11 0.000 0.000 0.000 0.000 sre_parse.py:75(__init__)
        9 0.000 0.000 0.000 0.000 sre_parse.py:80(opengroup)
        9 0.000 0.000 0.000 0.000 sre_parse.py:91(closegroup)
        1 0.000 0.000 0.000 0.000 sre_parse.py:96(SubPattern)
       35 0.000 0.000 0.000 0.000 sre_parse.py:98(__init__)
        6 0.000 0.000 0.000 0.000 stat.py:29(S_IFMT)
        4 0.000 0.000 0.000 0.000 stat.py:45(S_ISDIR)
        2 0.000 0.000 0.000 0.000 stat.py:54(S_ISREG)
        8 0.000 0.000 0.000 0.000 string.py:125(join)
        1 0.000 0.000 0.000 0.000 string.py:20(?)
        1 0.000 0.000 0.020 0.020 sysconfig.py:10(?)
        1 0.000 0.000 0.000 0.000 table.py:145(Table)
        1 0.000 0.000 0.000 0.000 table.py:21(?)
        1 0.000 0.000 0.000 0.000 table.py:37(Cell)
        1 0.000 0.000 0.980 0.980 testlog.py:2(?)
       84 0.010 0.000 0.090 0.001 text.py:216(draw)
        1 0.000 0.000 0.000 0.000 text.py:3(?)
        1 0.000 0.000 0.000 0.000 text.py:31(Text)
       18 0.000 0.000 0.000 0.000 text.py:314(get_position)
      156 0.000 0.000 0.000 0.000 text.py:318(get_prop_tup)
       81 0.000 0.000 0.020 0.000 text.py:344(get_window_extent)
       28 0.000 0.000 0.000 0.000 text.py:365(get_rotation_matrix)
       93 0.000 0.000 0.000 0.000 text.py:40(__init__)
       15 0.000 0.000 0.000 0.000 text.py:501(set_position)
       69 0.000 0.000 0.000 0.000 text.py:510(set_x)
       99 0.000 0.000 0.000 0.000 text.py:520(set_y)
      142 0.000 0.000 0.000 0.000 text.py:556(set_text)
       89 0.000 0.000 0.000 0.000 text.py:567(is_math_text)
       84 0.000 0.000 0.020 0.000 text.py:584(_get_layout_super)
      184 0.000 0.000 0.000 0.000 text.py:73(get_rotation)
       72 0.000 0.000 0.000 0.000 text.py:84(update_from)
       72 0.020 0.000 0.030 0.000 text.py:95(_get_layout)
        1 0.000 0.000 0.000 0.000 ticker.py:107(?)
        1 0.000 0.000 0.000 0.000 ticker.py:117(TickHelper)
       96 0.000 0.000 0.000 0.000 ticker.py:122(verify_intervals)
       27 0.000 0.000 0.000 0.000 ticker.py:130(set_view_interval)
       27 0.000 0.000 0.000 0.000 ticker.py:133(set_data_interval)
        1 0.000 0.000 0.000 0.000 ticker.py:136(Formatter)
       12 0.000 0.000 0.000 0.000 ticker.py:148(set_locs)
        1 0.000 0.000 0.000 0.000 ticker.py:151(NullFormatter)
       45 0.000 0.000 0.000 0.000 ticker.py:153(__call__)
        1 0.000 0.000 0.000 0.000 ticker.py:157(FixedFormatter)
        1 0.000 0.000 0.000 0.000 ticker.py:171(FuncFormatter)
        1 0.000 0.000 0.000 0.000 ticker.py:183(FormatStrFormatter)
        1 0.000 0.000 0.000 0.000 ticker.py:197(ScalarFormatter)
       27 0.000 0.000 0.000 0.000 ticker.py:204(__call__)
       27 0.000 0.000 0.000 0.000 ticker.py:211(pprint_val)
        1 0.000 0.000 0.000 0.000 ticker.py:234(LogFormatter)
        1 0.000 0.000 0.000 0.000 ticker.py:240(__init__)
       45 0.000 0.000 0.000 0.000 ticker.py:273(is_decade)
       90 0.000 0.000 0.000 0.000 ticker.py:277(nearest_long)
        1 0.000 0.000 0.000 0.000 ticker.py:282(LogFormatterExponent)
        1 0.000 0.000 0.000 0.000 ticker.py:305(LogFormatterMathtext)
       45 0.000 0.000 0.000 0.000 ticker.py:310(__call__)
        1 0.000 0.000 0.000 0.000 ticker.py:329(Locator)
        4 0.000 0.000 0.000 0.000 ticker.py:362(nonsingular)
        1 0.000 0.000 0.000 0.000 ticker.py:377(IndexLocator)
        1 0.000 0.000 0.000 0.000 ticker.py:395(FixedLocator)
        1 0.000 0.000 0.000 0.000 ticker.py:408(NullLocator)
        6 0.000 0.000 0.000 0.000 ticker.py:413(__call__)
        1 0.000 0.000 0.000 0.000 ticker.py:417(LinearLocator)
        4 0.000 0.000 0.000 0.000 ticker.py:428(__init__)
        2 0.000 0.000 0.000 0.000 ticker.py:485(closeto)
        1 0.000 0.000 0.000 0.000 ticker.py:489(Base)
        8 0.000 0.000 0.000 0.000 ticker.py:491(__init__)
        2 0.000 0.000 0.000 0.000 ticker.py:501(le)
        8 0.000 0.000 0.000 0.000 ticker.py:521(ge)
       12 0.000 0.000 0.000 0.000 ticker.py:527(get_base)
        1 0.000 0.000 0.000 0.000 ticker.py:530(MultipleLocator)
        8 0.000 0.000 0.000 0.000 ticker.py:536(__init__)
        6 0.000 0.000 0.000 0.000 ticker.py:539(__call__)
        2 0.000 0.000 0.000 0.000 ticker.py:552(autoscale)
        2 0.000 0.000 0.000 0.000 ticker.py:570(decade_down)
        1 0.000 0.000 0.000 0.000 ticker.py:576(decade_up)
        4 0.000 0.000 0.000 0.000 ticker.py:581(is_decade)
        1 0.000 0.000 0.000 0.000 ticker.py:585(LogLocator)
        2 0.000 0.000 0.000 0.000 ticker.py:590(__init__)
        2 0.000 0.000 0.000 0.000 ticker.py:597(base)
        2 0.000 0.000 0.000 0.000 ticker.py:603(subs)
       12 0.000 0.000 0.000 0.000 ticker.py:614(__call__)
        2 0.000 0.000 0.000 0.000 ticker.py:651(autoscale)
        1 0.000 0.000 0.000 0.000 ticker.py:672(AutoLocator)
        4 0.000 0.000 0.000 0.000 ticker.py:678(__init__)
        6 0.000 0.000 0.000 0.000 ticker.py:681(__call__)
        6 0.000 0.000 0.000 0.000 ticker.py:686(refresh)
        2 0.000 0.000 0.000 0.000 ticker.py:691(autoscale)
        8 0.000 0.000 0.000 0.000 ticker.py:699(get_locator)
        1 0.000 0.000 0.000 0.000 traceback.py:1(?)
        1 0.000 0.000 0.000 0.000 transforms.py:187(?)
     1499 0.020 0.000 0.020 0.000 transforms.py:192(zero)
     1146 0.000 0.000 0.000 0.000 transforms.py:194(one)
      572 0.020 0.000 0.030 0.000 transforms.py:196(origin)
      572 0.010 0.000 0.040 0.000 transforms.py:199(unit_bbox)
      284 0.000 0.000 0.040 0.000 transforms.py:212(identity_transform)
       88 0.010 0.000 0.020 0.000 transforms.py:220(translation_transform)
        9 0.000 0.000 0.000 0.000 transforms.py:267(bbox_all)
       62 0.000 0.000 0.000 0.000 transforms.py:296(lbwh_to_bbox)
        4 0.000 0.000 0.000 0.000 transforms.py:317(get_bbox_transform)
      223 0.000 0.000 0.000 0.000 transforms.py:326(blend_xy_sep_transform)
        9 0.000 0.000 0.000 0.000 transforms.py:377(inverse_transform_bbox)
        2 0.000 0.000 0.000 0.000 tzinfo.py:12(memorized_timedelta)
        1 0.000 0.000 0.000 0.000 tzinfo.py:2(?)
        1 0.000 0.000 0.000 0.000 tzinfo.py:299(AmbiguousTimeError)
        1 0.000 0.000 0.000 0.000 tzinfo.py:47(BaseTzInfo)
        1 0.000 0.000 0.000 0.000 tzinfo.py:57(StaticTzInfo)
        1 0.000 0.000 0.000 0.000 tzinfo.py:96(DstTzInfo)

John Hunter wrote:

For Fernando's test case, I was able to reduce the typical run time
from 1.02s to 0.2s for PNGs and 1.35s to 0.26s for PS . Here are my
notes on the various changes and the gains they brought. With
collections, I think we could halve this again for PS, or at the very
least get this down to agg speeds.

This is great, many thanks for working on this. For reference, here's what I was getting before:

[logtest]> ./logtest.py
Loading data...

pylab times...
plot: 3.38 s
png : 2.57 s
eps : 3.45 s

gnuplot...
plot: 0.16 s
eps : 0.06 s

Plot sizes:
-rw-r--r-- 1 fperez wavelet 27196 Feb 5 17:19 fig_gnuplot.eps
-rw-r--r-- 1 fperez wavelet 575701 Feb 5 17:19 fig_pylab.eps
-rw-r--r-- 1 fperez wavelet 33057 Feb 5 17:19 fig_pylab.png

and these are the current results:

[logtest]> ./logtest.py
Loading data...

pylab times...
plot: 0.70 s
png : 0.46 s
eps : 0.74 s

gnuplot...
plot: 0.02 s
eps : 0.21 s

Plot file info:
-rw-r--r-- 1 fperez wavelet 27196 Feb 6 15:19 fig_gnuplot.eps
-rw-r--r-- 1 fperez wavelet 417598 Feb 6 15:19 fig_pylab.eps
-rw-r--r-- 1 fperez wavelet 31550 Feb 6 15:19 fig_pylab.png

Note also how the pylab filesizes went down a bit, probably thanks to not having all the extra minor ticks.

For interactive work (which measures the time for the show() call, hence is higher than above), the improvement is also very noticeable:

In [6]: timing(fun2.plot_line,ptype='error') # pylab-based
Out[6]: 2.5686090000000004

In [7]: timing(fun2.plot_line_gp,ptype='error') # gnuplot-based
Out[7]: 0.56791400000000003

We're now within a factor of 5 of gnuplot (yesterday it was about 10x)

and here is the final profiler output of the newly optimized code

         58247 function calls (58081 primitive calls) in 0.980 CPU seconds

Wow, that's a lot of function calls... Given the cost of python function calls, I suspect that a major further improvement would require some manual inlining of some of this to reduce this number significantly. I'm not sure how worth this would be doing, given the cost in readability/architecture it may have. Just as a reference for you, here's the time for 58000 empty calls with one argument on my laptop (timings() is in IPython.genutils):

In [17]: def nothing(x):
    ....: pass
    ....:

In [18]: timings(58000,nothing,5)
Out[18]: (0.21196699999999957, 3.6546034482758548e-06)

            ^^ total time ^^ ^^ time per call ^^

But as far as I'm concerned, this is already much, much better than just a few days ago. Between the major fixes to correctness of log plots, and these performance improvements, I am very happy.

Many thanks for this effort. For those of us who spend a lot of time making log plots, this is great.

Best,

f