Tracing support shows up fairly heavily an a Python profile, even
though it's nearly always turned off. The attached patch against the
trunk speeds up PyBench by 2% for me. All tests pass. I have 2
questions:

1) Can other people corroborate this speedup on their machines? I'm
running on a Macbook Pro (Intel Core2 processor, probably Merom) with
a 32-bit build from Apple's gcc-4.0.1. (Apple's gcc consistently
produces a faster python than gcc-4.3.)

2) Assuming this speeds things up for most people, should I check it
in anywhere besides the trunk? I assume it's out for 3.0; is it in for
2.6.1 or 3.0.1?



Pybench output:

-------------------------------------------------------------------------------
PYBENCH 2.0
-------------------------------------------------------------------------------
* using CPython 2.7a0 (trunk:67458M, Nov 30 2008, 17:14:10) [GCC 4.0.1
(Apple Inc. build 5488)]
* disabled garbage collection
* system check interval set to maximum: 2147483647
* using timer: time.time

-------------------------------------------------------------------------------
Benchmark: pybench.out
-------------------------------------------------------------------------------

   Rounds: 10
   Warp:   10
   Timer:  time.time

   Machine Details:
      Platform ID:    Darwin-9.5.0-i386-32bit
      Processor:      i386

   Python:
      Implementation: CPython
      Executable:
