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!
diff --git a/Lib/cProfile.py b/Lib/cProfile.py
new file mode 100755
index 0000000..19d5804
--- /dev/null
+++ b/Lib/cProfile.py
@@ -0,0 +1,190 @@
+#! /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()
diff --git a/Lib/pstats.py b/Lib/pstats.py
index 98f351f..930cc6d 100644
--- a/Lib/pstats.py
+++ b/Lib/pstats.py
@@ -371,27 +371,47 @@
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
+ # 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):
- print func_std_string(source).ljust(name_size),
+ 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 @@
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.
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
diff --git a/Lib/test/test_cProfile.py b/Lib/test/test_cProfile.py
new file mode 100644
index 0000000..07b2a9b
--- /dev/null
+++ b/Lib/test/test_cProfile.py
@@ -0,0 +1,123 @@
+"""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()
diff --git a/Lib/test/test_profile.py b/Lib/test/test_profile.py
index aa0f26c..95ad8d2 100644
--- a/Lib/test/test_profile.py
+++ b/Lib/test/test_profile.py
@@ -1,8 +1,6 @@
"""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 @@
# 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 += 3
+ helper2() # 50
+ ticks += 2
+ helper2() # 50
ticks += 5
- helper2() # 50
- ticks += 4
- helper2() # 50
- ticks += 7
- helper2() # 50
- ticks += 14
+ 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 @@
# 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 @@
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()