diff options
| -rw-r--r-- | Lib/test/output/test_profile | 84 | ||||
| -rw-r--r-- | Lib/test/profilee.py | 115 | ||||
| -rwxr-xr-x[-rw-r--r--] | Lib/test/test_cprofile.py | 308 | ||||
| -rwxr-xr-x[-rw-r--r--] | Lib/test/test_profile.py | 271 | ||||
| -rw-r--r-- | Lib/test/test_queue.py | 36 | ||||
| -rw-r--r-- | Misc/NEWS | 2 |
6 files changed, 400 insertions, 416 deletions
diff --git a/Lib/test/output/test_profile b/Lib/test/output/test_profile deleted file mode 100644 index 96bd77f..0000000 --- a/Lib/test/output/test_profile +++ /dev/null @@ -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 - - diff --git a/Lib/test/profilee.py b/Lib/test/profilee.py new file mode 100644 index 0000000..6ad2c83 --- /dev/null +++ b/Lib/test/profilee.py @@ -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 diff --git a/Lib/test/test_cprofile.py b/Lib/test/test_cprofile.py index fdbd542..7ed6cec 100644..100755 --- a/Lib/test/test_cprofile.py +++ b/Lib/test/test_cprofile.py @@ -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 - -################################# -# 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 - -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 +from test.test_profile import ProfileTest, regenerate_expected_output + +class CProfileTest(ProfileTest): + profilerclass = cProfile.Profile + 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() diff --git a/Lib/test/test_profile.py b/Lib/test/test_profile.py index 95ad8d2..c8281c3 100644..100755 --- a/Lib/test/test_profile.py +++ b/Lib/test/test_profile.py @@ -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 -# 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 +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') -# 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 - -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 + 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 + + +""" if __name__ == "__main__": - test_main() + main() diff --git a/Lib/test/test_queue.py b/Lib/test/test_queue.py index fdee1fa..eaedebc 100644 --- a/Lib/test/test_queue.py +++ b/Lib/test/test_queue.py @@ -9,6 +9,10 @@ from test import test_support 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 @@ class BaseQueueTest(unittest.TestCase, BlockingTestMixin): 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 @@ class BaseQueueTest(unittest.TestCase, BlockingTestMixin): "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 @@ class BaseQueueTest(unittest.TestCase, BlockingTestMixin): # 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 FailingQueue(Queue.Queue): 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 @@ class FailingQueueTest(unittest.TestCase, BlockingTestMixin): 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 @@ class FailingQueueTest(unittest.TestCase, BlockingTestMixin): # 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 @@ class FailingQueueTest(unittest.TestCase, BlockingTestMixin): 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 @@ class FailingQueueTest(unittest.TestCase, BlockingTestMixin): 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. @@ -1287,6 +1287,8 @@ Extension Modules 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. |