/Users/jyasskin/src/python/trunk-fast-tracing/build/python.exe
      Version:        2.7.0
      Compiler:       GCC 4.0.1 (Apple Inc. build 5488)
      Bits:           32bit
      Build:          Nov 30 2008 17:14:10 (#trunk:67458M)
      Unicode:        UCS2


-------------------------------------------------------------------------------
Comparing with: ../build_orig/pybench.out
-------------------------------------------------------------------------------

   Rounds: 10
   Warp:   10
   Timer:  time.time

   Machine Details:
      Platform ID:    Darwin-9.5.0-i386-32bit
      Processor:      i386

   Python:
      Implementation: CPython
      Executable:
/Users/jyasskin/src/python/trunk-fast-tracing/build_orig/python.exe
      Version:        2.7.0
      Compiler:       GCC 4.0.1 (Apple Inc. build 5488)
      Bits:           32bit
      Build:          Nov 30 2008 13:51:09 (#trunk:67458)
      Unicode:        UCS2


Test                             minimum run-time        average  run-time
                                this    other   diff    this    other   diff
-------------------------------------------------------------------------------
         BuiltinFunctionCalls:   127ms   130ms   -2.4%   129ms   132ms 
 -2.1%
          BuiltinMethodLookup:    90ms    93ms   -3.2%    91ms    94ms 
 -3.1%
                CompareFloats:    88ms    91ms   -3.3%    89ms    93ms 
 -4.3%
        CompareFloatsIntegers:    97ms    99ms   -2.1%    97ms   100ms 
 -2.4%
              CompareIntegers:    79ms    82ms   -4.2%    79ms    85ms 
 -6.1%
       CompareInternedStrings:    90ms    92ms   -2.4%    94ms    94ms 
 -0.9%
                 CompareLongs:    86ms    83ms   +3.6%    87ms    84ms 
 +3.5%
               CompareStrings:    80ms    82ms   -3.1%    81ms    83ms 
 -2.3%
               CompareUnicode:   103ms   105ms   -2.3%   106ms   108ms 
 -1.5%
   ComplexPythonFunctionCalls:   139ms   137ms   +1.3%   140ms   139ms 
 +0.1%
                ConcatStrings:   142ms   151ms   -6.0%   156ms   154ms 
 +1.1%
                ConcatUnicode:    87ms    92ms   -5.4%    89ms    94ms 
 -5.7%
              CreateInstances:   142ms   144ms   -1.4%   144ms   145ms 
 -1.1%
           CreateNewInstances:   107ms   109ms   -2.3%   108ms   111ms 
 -2.1%
      CreateStringsWithConcat:   114ms   137ms  -17.1%   117ms   139ms 
-16.0%
      CreateUnicodeWithConcat:    92ms   101ms   -9.2%    95ms   102ms 
 -7.2%
                 DictCreation:    77ms    81ms   -4.4%    80ms    85ms 
 -5.9%
            DictWithFloatKeys:    91ms   107ms  -14.5%    93ms   109ms 
-14.6%
          DictWithIntegerKeys:    95ms    94ms   +1.4%   108ms    96ms 
+12.3%
           DictWithStringKeys:    83ms    88ms   -5.8%    84ms    88ms 
 -4.7%
                     ForLoops:    72ms    72ms   -0.1%    79ms    74ms 
 +5.8%
                   IfThenElse:    83ms    80ms   +3.9%    85ms    80ms 
 +5.3%
                  ListSlicing:   117ms   118ms   -0.7%   118ms   121ms 
 -1.8%
               NestedForLoops:   116ms   119ms   -2.4%   121ms   121ms 
 +0.0%
         NormalClassAttribute:   106ms   115ms   -7.7%   108ms   117ms 
 -7.7%
      NormalInstanceAttribute:    96ms    98ms   -2.3%    97ms   100ms 
 -3.1%
          PythonFunctionCalls:    92ms    95ms   -3.7%    94ms    99ms 
 -5.2%
            PythonMethodCalls:   147ms   147ms   +0.1%   152ms   149ms 
 +2.1%
                    Recursion:   135ms   136ms   -0.3%   140ms   144ms 
 -2.9%
                 SecondImport:   101ms    99ms   +2.1%   103ms   101ms 
 +2.2%
          SecondPackageImport:   107ms   103ms   +3.5%   108ms   104ms 
 +3.3%
        SecondSubmoduleImport:   134ms   134ms   +0.3%   136ms   136ms 
 -0.0%
      SimpleComplexArithmetic:   105ms   111ms   -5.0%   110ms   112ms 
 -1.4%
       SimpleDictManipulation:    95ms   106ms  -10.6%    96ms   109ms 
-12.0%
        SimpleFloatArithmetic:    90ms    99ms   -9.3%    93ms   102ms 
 -8.2%
     SimpleIntFloatArithmetic:    78ms    76ms   +2.3%    79ms    77ms 
 +2.0%
      SimpleIntegerArithmetic:    78ms    77ms   +1.8%    79ms    77ms 
 +2.0%
       SimpleListManipulation:    80ms    78ms   +2.4%    80ms    79ms 
 +1.9%
         SimpleLongArithmetic:   110ms   113ms   -2.0%   111ms   113ms 
 -2.1%
                   SmallLists:   128ms   117ms   +9.5%   130ms   124ms 
 +4.9%
                  SmallTuples:   115ms   114ms   +1.7%   117ms   114ms 
 +2.2%
        SpecialClassAttribute:   101ms   112ms  -10.3%   104ms   114ms 
 -8.9%
     SpecialInstanceAttribute:   173ms   177ms   -1.9%   176ms   179ms 
 -1.6%
               StringMappings:   165ms   167ms   -1.2%   168ms   169ms 
 -0.5%
             StringPredicates:   126ms   134ms   -5.7%   127ms   134ms 
 -5.6%
                StringSlicing:   125ms   123ms   +1.9%   131ms   130ms 
 +0.7%
                    TryExcept:    79ms    80ms   -0.6%    80ms    80ms 
 -0.8%
                   TryFinally:   110ms   107ms   +3.0%   111ms   112ms 
 -1.1%
               TryRaiseExcept:    99ms   101ms   -1.6%   100ms   102ms 
 -1.7%
                 TupleSlicing:   127ms   127ms   +0.6%   137ms   137ms 
 +0.0%
              UnicodeMappings:   144ms   144ms   -0.3%   145ms   145ms 
 -0.4%
            UnicodePredicates:   116ms   114ms   +1.3%   117ms   115ms 
 +1.1%
            UnicodeProperties:   106ms   102ms   +3.6%   107ms   104ms 
 +3.1%
               UnicodeSlicing:    95ms   111ms  -14.0%    99ms   112ms 
-11.8%
                  WithFinally:   157ms   152ms   +3.3%   159ms   154ms 
 +3.3%
              WithRaiseExcept:   123ms   125ms   -1.1%   125ms   126ms 
 -1.2%
-------------------------------------------------------------------------------
Totals:                          6043ms  6182ms   -2.2%  6185ms  6301ms
  -1.9%

(this=pybench.out, other=../build_orig/pybench.out)


2to3 times:

Before:
$ time ./python.exe ~/src/2to3/2to3 -f all ~/src/2to3/ >/dev/null
real    0m56.685s
user    0m55.620s
sys     0m0.380s

After:
$ time ./python.exe ~/src/2to3/2to3 -f all ~/src/2to3/ >/dev/null
real    0m55.067s
user    0m53.843s
sys     0m0.376s

== 3% faster


Gory details:

The meat of the patch is:
@@ -884,11 +891,12 @@
       fast_next_opcode:
               f->f_lasti = INSTR_OFFSET();

               /* line-by-line tracing support */

-               if (tstate->c_tracefunc != NULL && !tstate->tracing) {
+               if (_Py_TracingPossible &&
+                   tstate->c_tracefunc != NULL && !tstate->tracing) {


This converts the generated assembly (produced with `gcc -S -dA ...`,
then manually annotated a bit) from:

       # basic block 17
       # ../Python/ceval.c:885
LM541:
       movl    8(%ebp), %ecx
LVL319:
       subl    -316(%ebp), %edx
       movl    %edx, 60(%ecx)
       # ../Python/ceval.c:889
LM542:
# %esi = tstate
       movl    -336(%ebp), %esi
LVL320:
# %eax = tstate->c_tracefunc
       movl    28(%esi), %eax
LVL321:
# if tstate->c_tracefunc == 0
       testl   %eax, %eax
# goto past-if ()
       je      L567
# more if conditions here

to:

       # basic block 17
       # ../Python/ceval.c:889
LM542:
       movl    8(%ebp), %ecx
LVL319:
       subl    -316(%ebp), %edx
       movl    %edx, 60(%ecx)
       # ../Python/ceval.c:893
LM543:
# %eax = _Py_TracingPossible
       movl    __Py_TracingPossible-"L00000000033$pb"(%ebx), %eax
LVL320:
# if _Py_TracingPossible != 0
       testl   %eax, %eax
# goto rest-of-if (nearby)
       jne     L2321
# opcode = NEXTOP(); continues here


The branch should be predicted accurately either way, so there are 2
things that may be contributing to the performance change.

First, adding the global caching variable halves the amount of memory
that has to be read to check the prediction. The memory that is read
is still read one instruction before it's used, but adding a local
variable to read the memory earlier doesn't affect the performance.

Without the global variable, the compiler puts the tracing code
immediately after the if; with the global, it moves it away and puts the
non-tracing code immediately after the first test in the if. This
may affect branch prediction and may affect the icache. I tried using
gcc's __builtin_expect() to ensure that the tracing code is always
out-of-line. This moved it much farther away and cost about 1% in
performance (i.e. 1% instead of 2% faster than "before"). I don't know
why the __builtin_expect() version would be slower. If anyone feels
inspired to test this out on another processor or compiler version,
let me know how it goes.

Jeffrey

I don't think anything performance-related should be checked in before 3.0.

Martin, does your comment mean you think this should stay out of the
trunk(s) until 3.0 is released? That's fine. How about after that:
should it go in the 2.6.x and 3.0.x branches too?

I think it should stay out of the trunk until 3.0 is released only
because that simplifies merging and 3.0 is only 3 days away.

Before it is accepted, I'd like to see some independent analysis (which
I might have to carry out myself). It would also be good if some deeper
understanding of the effect could be provided - I'm fairly skeptical
that such a minor change should have any notable effect.

+1 on the patch.  It makes good sense to me.

Jeffrey, I've run my own timings and verified the improvement.  Please
go ahead and apply the trunk (2.7 head).  

It's too late for 3.0 but once that is out the door, Barry has approved
adding the patch for 3.0.1.

Thanks for the review, Raymond. Committed to the trunk in r67494. I'll
svnmerge it over to 3.0.1 once Barry unfreezes the branches.

Martin, let me know if you analyze this any more and find anything
interesting.

Merged to 3.1 in r67611, 3.0.x in r67721, and 2.6.x in r67722.