| 1 | """Test suite for the profile module."""
|
|---|
| 2 |
|
|---|
| 3 | import sys
|
|---|
| 4 | import pstats
|
|---|
| 5 | import unittest
|
|---|
| 6 | from StringIO import StringIO
|
|---|
| 7 | from test.test_support import run_unittest
|
|---|
| 8 |
|
|---|
| 9 | import profile
|
|---|
| 10 | from test.profilee import testfunc, timer
|
|---|
| 11 |
|
|---|
| 12 |
|
|---|
| 13 | class ProfileTest(unittest.TestCase):
|
|---|
| 14 |
|
|---|
| 15 | profilerclass = profile.Profile
|
|---|
| 16 | methodnames = ['print_stats', 'print_callers', 'print_callees']
|
|---|
| 17 | expected_output = {}
|
|---|
| 18 | expected_list_sort_output = ':0(sort)'
|
|---|
| 19 |
|
|---|
| 20 | @classmethod
|
|---|
| 21 | def do_profiling(cls):
|
|---|
| 22 | results = []
|
|---|
| 23 | prof = cls.profilerclass(timer, 0.001)
|
|---|
| 24 | start_timer = timer()
|
|---|
| 25 | prof.runctx("testfunc()", globals(), locals())
|
|---|
| 26 | results.append(timer() - start_timer)
|
|---|
| 27 | for methodname in cls.methodnames:
|
|---|
| 28 | s = StringIO()
|
|---|
| 29 | stats = pstats.Stats(prof, stream=s)
|
|---|
| 30 | stats.strip_dirs().sort_stats("stdname")
|
|---|
| 31 | getattr(stats, methodname)()
|
|---|
| 32 | results.append(s.getvalue())
|
|---|
| 33 | return results
|
|---|
| 34 |
|
|---|
| 35 | def test_cprofile(self):
|
|---|
| 36 | results = self.do_profiling()
|
|---|
| 37 | self.assertEqual(results[0], 1000)
|
|---|
| 38 | for i, method in enumerate(self.methodnames):
|
|---|
| 39 | self.assertEqual(results[i+1], self.expected_output[method],
|
|---|
| 40 | "Stats.%s output for %s doesn't fit expectation!" %
|
|---|
| 41 | (method, self.profilerclass.__name__))
|
|---|
| 42 |
|
|---|
| 43 | def test_calling_conventions(self):
|
|---|
| 44 | # Issue #5330: profile and cProfile wouldn't report C functions called
|
|---|
| 45 | # with keyword arguments. We test all calling conventions.
|
|---|
| 46 | stmts = [
|
|---|
| 47 | "[].sort()",
|
|---|
| 48 | "[].sort(reverse=True)",
|
|---|
| 49 | "[].sort(*(None, None, True))",
|
|---|
| 50 | "[].sort(**dict(reverse=True))",
|
|---|
| 51 | ]
|
|---|
| 52 | for stmt in stmts:
|
|---|
| 53 | s = StringIO()
|
|---|
| 54 | prof = self.profilerclass(timer, 0.001)
|
|---|
| 55 | prof.runctx(stmt, globals(), locals())
|
|---|
| 56 | stats = pstats.Stats(prof, stream=s)
|
|---|
| 57 | stats.print_stats()
|
|---|
| 58 | res = s.getvalue()
|
|---|
| 59 | self.assertIn(self.expected_list_sort_output, res,
|
|---|
| 60 | "Profiling {0!r} didn't report list.sort:\n{1}".format(stmt, res))
|
|---|
| 61 |
|
|---|
| 62 |
|
|---|
| 63 | def regenerate_expected_output(filename, cls):
|
|---|
| 64 | filename = filename.rstrip('co')
|
|---|
| 65 | print 'Regenerating %s...' % filename
|
|---|
| 66 | results = cls.do_profiling()
|
|---|
| 67 |
|
|---|
| 68 | newfile = []
|
|---|
| 69 | with open(filename, 'r') as f:
|
|---|
| 70 | for line in f:
|
|---|
| 71 | newfile.append(line)
|
|---|
| 72 | if line[:6] == '#--cut':
|
|---|
| 73 | break
|
|---|
| 74 |
|
|---|
| 75 | with open(filename, 'w') as f:
|
|---|
| 76 | f.writelines(newfile)
|
|---|
| 77 | for i, method in enumerate(cls.methodnames):
|
|---|
| 78 | f.write('%s.expected_output[%r] = """\\\n%s"""\n' % (
|
|---|
| 79 | cls.__name__, method, results[i+1]))
|
|---|
| 80 | f.write('\nif __name__ == "__main__":\n main()\n')
|
|---|
| 81 |
|
|---|
| 82 |
|
|---|
| 83 | def test_main():
|
|---|
| 84 | run_unittest(ProfileTest)
|
|---|
| 85 |
|
|---|
| 86 | def main():
|
|---|
| 87 | if '-r' not in sys.argv:
|
|---|
| 88 | test_main()
|
|---|
| 89 | else:
|
|---|
| 90 | regenerate_expected_output(__file__, ProfileTest)
|
|---|
| 91 |
|
|---|
| 92 |
|
|---|
| 93 | # Don't remove this comment. Everything below it is auto-generated.
|
|---|
| 94 | #--cut--------------------------------------------------------------------------
|
|---|
| 95 | ProfileTest.expected_output['print_stats'] = """\
|
|---|
| 96 | 127 function calls (107 primitive calls) in 999.749 seconds
|
|---|
| 97 |
|
|---|
| 98 | Ordered by: standard name
|
|---|
| 99 |
|
|---|
| 100 | ncalls tottime percall cumtime percall filename:lineno(function)
|
|---|
| 101 | 4 -0.004 -0.001 -0.004 -0.001 :0(append)
|
|---|
| 102 | 4 -0.004 -0.001 -0.004 -0.001 :0(exc_info)
|
|---|
| 103 | 12 -0.024 -0.002 11.964 0.997 :0(hasattr)
|
|---|
| 104 | 8 -0.008 -0.001 -0.008 -0.001 :0(range)
|
|---|
| 105 | 1 0.000 0.000 0.000 0.000 :0(setprofile)
|
|---|
| 106 | 1 -0.002 -0.002 999.751 999.751 <string>:1(<module>)
|
|---|
| 107 | 0 0.000 0.000 profile:0(profiler)
|
|---|
| 108 | 1 -0.002 -0.002 999.749 999.749 profile:0(testfunc())
|
|---|
| 109 | 28 27.972 0.999 27.972 0.999 profilee.py:110(__getattr__)
|
|---|
| 110 | 1 269.996 269.996 999.753 999.753 profilee.py:25(testfunc)
|
|---|
| 111 | 23/3 149.937 6.519 169.917 56.639 profilee.py:35(factorial)
|
|---|
| 112 | 20 19.980 0.999 19.980 0.999 profilee.py:48(mul)
|
|---|
| 113 | 2 39.986 19.993 599.814 299.907 profilee.py:55(helper)
|
|---|
| 114 | 4 115.984 28.996 119.964 29.991 profilee.py:73(helper1)
|
|---|
| 115 | 2 -0.006 -0.003 139.942 69.971 profilee.py:84(helper2_indirect)
|
|---|
| 116 | 8 311.976 38.997 399.896 49.987 profilee.py:88(helper2)
|
|---|
| 117 | 8 63.968 7.996 79.944 9.993 profilee.py:98(subhelper)
|
|---|
| 118 |
|
|---|
| 119 |
|
|---|
| 120 | """
|
|---|
| 121 | ProfileTest.expected_output['print_callers'] = """\
|
|---|
| 122 | Ordered by: standard name
|
|---|
| 123 |
|
|---|
| 124 | Function was called by...
|
|---|
| 125 | :0(append) <- profilee.py:73(helper1)(4) 119.964
|
|---|
| 126 | :0(exc_info) <- profilee.py:73(helper1)(4) 119.964
|
|---|
| 127 | :0(hasattr) <- profilee.py:73(helper1)(4) 119.964
|
|---|
| 128 | profilee.py:88(helper2)(8) 399.896
|
|---|
| 129 | :0(range) <- profilee.py:98(subhelper)(8) 79.944
|
|---|
| 130 | :0(setprofile) <- profile:0(testfunc())(1) 999.749
|
|---|
| 131 | <string>:1(<module>) <- profile:0(testfunc())(1) 999.749
|
|---|
| 132 | profile:0(profiler) <-
|
|---|
| 133 | profile:0(testfunc()) <- profile:0(profiler)(1) 0.000
|
|---|
| 134 | profilee.py:110(__getattr__) <- :0(hasattr)(12) 11.964
|
|---|
| 135 | profilee.py:98(subhelper)(16) 79.944
|
|---|
| 136 | profilee.py:25(testfunc) <- <string>:1(<module>)(1) 999.751
|
|---|
| 137 | profilee.py:35(factorial) <- profilee.py:25(testfunc)(1) 999.753
|
|---|
| 138 | profilee.py:35(factorial)(20) 169.917
|
|---|
| 139 | profilee.py:84(helper2_indirect)(2) 139.942
|
|---|
| 140 | profilee.py:48(mul) <- profilee.py:35(factorial)(20) 169.917
|
|---|
| 141 | profilee.py:55(helper) <- profilee.py:25(testfunc)(2) 999.753
|
|---|
| 142 | profilee.py:73(helper1) <- profilee.py:55(helper)(4) 599.814
|
|---|
| 143 | profilee.py:84(helper2_indirect) <- profilee.py:55(helper)(2) 599.814
|
|---|
| 144 | profilee.py:88(helper2) <- profilee.py:55(helper)(6) 599.814
|
|---|
| 145 | profilee.py:84(helper2_indirect)(2) 139.942
|
|---|
| 146 | profilee.py:98(subhelper) <- profilee.py:88(helper2)(8) 399.896
|
|---|
| 147 |
|
|---|
| 148 |
|
|---|
| 149 | """
|
|---|
| 150 | ProfileTest.expected_output['print_callees'] = """\
|
|---|
| 151 | Ordered by: standard name
|
|---|
| 152 |
|
|---|
| 153 | Function called...
|
|---|
| 154 | :0(append) ->
|
|---|
| 155 | :0(exc_info) ->
|
|---|
| 156 | :0(hasattr) -> profilee.py:110(__getattr__)(12) 27.972
|
|---|
| 157 | :0(range) ->
|
|---|
| 158 | :0(setprofile) ->
|
|---|
| 159 | <string>:1(<module>) -> profilee.py:25(testfunc)(1) 999.753
|
|---|
| 160 | profile:0(profiler) -> profile:0(testfunc())(1) 999.749
|
|---|
| 161 | profile:0(testfunc()) -> :0(setprofile)(1) 0.000
|
|---|
| 162 | <string>:1(<module>)(1) 999.751
|
|---|
| 163 | profilee.py:110(__getattr__) ->
|
|---|
| 164 | profilee.py:25(testfunc) -> profilee.py:35(factorial)(1) 169.917
|
|---|
| 165 | profilee.py:55(helper)(2) 599.814
|
|---|
| 166 | profilee.py:35(factorial) -> profilee.py:35(factorial)(20) 169.917
|
|---|
| 167 | profilee.py:48(mul)(20) 19.980
|
|---|
| 168 | profilee.py:48(mul) ->
|
|---|
| 169 | profilee.py:55(helper) -> profilee.py:73(helper1)(4) 119.964
|
|---|
| 170 | profilee.py:84(helper2_indirect)(2) 139.942
|
|---|
| 171 | profilee.py:88(helper2)(6) 399.896
|
|---|
| 172 | profilee.py:73(helper1) -> :0(append)(4) -0.004
|
|---|
| 173 | :0(exc_info)(4) -0.004
|
|---|
| 174 | :0(hasattr)(4) 11.964
|
|---|
| 175 | profilee.py:84(helper2_indirect) -> profilee.py:35(factorial)(2) 169.917
|
|---|
| 176 | profilee.py:88(helper2)(2) 399.896
|
|---|
| 177 | profilee.py:88(helper2) -> :0(hasattr)(8) 11.964
|
|---|
| 178 | profilee.py:98(subhelper)(8) 79.944
|
|---|
| 179 | profilee.py:98(subhelper) -> :0(range)(8) -0.008
|
|---|
| 180 | profilee.py:110(__getattr__)(16) 27.972
|
|---|
| 181 |
|
|---|
| 182 |
|
|---|
| 183 | """
|
|---|
| 184 |
|
|---|
| 185 | if __name__ == "__main__":
|
|---|
| 186 | main()
|
|---|
