Lib/test/test_profile.py

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