Added the cProfile module.

Based on lsprof (patch #1212837) by Brett Rosen and Ted Czotter.
With further editing by Michael Hudson and myself.
History in svn repo: http://codespeak.net/svn/user/arigo/hack/misc/lsprof

* Module/_lsprof.c is the internal C module, Lib/cProfile.py a wrapper.
* pstats.py updated to display cProfile's caller/callee timings if available.
* setup.py and NEWS updated.
* documentation updates in the profiler section:
   - explain the differences between the three profilers that we have now
   - profile and cProfile can use a unified documentation, like (c)Pickle
   - mention that hotshot is "for specialized usage" now
   - removed references to the "old profiler" that no longer exists
* test updates:
   - extended test_profile to cover delicate cases like recursion
   - added tests for the caller/callee displays
   - added test_cProfile, performing the same tests for cProfile
* TO-DO:
   - cProfile gives a nicer name to built-in, particularly built-in methods,
     which could be backported to profile.
   - not tested on Windows recently!

Doc/lib/lib.tex

@@ -358,7 +358,7 @@ and how to embed it in other applications.
 \input{libpdb}                  % The Python Debugger
 
 \input{libprofile}              % The Python Profiler
-\input{libhotshot}              % New profiler
+\input{libhotshot}              % unmaintained C profiler
 \input{libtimeit}
 
 

Doc/lib/libhotshot.tex

@@ -14,6 +14,17 @@ Hotshot is a replacement for the existing \refmodule{profile} module. As it's
 written mostly in C, it should result in a much smaller performance impact
 than the existing \refmodule{profile} module.
 
+\begin{notice}[note]
+  The \module{hotshot} module focuses on minimizing the overhead
+  while profiling, at the expense of long data post-processing times.
+  For common usages it is recommended to use \module{cProfile} instead.
+  \module{hotshot} is not maintained and might be removed from the
+  standard library in the future.
+\end{notice}
+
+\versionchanged[the results should be more meaningful than in the
+past: the timing core contained a critical bug]{2.5}
+
 \begin{notice}[warning]
   The \module{hotshot} profiler does not yet work well with threads.
   It is useful to use an unthreaded script to run the profiler over

Lib/cProfile.py

+#! /usr/bin/env python
+
+"""Python interface for the 'lsprof' profiler.
+   Compatible with the 'profile' module.
+"""
+
+__all__ = ["run", "runctx", "help", "Profile"]
+
+import _lsprof
+
+# ____________________________________________________________
+# Simple interface
+
+def run(statement, filename=None, sort=-1):
+    """Run statement under profiler optionally saving results in filename
+
+    This function takes a single argument that can be passed to the
+    "exec" statement, and an optional file name.  In all cases this
+    routine attempts to "exec" its first argument and gather profiling
+    statistics from the execution. If no file name is present, then this
+    function automatically prints a simple profiling report, sorted by the
+    standard name string (file/line/function-name) that is presented in
+    each line.
+    """
+    prof = Profile()
+    result = None
+    try:
+        try:
+            prof = prof.run(statement)
+        except SystemExit:
+            pass
+    finally:
+        if filename is not None:
+            prof.dump_stats(filename)
+        else:
+            result = prof.print_stats(sort)
+    return result
+
+def runctx(statement, globals, locals, filename=None):
+    """Run statement under profiler, supplying your own globals and locals,
+    optionally saving results in filename.
+
+    statement and filename have the same semantics as profile.run
+    """
+    prof = Profile()
+    result = None
+    try:
+        try:
+            prof = prof.runctx(statement, globals, locals)
+        except SystemExit:
+            pass
+    finally:
+        if filename is not None:
+            prof.dump_stats(filename)
+        else:
+            result = prof.print_stats()
+    return result
+
+# Backwards compatibility.
+def help():
+    print "Documentation for the profile/cProfile modules can be found "
+    print "in the Python Library Reference, section 'The Python Profiler'."
+
+# ____________________________________________________________
+
+class Profile(_lsprof.Profiler):
+    """Profile(custom_timer=None, time_unit=None, subcalls=True, builtins=True)
+
+    Builds a profiler object using the specified timer function.
+    The default timer is a fast built-in one based on real time.
+    For custom timer functions returning integers, time_unit can
+    be a float specifying a scale (i.e. how long each integer unit
+    is, in seconds).
+    """
+
+    # Most of the functionality is in the base class.
+    # This subclass only adds convenient and backward-compatible methods.
+
+    def print_stats(self, sort=-1):
+        import pstats
+        pstats.Stats(self).strip_dirs().sort_stats(sort).print_stats()
+
+    def dump_stats(self, file):
+        import marshal
+        f = open(file, 'wb')
+        self.create_stats()
+        marshal.dump(self.stats, f)
+        f.close()
+
+    def create_stats(self):
+        self.disable()
+        self.snapshot_stats()
+
+    def snapshot_stats(self):
+        entries = self.getstats()
+        self.stats = {}
+        callersdicts = {}
+        # call information
+        for entry in entries:
+            func = label(entry.code)
+            nc = entry.callcount         # ncalls column of pstats (before '/')
+            cc = nc - entry.reccallcount # ncalls column of pstats (after '/')
+            tt = entry.inlinetime        # tottime column of pstats
+            ct = entry.totaltime         # cumtime column of pstats
+            callers = {}
+            callersdicts[id(entry.code)] = callers
+            self.stats[func] = cc, nc, tt, ct, callers
+        # subcall information
+        for entry in entries:
+            if entry.calls:
+                func = label(entry.code)
+                for subentry in entry.calls:
+                    try:
+                        callers = callersdicts[id(subentry.code)]
+                    except KeyError:
+                        continue
+                    nc = subentry.callcount
+                    cc = nc - subentry.reccallcount
+                    tt = subentry.inlinetime
+                    ct = subentry.totaltime
+                    if func in callers:
+                        prev = callers[func]
+                        nc += prev[0]
+                        cc += prev[1]
+                        tt += prev[2]
+                        ct += prev[3]
+                    callers[func] = nc, cc, tt, ct
+
+    # The following two methods can be called by clients to use
+    # a profiler to profile a statement, given as a string.
+
+    def run(self, cmd):
+        import __main__
+        dict = __main__.__dict__
+        return self.runctx(cmd, dict, dict)
+
+    def runctx(self, cmd, globals, locals):
+        self.enable()
+        try:
+            exec cmd in globals, locals
+        finally:
+            self.disable()
+        return self
+
+    # This method is more useful to profile a single function call.
+    def runcall(self, func, *args, **kw):
+        self.enable()
+        try:
+            return func(*args, **kw)
+        finally:
+            self.disable()
+
+# ____________________________________________________________
+
+def label(code):
+    if isinstance(code, str):
+        return ('~', 0, code)    # built-in functions ('~' sorts at the end)
+    else:
+        return (code.co_filename, code.co_firstlineno, code.co_name)
+
+# ____________________________________________________________
+
+def main():
+    import os, sys
+    from optparse import OptionParser
+    usage = "cProfile.py [-o output_file_path] [-s sort] scriptfile [arg] ..."
+    parser = OptionParser(usage=usage)
+    parser.allow_interspersed_args = False
+    parser.add_option('-o', '--outfile', dest="outfile",
+        help="Save stats to <outfile>", default=None)
+    parser.add_option('-s', '--sort', dest="sort",
+        help="Sort order when printing to stdout, based on pstats.Stats class", default=-1)
+
+    if not sys.argv[1:]:
+        parser.print_usage()
+        sys.exit(2)
+
+    (options, args) = parser.parse_args()
+    sys.argv[:] = args
+
+    if (len(sys.argv) > 0):
+        sys.path.insert(0, os.path.dirname(sys.argv[0]))
+        run('execfile(%r)' % (sys.argv[0],), options.outfile, options.sort)
+    else:
+        parser.print_usage()
+    return parser
+
+# When invoked as main program, invoke the profiler on a script
+if __name__ == '__main__':
+    main()

Lib/pstats.py

@@ -371,27 +371,47 @@ class Stats:
             self.print_call_heading(width, "was called by...")
             for func in list:
                 cc, nc, tt, ct, callers = self.stats[func]
-                self.print_call_line(width, func, callers)
+                self.print_call_line(width, func, callers, "<-")
             print
             print
         return self
 
     def print_call_heading(self, name_size, column_title):
         print "Function ".ljust(name_size) + column_title
-
-    def print_call_line(self, name_size, source, call_dict):
-        print func_std_string(source).ljust(name_size),
+        # print sub-header only if we have new-style callers
+        subheader = False
+        for cc, nc, tt, ct, callers in self.stats.itervalues():
+            if callers:
+                value = callers.itervalues().next()
+                subheader = isinstance(value, tuple)
+                break
+        if subheader:
+            print " "*name_size + "    ncalls  tottime  cumtime"
+
+    def print_call_line(self, name_size, source, call_dict, arrow="->"):
+        print func_std_string(source).ljust(name_size) + arrow,
         if not call_dict:
-            print "--"
+            print
             return
         clist = call_dict.keys()
         clist.sort()
-        name_size = name_size + 1
         indent = ""
         for func in clist:
             name = func_std_string(func)
-            print indent*name_size + name + '(%r)' % (call_dict[func],), \
-                      f8(self.stats[func][3])
+            value = call_dict[func]
+            if isinstance(value, tuple):
+                nc, cc, tt, ct = value
+                if nc != cc:
+                    substats = '%d/%d' % (nc, cc)
+                else:
+                    substats = '%d' % (nc,)
+                substats = '%s %s %s  %s' % (substats.rjust(7+2*len(indent)),
+                                             f8(tt), f8(ct), name)
+                left_width = name_size + 1
+            else:
+                substats = '%s(%r) %s' % (name, value, f8(self.stats[func][3]))
+                left_width = name_size + 3
+            print indent*left_width + substats
             indent = " "
 
     def print_title(self):
@@ -448,7 +468,15 @@ def func_get_function_name(func):
     return func[2]
 
 def func_std_string(func_name): # match what old profile produced
-    return "%s:%d(%s)" % func_name
+    if func_name[:2] == ('~', 0):
+        # special case for built-in functions
+        name = func_name[2]
+        if name.startswith('<') and name.endswith('>'):
+            return '{%s}' % name[1:-1]
+        else:
+            return name
+    else:
+        return "%s:%d(%s)" % func_name
 
 #**************************************************************************
 # The following functions combine statists for pairs functions.

Lib/test/output/test_cProfile

+test_cProfile
+         126 function calls (106 primitive calls) in 1.000 CPU seconds
+
+   Ordered by: standard name
+
+   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
+        1    0.000    0.000    1.000    1.000 <string>:1(<module>)
+        8    0.064    0.008    0.080    0.010 test_cProfile.py:103(subhelper)
+       28    0.028    0.001    0.028    0.001 test_cProfile.py:115(__getattr__)
+        1    0.270    0.270    1.000    1.000 test_cProfile.py:30(testfunc)
+     23/3    0.150    0.007    0.170    0.057 test_cProfile.py:40(factorial)
+       20    0.020    0.001    0.020    0.001 test_cProfile.py:53(mul)
+        2    0.040    0.020    0.600    0.300 test_cProfile.py:60(helper)
+        4    0.116    0.029    0.120    0.030 test_cProfile.py:78(helper1)
+        2    0.000    0.000    0.140    0.070 test_cProfile.py:89(helper2_indirect)
+        8    0.312    0.039    0.400    0.050 test_cProfile.py:93(helper2)
+       12    0.000    0.000    0.012    0.001 {hasattr}
+        4    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
+        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
+        8    0.000    0.000    0.000    0.000 {range}
+        4    0.000    0.000    0.000    0.000 {sys.exc_info}
+
+
+   Ordered by: standard name
+
+Function                                          called...
+                                                      ncalls  tottime  cumtime
+<string>:1(<module>)                              ->       1    0.270    1.000  test_cProfile.py:30(testfunc)
+test_cProfile.py:103(subhelper)                   ->      16    0.016    0.016  test_cProfile.py:115(__getattr__)
+                                                           8    0.000    0.000  {range}
+test_cProfile.py:115(__getattr__)                 ->
+test_cProfile.py:30(testfunc)                     ->       1    0.014    0.130  test_cProfile.py:40(factorial)
+                                                           2    0.040    0.600  test_cProfile.py:60(helper)
+test_cProfile.py:40(factorial)                    ->    20/3    0.130    0.147  test_cProfile.py:40(factorial)
+                                                          20    0.020    0.020  test_cProfile.py:53(mul)
+test_cProfile.py:53(mul)                          ->
+test_cProfile.py:60(helper)                       ->       4    0.116    0.120  test_cProfile.py:78(helper1)
+                                                           2    0.000    0.140  test_cProfile.py:89(helper2_indirect)
+                                                           6    0.234    0.300  test_cProfile.py:93(helper2)
+test_cProfile.py:78(helper1)                      ->       4    0.000    0.004  {hasattr}
+                                                           4    0.000    0.000  {method 'append' of 'list' objects}
+                                                           4    0.000    0.000  {sys.exc_info}
+test_cProfile.py:89(helper2_indirect)             ->       2    0.006    0.040  test_cProfile.py:40(factorial)
+                                                           2    0.078    0.100  test_cProfile.py:93(helper2)
+test_cProfile.py:93(helper2)                      ->       8    0.064    0.080  test_cProfile.py:103(subhelper)
+                                                           8    0.000    0.008  {hasattr}
+{hasattr}                                         ->      12    0.012    0.012  test_cProfile.py:115(__getattr__)
+{method 'append' of 'list' objects}               ->
+{method 'disable' of '_lsprof.Profiler' objects}  ->
+{range}                                           ->
+{sys.exc_info}                                    ->
+
+
+   Ordered by: standard name
+
+Function                                          was called by...
+                                                      ncalls  tottime  cumtime
+<string>:1(<module>)                              <-
+test_cProfile.py:103(subhelper)                   <-       8    0.064    0.080  test_cProfile.py:93(helper2)
+test_cProfile.py:115(__getattr__)                 <-      16    0.016    0.016  test_cProfile.py:103(subhelper)
+                                                          12    0.012    0.012  {hasattr}
+test_cProfile.py:30(testfunc)                     <-       1    0.270    1.000  <string>:1(<module>)
+test_cProfile.py:40(factorial)                    <-       1    0.014    0.130  test_cProfile.py:30(testfunc)
+                                                        20/3    0.130    0.147  test_cProfile.py:40(factorial)
+                                                           2    0.006    0.040  test_cProfile.py:89(helper2_indirect)
+test_cProfile.py:53(mul)                          <-      20    0.020    0.020  test_cProfile.py:40(factorial)
+test_cProfile.py:60(helper)                       <-       2    0.040    0.600  test_cProfile.py:30(testfunc)
+test_cProfile.py:78(helper1)                      <-       4    0.116    0.120  test_cProfile.py:60(helper)
+test_cProfile.py:89(helper2_indirect)             <-       2    0.000    0.140  test_cProfile.py:60(helper)
+test_cProfile.py:93(helper2)                      <-       6    0.234    0.300  test_cProfile.py:60(helper)
+                                                           2    0.078    0.100  test_cProfile.py:89(helper2_indirect)
+{hasattr}                                         <-       4    0.000    0.004  test_cProfile.py:78(helper1)
+                                                           8    0.000    0.008  test_cProfile.py:93(helper2)
+{method 'append' of 'list' objects}               <-       4    0.000    0.000  test_cProfile.py:78(helper1)
+{method 'disable' of '_lsprof.Profiler' objects}  <-
+{range}                                           <-       8    0.000    0.000  test_cProfile.py:103(subhelper)
+{sys.exc_info}                                    <-       4    0.000    0.000  test_cProfile.py:78(helper1)
+
+

Lib/test/output/test_profile

 test_profile
-         74 function calls in 1.000 CPU seconds
+         127 function calls (107 primitive calls) in 1.000 CPU seconds
 
    Ordered by: standard name
 
    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
+        4    0.000    0.000    0.000    0.000 :0(append)
+        4    0.000    0.000    0.000    0.000 :0(exc_info)
        12    0.000    0.000    0.012    0.001 :0(hasattr)
         8    0.000    0.000    0.000    0.000 :0(range)
         1    0.000    0.000    0.000    0.000 :0(setprofile)
         1    0.000    0.000    1.000    1.000 <string>:1(<module>)
         0    0.000             0.000          profile:0(profiler)
         1    0.000    0.000    1.000    1.000 profile:0(testfunc())
-        1    0.400    0.400    1.000    1.000 test_profile.py:23(testfunc)
-        2    0.080    0.040    0.600    0.300 test_profile.py:32(helper)
-        4    0.116    0.029    0.120    0.030 test_profile.py:50(helper1)
-        8    0.312    0.039    0.400    0.050 test_profile.py:58(helper2)
-        8    0.064    0.008    0.080    0.010 test_profile.py:68(subhelper)
-       28    0.028    0.001    0.028    0.001 test_profile.py:80(__getattr__)
+        8    0.064    0.008    0.080    0.010 test_profile.py:103(subhelper)
+       28    0.028    0.001    0.028    0.001 test_profile.py:115(__getattr__)
+        1    0.270    0.270    1.000    1.000 test_profile.py:30(testfunc)
+     23/3    0.150    0.007    0.170    0.057 test_profile.py:40(factorial)
+       20    0.020    0.001    0.020    0.001 test_profile.py:53(mul)
+        2    0.040    0.020    0.600    0.300 test_profile.py:60(helper)
+        4    0.116    0.029    0.120    0.030 test_profile.py:78(helper1)
+        2    0.000    0.000    0.140    0.070 test_profile.py:89(helper2_indirect)
+        8    0.312    0.039    0.400    0.050 test_profile.py:93(helper2)
+
+
+   Ordered by: standard name
+
+Function                              called...
+:0(append)                            ->
+:0(exc_info)                          ->
+:0(hasattr)                           -> test_profile.py:115(__getattr__)(12)    0.028
+:0(range)                             ->
+:0(setprofile)                        ->
+<string>:1(<module>)                  -> test_profile.py:30(testfunc)(1)    1.000
+profile:0(profiler)                   -> profile:0(testfunc())(1)    1.000
+profile:0(testfunc())                 -> :0(setprofile)(1)    0.000
+                                         <string>:1(<module>)(1)    1.000
+test_profile.py:103(subhelper)        -> :0(range)(8)    0.000
+                                         test_profile.py:115(__getattr__)(16)    0.028
+test_profile.py:115(__getattr__)      ->
+test_profile.py:30(testfunc)          -> test_profile.py:40(factorial)(1)    0.170
+                                         test_profile.py:60(helper)(2)    0.600
+test_profile.py:40(factorial)         -> test_profile.py:40(factorial)(20)    0.170
+                                         test_profile.py:53(mul)(20)    0.020
+test_profile.py:53(mul)               ->
+test_profile.py:60(helper)            -> test_profile.py:78(helper1)(4)    0.120
+                                         test_profile.py:89(helper2_indirect)(2)    0.140
+                                         test_profile.py:93(helper2)(6)    0.400
+test_profile.py:78(helper1)           -> :0(append)(4)    0.000
+                                         :0(exc_info)(4)    0.000
+                                         :0(hasattr)(4)    0.012
+test_profile.py:89(helper2_indirect)  -> test_profile.py:40(factorial)(2)    0.170
+                                         test_profile.py:93(helper2)(2)    0.400
+test_profile.py:93(helper2)           -> :0(hasattr)(8)    0.012
+                                         test_profile.py:103(subhelper)(8)    0.080
+
+
+   Ordered by: standard name
+
+Function                              was called by...
+:0(append)                            <- test_profile.py:78(helper1)(4)    0.120
+:0(exc_info)                          <- test_profile.py:78(helper1)(4)    0.120
+:0(hasattr)                           <- test_profile.py:78(helper1)(4)    0.120
+                                         test_profile.py:93(helper2)(8)    0.400
+:0(range)                             <- test_profile.py:103(subhelper)(8)    0.080
+:0(setprofile)                        <- profile:0(testfunc())(1)    1.000
+<string>:1(<module>)                  <- profile:0(testfunc())(1)    1.000
+profile:0(profiler)                   <-
+profile:0(testfunc())                 <- profile:0(profiler)(1)    0.000
+test_profile.py:103(subhelper)        <- test_profile.py:93(helper2)(8)    0.400
+test_profile.py:115(__getattr__)      <- :0(hasattr)(12)    0.012
+                                         test_profile.py:103(subhelper)(16)    0.080
+test_profile.py:30(testfunc)          <- <string>:1(<module>)(1)    1.000
+test_profile.py:40(factorial)         <- test_profile.py:30(testfunc)(1)    1.000
+                                         test_profile.py:40(factorial)(20)    0.170
+                                         test_profile.py:89(helper2_indirect)(2)    0.140
+test_profile.py:53(mul)               <- test_profile.py:40(factorial)(20)    0.170
+test_profile.py:60(helper)            <- test_profile.py:30(testfunc)(2)    1.000
+test_profile.py:78(helper1)           <- test_profile.py:60(helper)(4)    0.600
+test_profile.py:89(helper2_indirect)  <- test_profile.py:60(helper)(2)    0.600
+test_profile.py:93(helper2)           <- test_profile.py:60(helper)(6)    0.600
+                                         test_profile.py:89(helper2_indirect)(2)    0.140
 
 

Lib/test/test_cProfile.py

+"""Test suite for the cProfile module."""
+
+import cProfile, pstats, sys
+
+# In order to have reproducible time, we simulate a timer in the global
+# variable 'ticks', which represents simulated time in milliseconds.
+# (We can't use a helper function increment the timer since it would be
+# included in the profile and would appear to consume all the time.)
+ticks = 0
+
+# IMPORTANT: this is an output test.  *ALL* NUMBERS in the expected
+# output are relevant.  If you change the formatting of pstats,
+# please don't just regenerate output/test_cProfile without checking
+# very carefully that not a single number has changed.
+
+def test_main():
+    global ticks
+    ticks = 42000
+    prof = cProfile.Profile(timer, 0.001)
+    prof.runctx("testfunc()", globals(), locals())
+    assert ticks == 43000, ticks
+    st = pstats.Stats(prof)
+    st.strip_dirs().sort_stats('stdname').print_stats()
+    st.print_callees()
+    st.print_callers()
+
+def timer():
+    return ticks
+
+def testfunc():
+    # 1 call
+    # 1000 ticks total: 270 ticks local, 730 ticks in subfunctions
+    global ticks
+    ticks += 99
+    helper()                            # 300
+    helper()                            # 300
+    ticks += 171
+    factorial(14)                       # 130
+
+def factorial(n):
+    # 23 calls total
+    # 170 ticks total, 150 ticks local
+    # 3 primitive calls, 130, 20 and 20 ticks total
+    # including 116, 17, 17 ticks local
+    global ticks
+    if n > 0:
+        ticks += n
+        return mul(n, factorial(n-1))
+    else:
+        ticks += 11
+        return 1
+
+def mul(a, b):
+    # 20 calls
+    # 1 tick, local
+    global ticks
+    ticks += 1
+    return a * b
+
+def helper():
+    # 2 calls
+    # 300 ticks total: 20 ticks local, 260 ticks in subfunctions
+    global ticks
+    ticks += 1
+    helper1()                           # 30
+    ticks += 2
+    helper1()                           # 30
+    ticks += 6
+    helper2()                           # 50
+    ticks += 3
+    helper2()                           # 50
+    ticks += 2
+    helper2()                           # 50
+    ticks += 5
+    helper2_indirect()                  # 70
+    ticks += 1
+
+def helper1():
+    # 4 calls
+    # 30 ticks total: 29 ticks local, 1 tick in subfunctions
+    global ticks
+    ticks += 10
+    hasattr(C(), "foo")                 # 1
+    ticks += 19
+    lst = []
+    lst.append(42)                      # 0
+    sys.exc_info()                      # 0
+
+def helper2_indirect():
+    helper2()                           # 50
+    factorial(3)                        # 20
+
+def helper2():
+    # 8 calls
+    # 50 ticks local: 39 ticks local, 11 ticks in subfunctions
+    global ticks
+    ticks += 11
+    hasattr(C(), "bar")                 # 1
+    ticks += 13
+    subhelper()                         # 10
+    ticks += 15
+
+def subhelper():
+    # 8 calls
+    # 10 ticks total: 8 ticks local, 2 ticks in subfunctions
+    global ticks
+    ticks += 2
+    for i in range(2):                  # 0
+        try:
+            C().foo                     # 1 x 2
+        except AttributeError:
+            ticks += 3                  # 3 x 2
+
+class C:
+    def __getattr__(self, name):
+        # 28 calls
+        # 1 tick, local
+        global ticks
+        ticks += 1
+        raise AttributeError
+
+if __name__ == "__main__":
+    test_main()

Lib/test/test_profile.py

 """Test suite for the profile module."""
 
-import profile
-import os
-from test.test_support import TESTFN, vereq
+import profile, pstats, sys
 
 # In order to have reproducible time, we simulate a timer in the global
 # variable 'ticks', which represents simulated time in milliseconds.
@@ -10,50 +8,87 @@ from test.test_support import TESTFN, vereq
 # included in the profile and would appear to consume all the time.)
 ticks = 0
 
-def test_1():
+# IMPORTANT: this is an output test.  *ALL* NUMBERS in the expected
+# output are relevant.  If you change the formatting of pstats,
+# please don't just regenerate output/test_profile without checking
+# very carefully that not a single number has changed.
+
+def test_main():
     global ticks
-    ticks = 0
+    ticks = 42000
     prof = profile.Profile(timer)
-    prof.runctx("testfunc()", globals(), globals())
-    prof.print_stats()
+    prof.runctx("testfunc()", globals(), locals())
+    assert ticks == 43000, ticks
+    st = pstats.Stats(prof)
+    st.strip_dirs().sort_stats('stdname').print_stats()
+    st.print_callees()
+    st.print_callers()
 
 def timer():
     return ticks*0.001
 
 def testfunc():
     # 1 call
-    # 1000 ticks total: 400 ticks local, 600 ticks in subfunctions
+    # 1000 ticks total: 270 ticks local, 730 ticks in subfunctions
     global ticks
-    ticks += 199
+    ticks += 99
     helper()                            # 300
     helper()                            # 300
-    ticks += 201
+    ticks += 171
+    factorial(14)                       # 130
+
+def factorial(n):
+    # 23 calls total
+    # 170 ticks total, 150 ticks local
+    # 3 primitive calls, 130, 20 and 20 ticks total
+    # including 116, 17, 17 ticks local
+    global ticks
+    if n > 0:
+        ticks += n
+        return mul(n, factorial(n-1))
+    else:
+        ticks += 11
+        return 1
+
+def mul(a, b):
+    # 20 calls
+    # 1 tick, local
+    global ticks
+    ticks += 1
+    return a * b
 
 def helper():
     # 2 calls
-    # 300 ticks total: 40 ticks local, 260 ticks in subfunctions
+    # 300 ticks total: 20 ticks local, 260 ticks in subfunctions
     global ticks
     ticks += 1
     helper1()                           # 30
-    ticks += 3
+    ticks += 2
     helper1()                           # 30
     ticks += 6
     helper2()                           # 50
-    ticks += 5
-    helper2()                           # 50
-    ticks += 4
+    ticks += 3
     helper2()                           # 50
-    ticks += 7
+    ticks += 2
     helper2()                           # 50
-    ticks += 14
+    ticks += 5
+    helper2_indirect()                  # 70
+    ticks += 1
 
 def helper1():
     # 4 calls
     # 30 ticks total: 29 ticks local, 1 tick in subfunctions
     global ticks
     ticks += 10
-    hasattr(C(), "foo")
+    hasattr(C(), "foo")                 # 1
     ticks += 19
+    lst = []
+    lst.append(42)                      # 0
+    sys.exc_info()                      # 0
+
+def helper2_indirect():
+    helper2()                           # 50
+    factorial(3)                        # 20
 
 def helper2():
     # 8 calls
@@ -70,7 +105,7 @@ def subhelper():
     # 10 ticks total: 8 ticks local, 2 ticks in subfunctions
     global ticks
     ticks += 2
-    for i in range(2):
+    for i in range(2):                  # 0
         try:
             C().foo                     # 1 x 2
         except AttributeError:
@@ -84,36 +119,5 @@ class C:
         ticks += 1
         raise AttributeError
 
-
-def test_2():
-    d = globals().copy()
-    def testfunc():
-        global x
-        x = 1
-    d['testfunc'] = testfunc
-    profile.runctx("testfunc()", d, d, TESTFN)
-    vereq (x, 1)
-    os.unlink (TESTFN)
-
-def test_3():
-    result = []
-    def testfunc1():
-        try: len(None)
-        except: pass
-        try: len(None)
-        except: pass
-        result.append(True)
-    def testfunc2():
-        testfunc1()
-        testfunc1()
-    profile.runctx("testfunc2()", locals(), locals(), TESTFN)
-    vereq(result, [True, True])
-    os.unlink(TESTFN)
-
-def test_main():
-    test_1()
-    test_2()
-    test_3()
-
 if __name__ == "__main__":
     test_main()

Misc/NEWS

@@ -2019,6 +2019,11 @@ Extension modules
 Library
 -------
 
+- Added a new module: cProfile, a C profiler with the same interface as the
+  profile module.  cProfile avoids some of the drawbacks of the hotshot
+  profiler and provides a bit more information than the other two profilers.
+  Based on "lsprof" (patch #1212837).
+
 - Bug #1266283: The new function "lexists" is now in os.path.__all__.
 
 - Bug #981530: Fix UnboundLocalError in shutil.rmtree().  This affects

Modules/rotatingtree.c

+#include "rotatingtree.h"
+
+#define KEY_LOWER_THAN(key1, key2)  ((char*)(key1) < (char*)(key2))
+
+/* The randombits() function below is a fast-and-dirty generator that
+ * is probably irregular enough for our purposes.  Note that it's biased:
+ * I think that ones are slightly more probable than zeroes.  It's not
+ * important here, though.
+ */
+
+static unsigned int random_value = 1;
+static unsigned int random_stream = 0;
+
+static int
+randombits(int bits)
+{
+	int result;
+	if (random_stream < (1<<bits)) {
+		random_value *= 1082527;
+		random_stream = random_value;
+	}
+	result = random_stream & ((1<<bits)-1);
+	random_stream >>= bits;
+	return result;
+}
+
+
+/* Insert a new node into the tree.
+   (*root) is modified to point to the new root. */
+void
+RotatingTree_Add(rotating_node_t **root, rotating_node_t *node)
+{
+	while (*root != NULL) {
+		if (KEY_LOWER_THAN(node->key, (*root)->key))
+			root = &((*root)->left);
+		else
+			root = &((*root)->right);
+	}
+	node->left = NULL;
+	node->right = NULL;
+	*root = node;
+}
+
+/* Locate the node with the given key.  This is the most complicated
+   function because it occasionally rebalances the tree to move the
+   resulting node closer to the root. */
+rotating_node_t *
+RotatingTree_Get(rotating_node_t **root, void *key)
+{
+	if (randombits(3) != 4) {
+		/* Fast path, no rebalancing */
+		rotating_node_t *node = *root;
+		while (node != NULL) {
+			if (node->key == key)
+				return node;
+			if (KEY_LOWER_THAN(key, node->key))
+				node = node->left;
+			else
+				node = node->right;
+		}
+		return NULL;
+	}
+	else {
+		rotating_node_t **pnode = root;
+		rotating_node_t *node = *pnode;
+		rotating_node_t *next;
+		int rotate;
+		if (node == NULL)
+			return NULL;
+		while (1) {
+			if (node->key == key)
+				return node;
+			rotate = !randombits(1);
+			if (KEY_LOWER_THAN(key, node->key)) {
+				next = node->left;
+				if (next == NULL)
+					return NULL;
+				if (rotate) {
+					node->left = next->right;
+					next->right = node;
+					*pnode = next;
+				}
+				else
+					pnode = &(node->left);
+			}
+			else {
+				next = node->right;
+				if (next == NULL)
+					return NULL;
+				if (rotate) {
+					node->right = next->left;
+					next->left = node;
+					*pnode = next;
+				}
+				else
+					pnode = &(node->right);
+			}
+			node = next;
+		}
+	}
+}
+
+/* Enumerate all nodes in the tree.  The callback enumfn() should return
+   zero to continue the enumeration, or non-zero to interrupt it.
+   A non-zero value is directly returned by RotatingTree_Enum(). */
+int
+RotatingTree_Enum(rotating_node_t *root, rotating_tree_enum_fn enumfn,
+		  void *arg)
+{
+	int result;
+	rotating_node_t *node;
+	while (root != NULL) {
+		result = RotatingTree_Enum(root->left, enumfn, arg);
+		if (result != 0) return result;
+		node = root->right;
+		result = enumfn(root, arg);
+		if (result != 0) return result;
+		root = node;
+	}
+	return 0;
+}

Modules/rotatingtree.h

+/* "Rotating trees" (Armin Rigo)
+ *
+ * Google "splay trees" for the general idea.
+ *
+ * It's a dict-like data structure that works best when accesses are not
+ * random, but follow a strong pattern.  The one implemented here is for
+ * accesses patterns where the same small set of keys is looked up over
+ * and over again, and this set of keys evolves slowly over time.
+ */
+
+#include <stdlib.h>
+
+#define EMPTY_ROTATING_TREE       ((rotating_node_t *)NULL)
+
+typedef struct rotating_node_s rotating_node_t;
+typedef int (*rotating_tree_enum_fn) (rotating_node_t *node, void *arg);
+
+struct rotating_node_s {
+	void *key;
+	rotating_node_t *left;
+	rotating_node_t *right;
+};
+
+void RotatingTree_Add(rotating_node_t **root, rotating_node_t *node);
+rotating_node_t* RotatingTree_Get(rotating_node_t **root, void *key);
+int RotatingTree_Enum(rotating_node_t *root, rotating_tree_enum_fn enumfn,
+		      void *arg);

setup.py

@@ -328,7 +328,6 @@ class PyBuildExt(build_ext):
         # Some modules that are normally always on:
         exts.append( Extension('regex', ['regexmodule.c', 'regexpr.c']) )
 
-        exts.append( Extension('_hotshot', ['_hotshot.c']) )
         exts.append( Extension('_weakref', ['_weakref.c']) )
 
         # array objects
@@ -363,6 +362,9 @@ class PyBuildExt(build_ext):
         exts.append( Extension("functional", ["functionalmodule.c"]) )
         # Python C API test module
         exts.append( Extension('_testcapi', ['_testcapimodule.c']) )
+        # profilers (_lsprof is for cProfile.py)
+        exts.append( Extension('_hotshot', ['_hotshot.c']) )
+        exts.append( Extension('_lsprof', ['_lsprof.c', 'rotatingtree.c']) )
         # static Unicode character database
         if have_unicode:
             exts.append( Extension('unicodedata', ['unicodedata.c']) )