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!

2 files changed, 150 insertions, 7 deletions

diff --git a/Lib/test/output/test_cProfile b/Lib/test/output/test_cProfile
new file mode 100644
index 0000000..fff3568
--- /dev/null
+++ b/Lib/test/output/test_cProfile
@@ -0,0 +1,79 @@
+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)
+
+
diff --git a/Lib/test/output/test_profile b/Lib/test/output/test_profile
index e745075..96bd77f 100644
--- a/Lib/test/output/test_profile
+++ b/Lib/test/output/test_profile
@@ -1,20 +1,84 @@
 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