Mirror
/
cpython
mirror of https://github.com/python/cpython
4
1
Fork 0
Code Issues Releases Wiki Activity

* 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.
This commit is contained in:
Georg Brandl 2008-02-05 19:58:17 +00:00
parent 3c0f309fd1
commit b70907796a
6 changed files with 390 additions and 406 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

84
Lib/test/output/test_profile
View 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

115
Lib/test/profilee.py Normal file
View File

@ -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

304
Lib/test/test_cprofile.py Normal file → Executable file
View File

@ -1,208 +1,112 @@
"""Test suite for the cProfile module."""
import sys import sys
from test.test_support import run_unittest
# rip off all interesting stuff from test_profile
import cProfile import cProfile
import pstats from test.test_profile import ProfileTest, regenerate_expected_output
import test.test_support
################################# class CProfileTest(ProfileTest):
# Warning! profilerclass = cProfile.Profile
# 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
def test_main(): def test_main():
""" run_unittest(CProfileTest)
>>> prof = cProfile.Profile(timer, 0.001)
>>> prof.runctx("testfunc()", globals(), locals()) #doctest: +ELLIPSIS def main():
<cProfile.Profile object at ...> if '-r' not in sys.argv:
>>> timer() test_main()
43000 else:
>>> stats = pstats.Stats(prof) regenerate_expected_output(__file__, CProfileTest)
>>> stats.strip_dirs().sort_stats("stdname") #doctest: +ELLIPSIS
<pstats.Stats ...>
>>> stats.print_stats() #doctest: +ELLIPSIS # Don't remove this comment. Everything below it is auto-generated.
126 function calls (106 primitive calls) in 1.000 CPU seconds #--cut--------------------------------------------------------------------------
<BLANKLINE> CProfileTest.expected_output['print_stats'] = """\
Ordered by: standard name 126 function calls (106 primitive calls) in 1.000 CPU seconds
<BLANKLINE>
ncalls tottime percall cumtime percall filename:lineno(function) Ordered by: standard name
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__) ncalls tottime percall cumtime percall filename:lineno(function)
1 0.270 0.270 1.000 1.000 test_cprofile.py:17(testfunc) 1 0.000 0.000 1.000 1.000 <string>:1(<module>)
23/3 0.150 0.007 0.170 0.057 test_cprofile.py:27(factorial) 28 0.028 0.001 0.028 0.001 profilee.py:110(__getattr__)
20 0.020 0.001 0.020 0.001 test_cprofile.py:40(mul) 1 0.270 0.270 1.000 1.000 profilee.py:25(testfunc)
2 0.040 0.020 0.600 0.300 test_cprofile.py:47(helper) 23/3 0.150 0.007 0.170 0.057 profilee.py:35(factorial)
4 0.116 0.029 0.120 0.030 test_cprofile.py:65(helper1) 20 0.020 0.001 0.020 0.001 profilee.py:48(mul)
2 0.000 0.000 0.140 0.070 test_cprofile.py:76(helper2_indirect) 2 0.040 0.020 0.600 0.300 profilee.py:55(helper)
8 0.312 0.039 0.400 0.050 test_cprofile.py:80(helper2) 4 0.116 0.029 0.120 0.030 profilee.py:73(helper1)
8 0.064 0.008 0.080 0.010 test_cprofile.py:90(subhelper) 2 0.000 0.000 0.140 0.070 profilee.py:84(helper2_indirect)
12 0.000 0.000 0.012 0.001 {hasattr} 8 0.312 0.039 0.400 0.050 profilee.py:88(helper2)
4 0.000 0.000 0.000 0.000 {method 'append' of 'list' objects} 8 0.064 0.008 0.080 0.010 profilee.py:98(subhelper)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 12 0.000 0.000 0.012 0.001 {hasattr}
8 0.000 0.000 0.000 0.000 {range} 4 0.000 0.000 0.000 0.000 {method 'append' of 'list' objects}
4 0.000 0.000 0.000 0.000 {sys.exc_info} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
<BLANKLINE> 8 0.000 0.000 0.000 0.000 {range}
<BLANKLINE> 4 0.000 0.000 0.000 0.000 {sys.exc_info}
<pstats.Stats instance at ...>
>>> stats.print_callers() #doctest: +ELLIPSIS
Ordered by: standard name """
<BLANKLINE> CProfileTest.expected_output['print_callers'] = """\
Function was called by... Ordered by: standard name
ncalls tottime cumtime
<string>:1(<module>) <- Function was called by...
test_cprofile.py:102(__getattr__) <- 16 0.016 0.016 test_cprofile.py:90(subhelper) ncalls tottime cumtime
12 0.012 0.012 {hasattr} <string>:1(<module>) <-
test_cprofile.py:17(testfunc) <- 1 0.270 1.000 <string>:1(<module>) profilee.py:110(__getattr__) <- 16 0.016 0.016 profilee.py:98(subhelper)
test_cprofile.py:27(factorial) <- 1 0.014 0.130 test_cprofile.py:17(testfunc) 12 0.012 0.012 {hasattr}
20/3 0.130 0.147 test_cprofile.py:27(factorial) profilee.py:25(testfunc) <- 1 0.270 1.000 <string>:1(<module>)
2 0.006 0.040 test_cprofile.py:76(helper2_indirect) profilee.py:35(factorial) <- 1 0.014 0.130 profilee.py:25(testfunc)
test_cprofile.py:40(mul) <- 20 0.020 0.020 test_cprofile.py:27(factorial) 20/3 0.130 0.147 profilee.py:35(factorial)
test_cprofile.py:47(helper) <- 2 0.040 0.600 test_cprofile.py:17(testfunc) 2 0.006 0.040 profilee.py:84(helper2_indirect)
test_cprofile.py:65(helper1) <- 4 0.116 0.120 test_cprofile.py:47(helper) profilee.py:48(mul) <- 20 0.020 0.020 profilee.py:35(factorial)
test_cprofile.py:76(helper2_indirect) <- 2 0.000 0.140 test_cprofile.py:47(helper) profilee.py:55(helper) <- 2 0.040 0.600 profilee.py:25(testfunc)
test_cprofile.py:80(helper2) <- 6 0.234 0.300 test_cprofile.py:47(helper) profilee.py:73(helper1) <- 4 0.116 0.120 profilee.py:55(helper)
2 0.078 0.100 test_cprofile.py:76(helper2_indirect) profilee.py:84(helper2_indirect) <- 2 0.000 0.140 profilee.py:55(helper)
test_cprofile.py:90(subhelper) <- 8 0.064 0.080 test_cprofile.py:80(helper2) profilee.py:88(helper2) <- 6 0.234 0.300 profilee.py:55(helper)
{hasattr} <- 4 0.000 0.004 test_cprofile.py:65(helper1) 2 0.078 0.100 profilee.py:84(helper2_indirect)
8 0.000 0.008 test_cprofile.py:80(helper2) profilee.py:98(subhelper) <- 8 0.064 0.080 profilee.py:88(helper2)
{method 'append' of 'list' objects} <- 4 0.000 0.000 test_cprofile.py:65(helper1) {hasattr} <- 4 0.000 0.004 profilee.py:73(helper1)
{method 'disable' of '_lsprof.Profiler' objects} <- 8 0.000 0.008 profilee.py:88(helper2)
{range} <- 8 0.000 0.000 test_cprofile.py:90(subhelper) {method 'append' of 'list' objects} <- 4 0.000 0.000 profilee.py:73(helper1)
{sys.exc_info} <- 4 0.000 0.000 test_cprofile.py:65(helper1) {method 'disable' of '_lsprof.Profiler' objects} <-
<BLANKLINE> {range} <- 8 0.000 0.000 profilee.py:98(subhelper)
<BLANKLINE> {sys.exc_info} <- 4 0.000 0.000 profilee.py:73(helper1)
<pstats.Stats instance at ...>
>>> stats.print_callees() #doctest: +ELLIPSIS
Ordered by: standard name """
<BLANKLINE> CProfileTest.expected_output['print_callees'] = """\
Function called... Ordered by: standard name
ncalls tottime cumtime
<string>:1(<module>) -> 1 0.270 1.000 test_cprofile.py:17(testfunc) Function called...
test_cprofile.py:102(__getattr__) -> ncalls tottime cumtime
test_cprofile.py:17(testfunc) -> 1 0.014 0.130 test_cprofile.py:27(factorial) <string>:1(<module>) -> 1 0.270 1.000 profilee.py:25(testfunc)
2 0.040 0.600 test_cprofile.py:47(helper) profilee.py:110(__getattr__) ->
test_cprofile.py:27(factorial) -> 20/3 0.130 0.147 test_cprofile.py:27(factorial) profilee.py:25(testfunc) -> 1 0.014 0.130 profilee.py:35(factorial)
20 0.020 0.020 test_cprofile.py:40(mul) 2 0.040 0.600 profilee.py:55(helper)
test_cprofile.py:40(mul) -> profilee.py:35(factorial) -> 20/3 0.130 0.147 profilee.py:35(factorial)
test_cprofile.py:47(helper) -> 4 0.116 0.120 test_cprofile.py:65(helper1) 20 0.020 0.020 profilee.py:48(mul)
2 0.000 0.140 test_cprofile.py:76(helper2_indirect) profilee.py:48(mul) ->
6 0.234 0.300 test_cprofile.py:80(helper2) profilee.py:55(helper) -> 4 0.116 0.120 profilee.py:73(helper1)
test_cprofile.py:65(helper1) -> 4 0.000 0.004 {hasattr} 2 0.000 0.140 profilee.py:84(helper2_indirect)
4 0.000 0.000 {method 'append' of 'list' objects} 6 0.234 0.300 profilee.py:88(helper2)
4 0.000 0.000 {sys.exc_info} profilee.py:73(helper1) -> 4 0.000 0.004 {hasattr}
test_cprofile.py:76(helper2_indirect) -> 2 0.006 0.040 test_cprofile.py:27(factorial) 4 0.000 0.000 {method 'append' of 'list' objects}
2 0.078 0.100 test_cprofile.py:80(helper2) 4 0.000 0.000 {sys.exc_info}
test_cprofile.py:80(helper2) -> 8 0.064 0.080 test_cprofile.py:90(subhelper) profilee.py:84(helper2_indirect) -> 2 0.006 0.040 profilee.py:35(factorial)
8 0.000 0.008 {hasattr} 2 0.078 0.100 profilee.py:88(helper2)
test_cprofile.py:90(subhelper) -> 16 0.016 0.016 test_cprofile.py:102(__getattr__) profilee.py:88(helper2) -> 8 0.064 0.080 profilee.py:98(subhelper)
8 0.000 0.000 {range} 8 0.000 0.008 {hasattr}
{hasattr} -> 12 0.012 0.012 test_cprofile.py:102(__getattr__) profilee.py:98(subhelper) -> 16 0.016 0.016 profilee.py:110(__getattr__)
{method 'append' of 'list' objects} -> 8 0.000 0.000 {range}
{method 'disable' of '_lsprof.Profiler' objects} -> {hasattr} -> 12 0.012 0.012 profilee.py:110(__getattr__)
{range} -> {method 'append' of 'list' objects} ->
{sys.exc_info} -> {method 'disable' of '_lsprof.Profiler' objects} ->
<BLANKLINE> {range} ->
<BLANKLINE> {sys.exc_info} ->
<pstats.Stats instance at ...>
"""
from test import test_cprofile """
test.test_support.run_doctest(test_cprofile)
if __name__ == "__main__": if __name__ == "__main__":
test_main() main()

