test_profile.py 7.8 KB

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