Hopefully fix the profiler right. Add a test suite that checks that
it deals correctly with some anomalous cases; according to this test
suite I've fixed it right.
The anomalous cases had to do with 'exception' events: these aren't
generated when they would be most helpful, and the profiler has to
work hard to recover the right information. The problems occur when C
code (such as hasattr(), which is used as the example here) calls back
into Python code and clears an exception raised by that Python code.
Consider this example:
def foo():
hasattr(obj, "bar")
Where obj is an instance from a class like this:
class C:
def __getattr__(self, name):
raise AttributeError
The profiler sees the following sequence of events:
call (foo)
call (__getattr__)
exception (in __getattr__)
return (from foo)
Previously, the profiler would assume the return event returned from
__getattr__. An if statement checking for this condition and raising
an exception was commented out... This version does the right thing.
diff --git a/Lib/test/output/test_profile b/Lib/test/output/test_profile
new file mode 100644
index 0000000..b36a016
--- /dev/null
+++ b/Lib/test/output/test_profile
@@ -0,0 +1,17 @@
+test_profile
+ 53 function 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(?)
+ 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:21(testfunc)
+ 2 0.080 0.040 0.600 0.300 test_profile.py:30(helper)
+ 4 0.116 0.029 0.120 0.030 test_profile.py:48(helper1)
+ 8 0.312 0.039 0.400 0.050 test_profile.py:56(helper2)
+ 8 0.064 0.008 0.080 0.010 test_profile.py:66(subhelper)
+ 28 0.028 0.001 0.028 0.001 test_profile.py:78(__getattr__)
+
+
diff --git a/Lib/test/test_profile.py b/Lib/test/test_profile.py
new file mode 100644
index 0000000..460d56f
--- /dev/null
+++ b/Lib/test/test_profile.py
@@ -0,0 +1,86 @@
+"""Test suite for the profile module."""
+
+import profile
+
+# 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
+
+def test_main():
+ global ticks
+ ticks = 0
+ prof = profile.Profile(timer)
+ prof.runctx("testfunc()", globals(), globals())
+ prof.print_stats()
+
+def timer():
+ return ticks*0.001
+
+def testfunc():
+ # 1 call
+ # 1000 ticks total: 400 ticks local, 600 ticks in subfunctions
+ global ticks
+ ticks += 199
+ helper() # 300
+ helper() # 300
+ ticks += 201
+
+def helper():
+ # 2 calls
+ # 300 ticks total: 40 ticks local, 260 ticks in subfunctions
+ global ticks
+ ticks += 1
+ helper1() # 30
+ ticks += 3
+ helper1() # 30
+ ticks += 6
+ helper2() # 50
+ ticks += 5
+ helper2() # 50
+ ticks += 4
+ helper2() # 50
+ ticks += 7
+ helper2() # 50
+ ticks += 14
+
+def helper1():
+ # 4 calls
+ # 30 ticks total: 29 ticks local, 1 tick in subfunctions
+ global ticks
+ ticks += 10
+ hasattr(C(), "foo")
+ ticks += 19
+
+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):
+ 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()