255
Lib/test/test_profile.py Normal file → Executable file
View File

@ -1,123 +1,166 @@
"""Test suite for the profile module.""" """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 import profile
# variable 'ticks', which represents simulated time in milliseconds. from test.profilee import testfunc, timer
# (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 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(): def test_main():
global ticks run_unittest(ProfileTest)
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(): def main():
return ticks*0.001 if '-r' not in sys.argv:
test_main()
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: else:
ticks += 11 regenerate_expected_output(__file__, ProfileTest)
return 1
def mul(a, b):
# 20 calls
# 1 tick, local
global ticks
ticks += 1
return a * b
def helper(): # Don't remove this comment. Everything below it is auto-generated.
# 2 calls #--cut--------------------------------------------------------------------------
# 300 ticks total: 20 ticks local, 260 ticks in subfunctions ProfileTest.expected_output['print_stats'] = """\
global ticks 127 function calls (107 primitive calls) in 999.749 CPU seconds
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(): Ordered by: standard name
# 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(): ncalls tottime percall cumtime percall filename:lineno(function)
helper2() # 50 4 -0.004 -0.001 -0.004 -0.001 :0(append)
factorial(3) # 20 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)
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 ProfileTest.expected_output['print_callers'] = """\
# 10 ticks total: 8 ticks local, 2 ticks in subfunctions Ordered by: standard name
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: Function was called by...
def __getattr__(self, name): :0(append) <- profilee.py:73(helper1)(4) 119.964
# 28 calls :0(exc_info) <- profilee.py:73(helper1)(4) 119.964
# 1 tick, local :0(hasattr) <- profilee.py:73(helper1)(4) 119.964
global ticks profilee.py:88(helper2)(8) 399.896
ticks += 1 :0(range) <- profilee.py:98(subhelper)(8) 79.944
raise AttributeError :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__": if __name__ == "__main__":
test_main() main()

36
Lib/test/test_queue.py
View File

@ -9,6 +9,10 @@ from test import test_support
QUEUE_SIZE = 5 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. # A thread to run a function that unclogs a blocked Queue.
class _TriggerThread(threading.Thread): class _TriggerThread(threading.Thread):
def __init__(self, fn, args): def __init__(self, fn, args):
@ -86,7 +90,7 @@ class BaseQueueTest(unittest.TestCase, BlockingTestMixin):
self.cumlock = threading.Lock() self.cumlock = threading.Lock()
def simple_queue_test(self, q): def simple_queue_test(self, q):
if not q.empty(): if q.qsize():
raise RuntimeError, "Call this function with an empty queue" raise RuntimeError, "Call this function with an empty queue"
# I guess we better check things actually queue correctly a little :) # I guess we better check things actually queue correctly a little :)
q.put(111) q.put(111)
@ -100,10 +104,10 @@ class BaseQueueTest(unittest.TestCase, BlockingTestMixin):
"Didn't seem to queue the correct data!") "Didn't seem to queue the correct data!")
for i in range(QUEUE_SIZE-1): for i in range(QUEUE_SIZE-1):
q.put(i) q.put(i)
self.assert_(not q.empty(), "Queue should not be empty") self.assert_(q.qsize(), "Queue should not be empty")
self.assert_(not q.full(), "Queue should not be full") self.assert_(not qfull(q), "Queue should not be full")
q.put("last") q.put("last")
self.assert_(q.full(), "Queue should be full") self.assert_(qfull(q), "Queue should be full")
try: try:
q.put("full", block=0) q.put("full", block=0)
self.fail("Didn't appear to block with a full queue") self.fail("Didn't appear to block with a full queue")
@ -120,7 +124,7 @@ class BaseQueueTest(unittest.TestCase, BlockingTestMixin):
# Empty it # Empty it
for i in range(QUEUE_SIZE): for i in range(QUEUE_SIZE):
q.get() q.get()
self.assert_(q.empty(), "Queue should be empty") self.assert_(not q.qsize(), "Queue should be empty")
try: try:
q.get(block=0) q.get(block=0)
self.fail("Didn't appear to block with an empty queue") self.fail("Didn't appear to block with an empty queue")
@ -224,7 +228,7 @@ class FailingQueue(Queue.Queue):
class FailingQueueTest(unittest.TestCase, BlockingTestMixin): class FailingQueueTest(unittest.TestCase, BlockingTestMixin):
def failing_queue_test(self, q): def failing_queue_test(self, q):
if not q.empty(): if q.qsize():
raise RuntimeError, "Call this function with an empty queue" raise RuntimeError, "Call this function with an empty queue"
for i in range(QUEUE_SIZE-1): for i in range(QUEUE_SIZE-1):
q.put(i) q.put(i)
@ -242,7 +246,7 @@ class FailingQueueTest(unittest.TestCase, BlockingTestMixin):
except FailingQueueException: except FailingQueueException:
pass pass
q.put("last") q.put("last")
self.assert_(q.full(), "Queue should be full") self.assert_(qfull(q), "Queue should be full")
# Test a failing blocking put # Test a failing blocking put
q.fail_next_put = True q.fail_next_put = True
try: try:
@ -264,17 +268,17 @@ class FailingQueueTest(unittest.TestCase, BlockingTestMixin):
# Check the Queue isn't damaged. # Check the Queue isn't damaged.
# put failed, but get succeeded - re-add # put failed, but get succeeded - re-add
q.put("last") q.put("last")
self.assert_(q.full(), "Queue should be full") self.assert_(qfull(q), "Queue should be full")
q.get() 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") q.put("last")
self.assert_(q.full(), "Queue should be full") self.assert_(qfull(q), "Queue should be full")
# Test a blocking put # Test a blocking put
self.do_blocking_test(q.put, ("full",), q.get, ()) self.do_blocking_test(q.put, ("full",), q.get, ())
# Empty it # Empty it
for i in range(QUEUE_SIZE): for i in range(QUEUE_SIZE):
q.get() q.get()
self.assert_(q.empty(), "Queue should be empty") self.assert_(not q.qsize(), "Queue should be empty")
q.put("first") q.put("first")
q.fail_next_get = True q.fail_next_get = True
try: try:
@ -282,16 +286,16 @@ class FailingQueueTest(unittest.TestCase, BlockingTestMixin):
self.fail("The queue didn't fail when it should have") self.fail("The queue didn't fail when it should have")
except FailingQueueException: except FailingQueueException:
pass 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 q.fail_next_get = True
try: try:
q.get(timeout=0.1) q.get(timeout=0.1)
self.fail("The queue didn't fail when it should have") self.fail("The queue didn't fail when it should have")
except FailingQueueException: except FailingQueueException:
pass pass
self.assert_(not q.empty(), "Queue should not be empty") self.assert_(q.qsize(), "Queue should not be empty")
q.get() q.get()
self.assert_(q.empty(), "Queue should be empty") self.assert_(not q.qsize(), "Queue should be empty")
q.fail_next_get = True q.fail_next_get = True
try: try:
self.do_exceptional_blocking_test(q.get, (), q.put, ('empty',), self.do_exceptional_blocking_test(q.get, (), q.put, ('empty',),
@ -300,9 +304,9 @@ class FailingQueueTest(unittest.TestCase, BlockingTestMixin):
except FailingQueueException: except FailingQueueException:
pass pass
# put succeeded, but get failed. # 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() q.get()
self.assert_(q.empty(), "Queue should be empty") self.assert_(not q.qsize(), "Queue should be empty")
def test_failing_queue(self): def test_failing_queue(self):
# Test to make sure a queue is functioning correctly. # Test to make sure a queue is functioning correctly.

2
Misc/NEWS
View File

@ -1287,6 +1287,8 @@ Extension Modules
Tests 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 - 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 being tested. Was causing an error by __import__ doing a reload on the
second run and thus suppressing bytecode recreation. second run and thus suppressing bytecode recreation.