test_profile.py 8.7 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217
  1. """Test suite for the profile module."""
  2. import sys
  3. import pstats
  4. import unittest
  5. import os
  6. from difflib import unified_diff
  7. from io import StringIO
  8. from test.support.os_helper import TESTFN, unlink, temp_dir, change_cwd
  9. from contextlib import contextmanager
  10. import profile
  11. from test.profilee import testfunc, timer
  12. from test.support.script_helper import assert_python_failure, assert_python_ok
  13. class ProfileTest(unittest.TestCase):
  14. profilerclass = profile.Profile
  15. profilermodule = profile
  16. methodnames = ['print_stats', 'print_callers', 'print_callees']
  17. expected_max_output = ':0(max)'
  18. def tearDown(self):
  19. unlink(TESTFN)
  20. def get_expected_output(self):
  21. return _ProfileOutput
  22. @classmethod
  23. def do_profiling(cls):
  24. results = []
  25. prof = cls.profilerclass(timer, 0.001)
  26. start_timer = timer()
  27. prof.runctx("testfunc()", globals(), locals())
  28. results.append(timer() - start_timer)
  29. for methodname in cls.methodnames:
  30. s = StringIO()
  31. stats = pstats.Stats(prof, stream=s)
  32. stats.strip_dirs().sort_stats("stdname")
  33. getattr(stats, methodname)()
  34. output = s.getvalue().splitlines()
  35. mod_name = testfunc.__module__.rsplit('.', 1)[1]
  36. # Only compare against stats originating from the test file.
  37. # Prevents outside code (e.g., the io module) from causing
  38. # unexpected output.
  39. output = [line.rstrip() for line in output if mod_name in line]
  40. results.append('\n'.join(output))
  41. return results
  42. def test_cprofile(self):
  43. results = self.do_profiling()
  44. expected = self.get_expected_output()
  45. self.assertEqual(results[0], 1000)
  46. fail = []
  47. for i, method in enumerate(self.methodnames):
  48. a = expected[method]
  49. b = results[i+1]
  50. if a != b:
  51. fail.append(f"\nStats.{method} output for "
  52. f"{self.profilerclass.__name__} "
  53. "does not fit expectation:")
  54. fail.extend(unified_diff(a.split('\n'), b.split('\n'),
  55. lineterm=""))
  56. if fail:
  57. self.fail("\n".join(fail))
  58. def test_calling_conventions(self):
  59. # Issue #5330: profile and cProfile wouldn't report C functions called
  60. # with keyword arguments. We test all calling conventions.
  61. stmts = [
  62. "max([0])",
  63. "max([0], key=int)",
  64. "max([0], **dict(key=int))",
  65. "max(*([0],))",
  66. "max(*([0],), key=int)",
  67. "max(*([0],), **dict(key=int))",
  68. ]
  69. for stmt in stmts:
  70. s = StringIO()
  71. prof = self.profilerclass(timer, 0.001)
  72. prof.runctx(stmt, globals(), locals())
  73. stats = pstats.Stats(prof, stream=s)
  74. stats.print_stats()
  75. res = s.getvalue()
  76. self.assertIn(self.expected_max_output, res,
  77. "Profiling {0!r} didn't report max:\n{1}".format(stmt, res))
  78. def test_run(self):
  79. with silent():
  80. self.profilermodule.run("int('1')")
  81. self.profilermodule.run("int('1')", filename=TESTFN)
  82. self.assertTrue(os.path.exists(TESTFN))
  83. def test_runctx(self):
  84. with silent():
  85. self.profilermodule.runctx("testfunc()", globals(), locals())
  86. self.profilermodule.runctx("testfunc()", globals(), locals(),
  87. filename=TESTFN)
  88. self.assertTrue(os.path.exists(TESTFN))
  89. def test_run_profile_as_module(self):
  90. # Test that -m switch needs an argument
  91. assert_python_failure('-m', self.profilermodule.__name__, '-m')
  92. # Test failure for not-existent module
  93. assert_python_failure('-m', self.profilermodule.__name__,
  94. '-m', 'random_module_xyz')
  95. # Test successful run
  96. assert_python_ok('-m', self.profilermodule.__name__,
  97. '-m', 'timeit', '-n', '1')
  98. def test_output_file_when_changing_directory(self):
  99. with temp_dir() as tmpdir, change_cwd(tmpdir):
  100. os.mkdir('dest')
  101. with open('demo.py', 'w', encoding="utf-8") as f:
  102. f.write('import os; os.chdir("dest")')
  103. assert_python_ok(
  104. '-m', self.profilermodule.__name__,
  105. '-o', 'out.pstats',
  106. 'demo.py',
  107. )
  108. self.assertTrue(os.path.exists('out.pstats'))
  109. def regenerate_expected_output(filename, cls):
  110. filename = filename.rstrip('co')
  111. print('Regenerating %s...' % filename)
  112. results = cls.do_profiling()
  113. newfile = []
  114. with open(filename, 'r') as f:
  115. for line in f:
  116. newfile.append(line)
  117. if line.startswith('#--cut'):
  118. break
  119. with open(filename, 'w') as f:
  120. f.writelines(newfile)
  121. f.write("_ProfileOutput = {}\n")
  122. for i, method in enumerate(cls.methodnames):
  123. f.write('_ProfileOutput[%r] = """\\\n%s"""\n' % (
  124. method, results[i+1]))
  125. f.write('\nif __name__ == "__main__":\n main()\n')
  126. @contextmanager
  127. def silent():
  128. stdout = sys.stdout
  129. try:
  130. sys.stdout = StringIO()
  131. yield
  132. finally:
  133. sys.stdout = stdout
  134. def main():
  135. if '-r' not in sys.argv:
  136. unittest.main()
  137. else:
  138. regenerate_expected_output(__file__, ProfileTest)
  139. # Don't remove this comment. Everything below it is auto-generated.
  140. #--cut--------------------------------------------------------------------------
  141. _ProfileOutput = {}
  142. _ProfileOutput['print_stats'] = """\
  143. 28 27.972 0.999 27.972 0.999 profilee.py:110(__getattr__)
  144. 1 269.996 269.996 999.769 999.769 profilee.py:25(testfunc)
  145. 23/3 149.937 6.519 169.917 56.639 profilee.py:35(factorial)
  146. 20 19.980 0.999 19.980 0.999 profilee.py:48(mul)
  147. 2 39.986 19.993 599.830 299.915 profilee.py:55(helper)
  148. 4 115.984 28.996 119.964 29.991 profilee.py:73(helper1)
  149. 2 -0.006 -0.003 139.946 69.973 profilee.py:84(helper2_indirect)
  150. 8 311.976 38.997 399.912 49.989 profilee.py:88(helper2)
  151. 8 63.976 7.997 79.960 9.995 profilee.py:98(subhelper)"""
  152. _ProfileOutput['print_callers'] = """\
  153. :0(append) <- profilee.py:73(helper1)(4) 119.964
  154. :0(exc_info) <- profilee.py:73(helper1)(4) 119.964
  155. :0(hasattr) <- profilee.py:73(helper1)(4) 119.964
  156. profilee.py:88(helper2)(8) 399.912
  157. profilee.py:110(__getattr__) <- :0(hasattr)(12) 11.964
  158. profilee.py:98(subhelper)(16) 79.960
  159. profilee.py:25(testfunc) <- <string>:1(<module>)(1) 999.767
  160. profilee.py:35(factorial) <- profilee.py:25(testfunc)(1) 999.769
  161. profilee.py:35(factorial)(20) 169.917
  162. profilee.py:84(helper2_indirect)(2) 139.946
  163. profilee.py:48(mul) <- profilee.py:35(factorial)(20) 169.917
  164. profilee.py:55(helper) <- profilee.py:25(testfunc)(2) 999.769
  165. profilee.py:73(helper1) <- profilee.py:55(helper)(4) 599.830
  166. profilee.py:84(helper2_indirect) <- profilee.py:55(helper)(2) 599.830
  167. profilee.py:88(helper2) <- profilee.py:55(helper)(6) 599.830
  168. profilee.py:84(helper2_indirect)(2) 139.946
  169. profilee.py:98(subhelper) <- profilee.py:88(helper2)(8) 399.912"""
  170. _ProfileOutput['print_callees'] = """\
  171. :0(hasattr) -> profilee.py:110(__getattr__)(12) 27.972
  172. <string>:1(<module>) -> profilee.py:25(testfunc)(1) 999.769
  173. profilee.py:110(__getattr__) ->
  174. profilee.py:25(testfunc) -> profilee.py:35(factorial)(1) 169.917
  175. profilee.py:55(helper)(2) 599.830
  176. profilee.py:35(factorial) -> profilee.py:35(factorial)(20) 169.917
  177. profilee.py:48(mul)(20) 19.980
  178. profilee.py:48(mul) ->
  179. profilee.py:55(helper) -> profilee.py:73(helper1)(4) 119.964
  180. profilee.py:84(helper2_indirect)(2) 139.946
  181. profilee.py:88(helper2)(6) 399.912
  182. profilee.py:73(helper1) -> :0(append)(4) -0.004
  183. profilee.py:84(helper2_indirect) -> profilee.py:35(factorial)(2) 169.917
  184. profilee.py:88(helper2)(2) 399.912
  185. profilee.py:88(helper2) -> :0(hasattr)(8) 11.964
  186. profilee.py:98(subhelper)(8) 79.960
  187. profilee.py:98(subhelper) -> profilee.py:110(__getattr__)(16) 27.972"""
  188. if __name__ == "__main__":
  189. main()