Speed quirk: redundant line gives six-fold speedup

[Bill Mill]

On 8/25/05, Erik Max Francis <max at alcyone.com> wrote:
> Bill Mill wrote:
> 
> > Unlikely; 2 people have confirmed these results already.
> >
> > I did find, though, that if I remove all print statements from the
> > program, the dummy and non-dummy variable versions take indentical
> > time. Can others reproduce this?
> 
> Yes, it's obviously a real effect given the other sightings.  I don't
> see any speed difference, myself (Pentium IV 3.0 GHz running Slackware
> Linux).
> 

Pentium M 1.8 GHz Windows 2k. Here's the top of the profile results
for fast and slow on my machine (these won't look decent except in a
fixed-width font):

Slow:

         6766494 function calls (6737594 primitive calls) in 45.740 CPU seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  3322320   20.539    0.000   31.152    0.000 test.py:135(<generator expression>
)
    27520   10.641    0.000   41.792    0.002 :0(min)
  3322320   10.613    0.000   10.613    0.000 test.py:81(rowitems)
 28100/20    3.620    0.000   45.633    2.282 test.py:130(search)
    27545    0.113    0.000    0.113    0.000 :0(append)
    27520    0.098    0.000    0.098    0.000 :0(pop)
        1    0.041    0.041   45.736   45.736 test.py:36(?)

Fast:

         540174 function calls (536514 primitive calls) in 3.506 CPU seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   259640    1.516    0.000    2.303    0.000 test.py:135(<generator expression>
)
     2280    0.791    0.000    3.094    0.001 :0(min)
   259640    0.788    0.000    0.788    0.000 test.py:81(rowitems)
  2860/20    0.269    0.000    3.391    0.170 test.py:130(search)
        1    0.045    0.045    3.499    3.499 test.py:2(?)
     3645    0.021    0.000    0.021    0.000 test.py:71(colinsert)
     3240    0.019    0.000    0.019    0.000 test.py:62(rowinsert)
     2305    0.010    0.000    0.010    0.000 :0(append)

Interestingly, the test.py:36 line, which takes 45 seconds (!!) in the
slow version, does not appear at all in the fast profile. I can't
figure out why - both printed out their data, so template must have
been called somewhere.

Peace
Bill Mill
bill.mill at gmail.com