Home | History | Annotate | Download | only in test
      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()
    187