traverseda
/
cpython
1
0
Fork 0
Code Issues Pull Requests Releases Wiki Activity
cpython/Lib/test/test_profile.py

188 lines
7.9 KiB
Python
Raw Normal View History

Hopefully fix the profiler right. Add a test suite that checks that it deals correctly with some anomalous cases; according to this test suite I've fixed it right. The anomalous cases had to do with 'exception' events: these aren't generated when they would be most helpful, and the profiler has to work hard to recover the right information. The problems occur when C code (such as hasattr(), which is used as the example here) calls back into Python code and clears an exception raised by that Python code. Consider this example: def foo(): hasattr(obj, "bar") Where obj is an instance from a class like this: class C: def __getattr__(self, name): raise AttributeError The profiler sees the following sequence of events: call (foo) call (__getattr__) exception (in __getattr__) return (from foo) Previously, the profiler would assume the return event returned from __getattr__. An if statement checking for this condition and raising an exception was commented out... This version does the right thing.
2001-10-03 21:58:24 -03:00
"""Test suite for the profile module."""
* 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.
2008-02-05 15:58:17 -04:00
import os
import sys
import pstats
import unittest
from StringIO import StringIO
from test.test_support import run_unittest
Hopefully fix the profiler right. Add a test suite that checks that it deals correctly with some anomalous cases; according to this test suite I've fixed it right. The anomalous cases had to do with 'exception' events: these aren't generated when they would be most helpful, and the profiler has to work hard to recover the right information. The problems occur when C code (such as hasattr(), which is used as the example here) calls back into Python code and clears an exception raised by that Python code. Consider this example: def foo(): hasattr(obj, "bar") Where obj is an instance from a class like this: class C: def __getattr__(self, name): raise AttributeError The profiler sees the following sequence of events: call (foo) call (__getattr__) exception (in __getattr__) return (from foo) Previously, the profiler would assume the return event returned from __getattr__. An if statement checking for this condition and raising an exception was commented out... This version does the right thing.
2001-10-03 21:58:24 -03:00
* 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.
2008-02-05 15:58:17 -04:00
import profile
from test.profilee import testfunc, timer
class ProfileTest(unittest.TestCase):
profilerclass = profile.Profile
methodnames = ['print_stats', 'print_callers', 'print_callees']
expected_output = {}
Issue #5330: C functions called with keyword arguments were not reported by the various profiling modules (profile, cProfile). Patch by Hagen Fürstenau.
2009-05-30 18:27:00 -03:00
expected_list_sort_output = ':0(sort)'
* 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.
2008-02-05 15:58:17 -04:00
@classmethod
def do_profiling(cls):
results = []
prof = cls.profilerclass(timer, 0.001)
Some tests did not pass on repeated calls (regrtest -R::) Perform additional cleanup, mostly deleting from sys.modules, or clearing the warnings registry.
2008-04-18 20:31:33 -03:00
start_timer = timer()
* 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.
2008-02-05 15:58:17 -04:00
prof.runctx("testfunc()", globals(), locals())
Some tests did not pass on repeated calls (regrtest -R::) Perform additional cleanup, mostly deleting from sys.modules, or clearing the warnings registry.
2008-04-18 20:31:33 -03:00
results.append(timer() - start_timer)
* 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.
2008-02-05 15:58:17 -04:00
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()
Some tests did not pass on repeated calls (regrtest -R::) Perform additional cleanup, mostly deleting from sys.modules, or clearing the warnings registry.
2008-04-18 20:31:33 -03:00
self.assertEqual(results[0], 1000)
* 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.
2008-02-05 15:58:17 -04:00
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__))
Issue #5330: C functions called with keyword arguments were not reported by the various profiling modules (profile, cProfile). Patch by Hagen Fürstenau.
2009-05-30 18:27:00 -03:00
def test_calling_conventions(self):
# Issue #5330: profile and cProfile wouldn't report C functions called
# with keyword arguments. We test all calling conventions.
stmts = [
"[].sort()",
"[].sort(reverse=True)",
"[].sort(*(None, None, True))",
"[].sort(**dict(reverse=True))",
]
for stmt in stmts:
s = StringIO()
The test for #5330 wasn't correct.
2009-05-30 18:39:25 -03:00
prof = self.profilerclass(timer, 0.001)
Issue #5330: C functions called with keyword arguments were not reported by the various profiling modules (profile, cProfile). Patch by Hagen Fürstenau.
2009-05-30 18:27:00 -03:00
prof.runctx(stmt, globals(), locals())
stats = pstats.Stats(prof, stream=s)
stats.print_stats()
res = s.getvalue()
self.assertTrue(self.expected_list_sort_output in res,
"Profiling {0!r} didn't report list.sort:\n{1}".format(stmt, res))
* 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.
2008-02-05 15:58:17 -04:00
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')
Whitespace normalization.
2001-10-04 02:36:56 -03:00
Added the cProfile module. Based on lsprof (patch #1212837) by Brett Rosen and Ted Czotter. With further editing by Michael Hudson and myself. History in svn repo: http://codespeak.net/svn/user/arigo/hack/misc/lsprof * Module/_lsprof.c is the internal C module, Lib/cProfile.py a wrapper. * pstats.py updated to display cProfile's caller/callee timings if available. * setup.py and NEWS updated. * documentation updates in the profiler section: - explain the differences between the three profilers that we have now - profile and cProfile can use a unified documentation, like (c)Pickle - mention that hotshot is "for specialized usage" now - removed references to the "old profiler" that no longer exists * test updates: - extended test_profile to cover delicate cases like recursion - added tests for the caller/callee displays - added test_cProfile, performing the same tests for cProfile * TO-DO: - cProfile gives a nicer name to built-in, particularly built-in methods, which could be backported to profile. - not tested on Windows recently!
2006-02-08 08:53:56 -04:00
def test_main():
* 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.
2008-02-05 15:58:17 -04:00
run_unittest(ProfileTest)
def main():
if '-r' not in sys.argv:
test_main()
Added the cProfile module. Based on lsprof (patch #1212837) by Brett Rosen and Ted Czotter. With further editing by Michael Hudson and myself. History in svn repo: http://codespeak.net/svn/user/arigo/hack/misc/lsprof * Module/_lsprof.c is the internal C module, Lib/cProfile.py a wrapper. * pstats.py updated to display cProfile's caller/callee timings if available. * setup.py and NEWS updated. * documentation updates in the profiler section: - explain the differences between the three profilers that we have now - profile and cProfile can use a unified documentation, like (c)Pickle - mention that hotshot is "for specialized usage" now - removed references to the "old profiler" that no longer exists * test updates: - extended test_profile to cover delicate cases like recursion - added tests for the caller/callee displays - added test_cProfile, performing the same tests for cProfile * TO-DO: - cProfile gives a nicer name to built-in, particularly built-in methods, which could be backported to profile. - not tested on Windows recently!
2006-02-08 08:53:56 -04:00
else:
* 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.
2008-02-05 15:58:17 -04:00
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
"""
Hopefully fix the profiler right. Add a test suite that checks that it deals correctly with some anomalous cases; according to this test suite I've fixed it right. The anomalous cases had to do with 'exception' events: these aren't generated when they would be most helpful, and the profiler has to work hard to recover the right information. The problems occur when C code (such as hasattr(), which is used as the example here) calls back into Python code and clears an exception raised by that Python code. Consider this example: def foo(): hasattr(obj, "bar") Where obj is an instance from a class like this: class C: def __getattr__(self, name): raise AttributeError The profiler sees the following sequence of events: call (foo) call (__getattr__) exception (in __getattr__) return (from foo) Previously, the profiler would assume the return event returned from __getattr__. An if statement checking for this condition and raising an exception was commented out... This version does the right thing.
2001-10-03 21:58:24 -03:00
if __name__ == "__main__":
* 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.
2008-02-05 15:58:17 -04:00
main()