[Python-checkins] r60605 - in python/trunk: Lib/test/output/test_profile Lib/test/profilee.py Lib/test/test_cprofile.py Lib/test/test_profile.py Lib/test/test_queue.py Misc/NEWS
georg.brandl
python-checkins at python.org
Tue Feb 5 20:58:18 CET 2008
Author: georg.brandl
Date: Tue Feb 5 20:58:17 2008
New Revision: 60605
Added:
python/trunk/Lib/test/profilee.py
Removed:
python/trunk/Lib/test/output/test_profile
Modified:
python/trunk/Lib/test/test_cprofile.py (contents, props changed)
python/trunk/Lib/test/test_profile.py (contents, props changed)
python/trunk/Lib/test/test_queue.py
python/trunk/Misc/NEWS
Log:
* Use the same code to profile for test_profile and test_cprofile.
* Convert both to unittest.
* Use the same unit testing code.
* Include the expected output in both test files.
* Make it possible to regenerate the expected output by running
the file as a script with an '-r' argument.
Deleted: /python/trunk/Lib/test/output/test_profile
==============================================================================
--- /python/trunk/Lib/test/output/test_profile Tue Feb 5 20:58:17 2008
+++ (empty file)
@@ -1,84 +0,0 @@
-test_profile
- 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())
- 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
-
-
Added: python/trunk/Lib/test/profilee.py
==============================================================================
--- (empty file)
+++ python/trunk/Lib/test/profilee.py Tue Feb 5 20:58:17 2008
@@ -0,0 +1,115 @@
+"""
+Input for test_profile.py and test_cprofile.py.
+
+IMPORTANT: This stuff is touchy. If you modify anything above the
+test class you'll have to regenerate the stats by running the two
+test files.
+
+*ALL* NUMBERS in the expected output are relevant. If you change
+the formatting of pstats, please don't just regenerate the expected
+output without checking very carefully that not a single number has
+changed.
+"""
+
+import 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 = 42000
+
+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
Modified: python/trunk/Lib/test/test_cprofile.py
==============================================================================
--- python/trunk/Lib/test/test_cprofile.py (original)
+++ python/trunk/Lib/test/test_cprofile.py Tue Feb 5 20:58:17 2008
@@ -1,208 +1,112 @@
+"""Test suite for the cProfile module."""
+
import sys
+from test.test_support import run_unittest
+
+# rip off all interesting stuff from test_profile
import cProfile
-import pstats
-import test.test_support
+from test.test_profile import ProfileTest, regenerate_expected_output
-#################################
-# Warning!
-# This stuff is touchy. If you modify anything above the test_main function,
-# you'll have to regenerate the stats for the doctest!
-################################
-
-TICKS = 42000
-
-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
+class CProfileTest(ProfileTest):
+ profilerclass = cProfile.Profile
-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
def test_main():
- """
- >>> prof = cProfile.Profile(timer, 0.001)
- >>> prof.runctx("testfunc()", globals(), locals()) #doctest: +ELLIPSIS
- <cProfile.Profile object at ...>
- >>> timer()
- 43000
- >>> stats = pstats.Stats(prof)
- >>> stats.strip_dirs().sort_stats("stdname") #doctest: +ELLIPSIS
- <pstats.Stats ...>
- >>> stats.print_stats() #doctest: +ELLIPSIS
- 126 function calls (106 primitive calls) in 1.000 CPU seconds
- <BLANKLINE>
- Ordered by: standard name
- <BLANKLINE>
- ncalls tottime percall cumtime percall filename:lineno(function)
- 1 0.000 0.000 1.000 1.000 <string>:1(<module>)
- 28 0.028 0.001 0.028 0.001 test_cprofile.py:102(__getattr__)
- 1 0.270 0.270 1.000 1.000 test_cprofile.py:17(testfunc)
- 23/3 0.150 0.007 0.170 0.057 test_cprofile.py:27(factorial)
- 20 0.020 0.001 0.020 0.001 test_cprofile.py:40(mul)
- 2 0.040 0.020 0.600 0.300 test_cprofile.py:47(helper)
- 4 0.116 0.029 0.120 0.030 test_cprofile.py:65(helper1)
- 2 0.000 0.000 0.140 0.070 test_cprofile.py:76(helper2_indirect)
- 8 0.312 0.039 0.400 0.050 test_cprofile.py:80(helper2)
- 8 0.064 0.008 0.080 0.010 test_cprofile.py:90(subhelper)
- 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}
- <BLANKLINE>
- <BLANKLINE>
- <pstats.Stats instance at ...>
- >>> stats.print_callers() #doctest: +ELLIPSIS
- Ordered by: standard name
- <BLANKLINE>
- Function was called by...
- ncalls tottime cumtime
- <string>:1(<module>) <-
- test_cprofile.py:102(__getattr__) <- 16 0.016 0.016 test_cprofile.py:90(subhelper)
- 12 0.012 0.012 {hasattr}
- test_cprofile.py:17(testfunc) <- 1 0.270 1.000 <string>:1(<module>)
- test_cprofile.py:27(factorial) <- 1 0.014 0.130 test_cprofile.py:17(testfunc)
- 20/3 0.130 0.147 test_cprofile.py:27(factorial)
- 2 0.006 0.040 test_cprofile.py:76(helper2_indirect)
- test_cprofile.py:40(mul) <- 20 0.020 0.020 test_cprofile.py:27(factorial)
- test_cprofile.py:47(helper) <- 2 0.040 0.600 test_cprofile.py:17(testfunc)
- test_cprofile.py:65(helper1) <- 4 0.116 0.120 test_cprofile.py:47(helper)
- test_cprofile.py:76(helper2_indirect) <- 2 0.000 0.140 test_cprofile.py:47(helper)
- test_cprofile.py:80(helper2) <- 6 0.234 0.300 test_cprofile.py:47(helper)
- 2 0.078 0.100 test_cprofile.py:76(helper2_indirect)
- test_cprofile.py:90(subhelper) <- 8 0.064 0.080 test_cprofile.py:80(helper2)
- {hasattr} <- 4 0.000 0.004 test_cprofile.py:65(helper1)
- 8 0.000 0.008 test_cprofile.py:80(helper2)
- {method 'append' of 'list' objects} <- 4 0.000 0.000 test_cprofile.py:65(helper1)
- {method 'disable' of '_lsprof.Profiler' objects} <-
- {range} <- 8 0.000 0.000 test_cprofile.py:90(subhelper)
- {sys.exc_info} <- 4 0.000 0.000 test_cprofile.py:65(helper1)
- <BLANKLINE>
- <BLANKLINE>
- <pstats.Stats instance at ...>
- >>> stats.print_callees() #doctest: +ELLIPSIS
- Ordered by: standard name
- <BLANKLINE>
- Function called...
- ncalls tottime cumtime
- <string>:1(<module>) -> 1 0.270 1.000 test_cprofile.py:17(testfunc)
- test_cprofile.py:102(__getattr__) ->
- test_cprofile.py:17(testfunc) -> 1 0.014 0.130 test_cprofile.py:27(factorial)
- 2 0.040 0.600 test_cprofile.py:47(helper)
- test_cprofile.py:27(factorial) -> 20/3 0.130 0.147 test_cprofile.py:27(factorial)
- 20 0.020 0.020 test_cprofile.py:40(mul)
- test_cprofile.py:40(mul) ->
- test_cprofile.py:47(helper) -> 4 0.116 0.120 test_cprofile.py:65(helper1)
- 2 0.000 0.140 test_cprofile.py:76(helper2_indirect)
- 6 0.234 0.300 test_cprofile.py:80(helper2)
- test_cprofile.py:65(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:76(helper2_indirect) -> 2 0.006 0.040 test_cprofile.py:27(factorial)
- 2 0.078 0.100 test_cprofile.py:80(helper2)
- test_cprofile.py:80(helper2) -> 8 0.064 0.080 test_cprofile.py:90(subhelper)
- 8 0.000 0.008 {hasattr}
- test_cprofile.py:90(subhelper) -> 16 0.016 0.016 test_cprofile.py:102(__getattr__)
- 8 0.000 0.000 {range}
- {hasattr} -> 12 0.012 0.012 test_cprofile.py:102(__getattr__)
- {method 'append' of 'list' objects} ->
- {method 'disable' of '_lsprof.Profiler' objects} ->
- {range} ->
- {sys.exc_info} ->
- <BLANKLINE>
- <BLANKLINE>
- <pstats.Stats instance at ...>
- """
- from test import test_cprofile
- test.test_support.run_doctest(test_cprofile)
+ run_unittest(CProfileTest)
+
+def main():
+ if '-r' not in sys.argv:
+ test_main()
+ else:
+ regenerate_expected_output(__file__, CProfileTest)
+
+
+# Don't remove this comment. Everything below it is auto-generated.
+#--cut--------------------------------------------------------------------------
+CProfileTest.expected_output['print_stats'] = """\
+ 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>)
+ 28 0.028 0.001 0.028 0.001 profilee.py:110(__getattr__)
+ 1 0.270 0.270 1.000 1.000 profilee.py:25(testfunc)
+ 23/3 0.150 0.007 0.170 0.057 profilee.py:35(factorial)
+ 20 0.020 0.001 0.020 0.001 profilee.py:48(mul)
+ 2 0.040 0.020 0.600 0.300 profilee.py:55(helper)
+ 4 0.116 0.029 0.120 0.030 profilee.py:73(helper1)
+ 2 0.000 0.000 0.140 0.070 profilee.py:84(helper2_indirect)
+ 8 0.312 0.039 0.400 0.050 profilee.py:88(helper2)
+ 8 0.064 0.008 0.080 0.010 profilee.py:98(subhelper)
+ 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}
+
+
+"""
+CProfileTest.expected_output['print_callers'] = """\
+ Ordered by: standard name
+
+Function was called by...
+ ncalls tottime cumtime
+<string>:1(<module>) <-
+profilee.py:110(__getattr__) <- 16 0.016 0.016 profilee.py:98(subhelper)
+ 12 0.012 0.012 {hasattr}
+profilee.py:25(testfunc) <- 1 0.270 1.000 <string>:1(<module>)
+profilee.py:35(factorial) <- 1 0.014 0.130 profilee.py:25(testfunc)
+ 20/3 0.130 0.147 profilee.py:35(factorial)
+ 2 0.006 0.040 profilee.py:84(helper2_indirect)
+profilee.py:48(mul) <- 20 0.020 0.020 profilee.py:35(factorial)
+profilee.py:55(helper) <- 2 0.040 0.600 profilee.py:25(testfunc)
+profilee.py:73(helper1) <- 4 0.116 0.120 profilee.py:55(helper)
+profilee.py:84(helper2_indirect) <- 2 0.000 0.140 profilee.py:55(helper)
+profilee.py:88(helper2) <- 6 0.234 0.300 profilee.py:55(helper)
+ 2 0.078 0.100 profilee.py:84(helper2_indirect)
+profilee.py:98(subhelper) <- 8 0.064 0.080 profilee.py:88(helper2)
+{hasattr} <- 4 0.000 0.004 profilee.py:73(helper1)
+ 8 0.000 0.008 profilee.py:88(helper2)
+{method 'append' of 'list' objects} <- 4 0.000 0.000 profilee.py:73(helper1)
+{method 'disable' of '_lsprof.Profiler' objects} <-
+{range} <- 8 0.000 0.000 profilee.py:98(subhelper)
+{sys.exc_info} <- 4 0.000 0.000 profilee.py:73(helper1)
+
+
+"""
+CProfileTest.expected_output['print_callees'] = """\
+ Ordered by: standard name
+
+Function called...
+ ncalls tottime cumtime
+<string>:1(<module>) -> 1 0.270 1.000 profilee.py:25(testfunc)
+profilee.py:110(__getattr__) ->
+profilee.py:25(testfunc) -> 1 0.014 0.130 profilee.py:35(factorial)
+ 2 0.040 0.600 profilee.py:55(helper)
+profilee.py:35(factorial) -> 20/3 0.130 0.147 profilee.py:35(factorial)
+ 20 0.020 0.020 profilee.py:48(mul)
+profilee.py:48(mul) ->
+profilee.py:55(helper) -> 4 0.116 0.120 profilee.py:73(helper1)
+ 2 0.000 0.140 profilee.py:84(helper2_indirect)
+ 6 0.234 0.300 profilee.py:88(helper2)
+profilee.py:73(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}
+profilee.py:84(helper2_indirect) -> 2 0.006 0.040 profilee.py:35(factorial)
+ 2 0.078 0.100 profilee.py:88(helper2)
+profilee.py:88(helper2) -> 8 0.064 0.080 profilee.py:98(subhelper)
+ 8 0.000 0.008 {hasattr}
+profilee.py:98(subhelper) -> 16 0.016 0.016 profilee.py:110(__getattr__)
+ 8 0.000 0.000 {range}
+{hasattr} -> 12 0.012 0.012 profilee.py:110(__getattr__)
+{method 'append' of 'list' objects} ->
+{method 'disable' of '_lsprof.Profiler' objects} ->
+{range} ->
+{sys.exc_info} ->
+
+
+"""
if __name__ == "__main__":
- test_main()
+ main()
Modified: python/trunk/Lib/test/test_profile.py
==============================================================================
--- python/trunk/Lib/test/test_profile.py (original)
+++ python/trunk/Lib/test/test_profile.py Tue Feb 5 20:58:17 2008
@@ -1,123 +1,166 @@
"""Test suite for the profile module."""
-import profile, pstats, sys
+import os
+import sys
+import pstats
+import unittest
+from StringIO import StringIO
+from test.test_support import run_unittest
+
+import profile
+from test.profilee import testfunc, timer
+
+
+class ProfileTest(unittest.TestCase):
+
+ profilerclass = profile.Profile
+ methodnames = ['print_stats', 'print_callers', 'print_callees']
+ expected_output = {}
+
+ @classmethod
+ def do_profiling(cls):
+ results = []
+ prof = cls.profilerclass(timer, 0.001)
+ prof.runctx("testfunc()", globals(), locals())
+ results.append(timer())
+ for methodname in cls.methodnames:
+ s = StringIO()
+ stats = pstats.Stats(prof, stream=s)
+ stats.strip_dirs().sort_stats("stdname")
+ getattr(stats, methodname)()
+ results.append(s.getvalue())
+ return results
+
+ def test_cprofile(self):
+ results = self.do_profiling()
+ self.assertEqual(results[0], 43000)
+ for i, method in enumerate(self.methodnames):
+ self.assertEqual(results[i+1], self.expected_output[method],
+ "Stats.%s output for %s doesn't fit expectation!" %
+ (method, self.profilerclass.__name__))
+
+
+def regenerate_expected_output(filename, cls):
+ filename = filename.rstrip('co')
+ print 'Regenerating %s...' % filename
+ results = cls.do_profiling()
+
+ newfile = []
+ with open(filename, 'r') as f:
+ for line in f:
+ newfile.append(line)
+ if line[:6] == '#--cut':
+ break
+
+ with open(filename, 'w') as f:
+ f.writelines(newfile)
+ for i, method in enumerate(cls.methodnames):
+ f.write('%s.expected_output[%r] = """\\\n%s"""\n' % (
+ cls.__name__, method, results[i+1]))
+ f.write('\nif __name__ == "__main__":\n main()\n')
-# 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_profile without checking
-# very carefully that not a single number has changed.
def test_main():
- global ticks
- ticks = 42000
- prof = profile.Profile(timer)
- 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: 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))
+ run_unittest(ProfileTest)
+
+def main():
+ if '-r' not in sys.argv:
+ test_main()
else:
- ticks += 11
- return 1
+ regenerate_expected_output(__file__, ProfileTest)
+
+
+# Don't remove this comment. Everything below it is auto-generated.
+#--cut--------------------------------------------------------------------------
+ProfileTest.expected_output['print_stats'] = """\
+ 127 function calls (107 primitive calls) in 999.749 CPU seconds
+
+ Ordered by: standard name
+
+ ncalls tottime percall cumtime percall filename:lineno(function)
+ 4 -0.004 -0.001 -0.004 -0.001 :0(append)
+ 4 -0.004 -0.001 -0.004 -0.001 :0(exc_info)
+ 12 -0.024 -0.002 11.964 0.997 :0(hasattr)
+ 8 -0.008 -0.001 -0.008 -0.001 :0(range)
+ 1 0.000 0.000 0.000 0.000 :0(setprofile)
+ 1 -0.002 -0.002 999.751 999.751 <string>:1(<module>)
+ 0 0.000 0.000 profile:0(profiler)
+ 1 -0.002 -0.002 999.749 999.749 profile:0(testfunc())
+ 28 27.972 0.999 27.972 0.999 profilee.py:110(__getattr__)
+ 1 269.996 269.996 999.753 999.753 profilee.py:25(testfunc)
+ 23/3 149.937 6.519 169.917 56.639 profilee.py:35(factorial)
+ 20 19.980 0.999 19.980 0.999 profilee.py:48(mul)
+ 2 39.986 19.993 599.814 299.907 profilee.py:55(helper)
+ 4 115.984 28.996 119.964 29.991 profilee.py:73(helper1)
+ 2 -0.006 -0.003 139.942 69.971 profilee.py:84(helper2_indirect)
+ 8 311.976 38.997 399.896 49.987 profilee.py:88(helper2)
+ 8 63.968 7.996 79.944 9.993 profilee.py:98(subhelper)
+
+
+"""
+ProfileTest.expected_output['print_callers'] = """\
+ Ordered by: standard name
+
+Function was called by...
+:0(append) <- profilee.py:73(helper1)(4) 119.964
+:0(exc_info) <- profilee.py:73(helper1)(4) 119.964
+:0(hasattr) <- profilee.py:73(helper1)(4) 119.964
+ profilee.py:88(helper2)(8) 399.896
+:0(range) <- profilee.py:98(subhelper)(8) 79.944
+:0(setprofile) <- profile:0(testfunc())(1) 999.749
+<string>:1(<module>) <- profile:0(testfunc())(1) 999.749
+profile:0(profiler) <-
+profile:0(testfunc()) <- profile:0(profiler)(1) 0.000
+profilee.py:110(__getattr__) <- :0(hasattr)(12) 11.964
+ profilee.py:98(subhelper)(16) 79.944
+profilee.py:25(testfunc) <- <string>:1(<module>)(1) 999.751
+profilee.py:35(factorial) <- profilee.py:25(testfunc)(1) 999.753
+ profilee.py:35(factorial)(20) 169.917
+ profilee.py:84(helper2_indirect)(2) 139.942
+profilee.py:48(mul) <- profilee.py:35(factorial)(20) 169.917
+profilee.py:55(helper) <- profilee.py:25(testfunc)(2) 999.753
+profilee.py:73(helper1) <- profilee.py:55(helper)(4) 599.814
+profilee.py:84(helper2_indirect) <- profilee.py:55(helper)(2) 599.814
+profilee.py:88(helper2) <- profilee.py:55(helper)(6) 599.814
+ profilee.py:84(helper2_indirect)(2) 139.942
+profilee.py:98(subhelper) <- profilee.py:88(helper2)(8) 399.896
+
+
+"""
+ProfileTest.expected_output['print_callees'] = """\
+ Ordered by: standard name
+
+Function called...
+:0(append) ->
+:0(exc_info) ->
+:0(hasattr) -> profilee.py:110(__getattr__)(12) 27.972
+:0(range) ->
+:0(setprofile) ->
+<string>:1(<module>) -> profilee.py:25(testfunc)(1) 999.753
+profile:0(profiler) -> profile:0(testfunc())(1) 999.749
+profile:0(testfunc()) -> :0(setprofile)(1) 0.000
+ <string>:1(<module>)(1) 999.751
+profilee.py:110(__getattr__) ->
+profilee.py:25(testfunc) -> profilee.py:35(factorial)(1) 169.917
+ profilee.py:55(helper)(2) 599.814
+profilee.py:35(factorial) -> profilee.py:35(factorial)(20) 169.917
+ profilee.py:48(mul)(20) 19.980
+profilee.py:48(mul) ->
+profilee.py:55(helper) -> profilee.py:73(helper1)(4) 119.964
+ profilee.py:84(helper2_indirect)(2) 139.942
+ profilee.py:88(helper2)(6) 399.896
+profilee.py:73(helper1) -> :0(append)(4) -0.004
+ :0(exc_info)(4) -0.004
+ :0(hasattr)(4) 11.964
+profilee.py:84(helper2_indirect) -> profilee.py:35(factorial)(2) 169.917
+ profilee.py:88(helper2)(2) 399.896
+profilee.py:88(helper2) -> :0(hasattr)(8) 11.964
+ profilee.py:98(subhelper)(8) 79.944
+profilee.py:98(subhelper) -> :0(range)(8) -0.008
+ profilee.py:110(__getattr__)(16) 27.972
+
-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()
+ main()
Modified: python/trunk/Lib/test/test_queue.py
==============================================================================
--- python/trunk/Lib/test/test_queue.py (original)
+++ python/trunk/Lib/test/test_queue.py Tue Feb 5 20:58:17 2008
@@ -9,6 +9,10 @@
QUEUE_SIZE = 5
+def qfull(q):
+ return q.maxsize > 0 and q.qsize() == q.maxsize
+
+
# A thread to run a function that unclogs a blocked Queue.
class _TriggerThread(threading.Thread):
def __init__(self, fn, args):
@@ -86,7 +90,7 @@
self.cumlock = threading.Lock()
def simple_queue_test(self, q):
- if not q.empty():
+ if q.qsize():
raise RuntimeError, "Call this function with an empty queue"
# I guess we better check things actually queue correctly a little :)
q.put(111)
@@ -100,10 +104,10 @@
"Didn't seem to queue the correct data!")
for i in range(QUEUE_SIZE-1):
q.put(i)
- self.assert_(not q.empty(), "Queue should not be empty")
- self.assert_(not q.full(), "Queue should not be full")
+ self.assert_(q.qsize(), "Queue should not be empty")
+ self.assert_(not qfull(q), "Queue should not be full")
q.put("last")
- self.assert_(q.full(), "Queue should be full")
+ self.assert_(qfull(q), "Queue should be full")
try:
q.put("full", block=0)
self.fail("Didn't appear to block with a full queue")
@@ -120,7 +124,7 @@
# Empty it
for i in range(QUEUE_SIZE):
q.get()
- self.assert_(q.empty(), "Queue should be empty")
+ self.assert_(not q.qsize(), "Queue should be empty")
try:
q.get(block=0)
self.fail("Didn't appear to block with an empty queue")
@@ -224,7 +228,7 @@
class FailingQueueTest(unittest.TestCase, BlockingTestMixin):
def failing_queue_test(self, q):
- if not q.empty():
+ if q.qsize():
raise RuntimeError, "Call this function with an empty queue"
for i in range(QUEUE_SIZE-1):
q.put(i)
@@ -242,7 +246,7 @@
except FailingQueueException:
pass
q.put("last")
- self.assert_(q.full(), "Queue should be full")
+ self.assert_(qfull(q), "Queue should be full")
# Test a failing blocking put
q.fail_next_put = True
try:
@@ -264,17 +268,17 @@
# Check the Queue isn't damaged.
# put failed, but get succeeded - re-add
q.put("last")
- self.assert_(q.full(), "Queue should be full")
+ self.assert_(qfull(q), "Queue should be full")
q.get()
- self.assert_(not q.full(), "Queue should not be full")
+ self.assert_(not qfull(q), "Queue should not be full")
q.put("last")
- self.assert_(q.full(), "Queue should be full")
+ self.assert_(qfull(q), "Queue should be full")
# Test a blocking put
self.do_blocking_test(q.put, ("full",), q.get, ())
# Empty it
for i in range(QUEUE_SIZE):
q.get()
- self.assert_(q.empty(), "Queue should be empty")
+ self.assert_(not q.qsize(), "Queue should be empty")
q.put("first")
q.fail_next_get = True
try:
@@ -282,16 +286,16 @@
self.fail("The queue didn't fail when it should have")
except FailingQueueException:
pass
- self.assert_(not q.empty(), "Queue should not be empty")
+ self.assert_(q.qsize(), "Queue should not be empty")
q.fail_next_get = True
try:
q.get(timeout=0.1)
self.fail("The queue didn't fail when it should have")
except FailingQueueException:
pass
- self.assert_(not q.empty(), "Queue should not be empty")
+ self.assert_(q.qsize(), "Queue should not be empty")
q.get()
- self.assert_(q.empty(), "Queue should be empty")
+ self.assert_(not q.qsize(), "Queue should be empty")
q.fail_next_get = True
try:
self.do_exceptional_blocking_test(q.get, (), q.put, ('empty',),
@@ -300,9 +304,9 @@
except FailingQueueException:
pass
# put succeeded, but get failed.
- self.assert_(not q.empty(), "Queue should not be empty")
+ self.assert_(q.qsize(), "Queue should not be empty")
q.get()
- self.assert_(q.empty(), "Queue should be empty")
+ self.assert_(not q.qsize(), "Queue should be empty")
def test_failing_queue(self):
# Test to make sure a queue is functioning correctly.
Modified: python/trunk/Misc/NEWS
==============================================================================
--- python/trunk/Misc/NEWS (original)
+++ python/trunk/Misc/NEWS Tue Feb 5 20:58:17 2008
@@ -1287,6 +1287,8 @@
Tests
-----
+- Refactor test_profile and test_cprofile to use the same code to profile.
+
- Make test_runpy reentrant by fixing _check_module to clear out any module
being tested. Was causing an error by __import__ doing a reload on the
second run and thus suppressing bytecode recreation.
More information about the Python-checkins
mailing list