Georg Brandl | 5a6cfee | 2008-02-02 11:46:07 +0000 | [diff] [blame] | 1 | import sys |
| 2 | import cProfile |
| 3 | import pstats |
| 4 | import test.test_support |
| 5 | |
| 6 | ################################# |
| 7 | # Warning! |
| 8 | # This stuff is touchy. If you modify anything above the test_main function, |
| 9 | # you'll have to regenerate the stats for the doctest! |
| 10 | ################################ |
| 11 | |
| 12 | TICKS = 42000 |
| 13 | |
| 14 | def timer(): |
| 15 | return TICKS |
| 16 | |
| 17 | def testfunc(): |
| 18 | # 1 call |
| 19 | # 1000 ticks total: 270 ticks local, 730 ticks in subfunctions |
| 20 | global TICKS |
| 21 | TICKS += 99 |
| 22 | helper() # 300 |
| 23 | helper() # 300 |
| 24 | TICKS += 171 |
| 25 | factorial(14) # 130 |
| 26 | |
| 27 | def factorial(n): |
| 28 | # 23 calls total |
| 29 | # 170 ticks total, 150 ticks local |
| 30 | # 3 primitive calls, 130, 20 and 20 ticks total |
| 31 | # including 116, 17, 17 ticks local |
| 32 | global TICKS |
| 33 | if n > 0: |
| 34 | TICKS += n |
| 35 | return mul(n, factorial(n-1)) |
| 36 | else: |
| 37 | TICKS += 11 |
| 38 | return 1 |
| 39 | |
| 40 | def mul(a, b): |
| 41 | # 20 calls |
| 42 | # 1 tick, local |
| 43 | global TICKS |
| 44 | TICKS += 1 |
| 45 | return a * b |
| 46 | |
| 47 | def helper(): |
| 48 | # 2 calls |
| 49 | # 300 ticks total: 20 ticks local, 260 ticks in subfunctions |
| 50 | global TICKS |
| 51 | TICKS += 1 |
| 52 | helper1() # 30 |
| 53 | TICKS += 2 |
| 54 | helper1() # 30 |
| 55 | TICKS += 6 |
| 56 | helper2() # 50 |
| 57 | TICKS += 3 |
| 58 | helper2() # 50 |
| 59 | TICKS += 2 |
| 60 | helper2() # 50 |
| 61 | TICKS += 5 |
| 62 | helper2_indirect() # 70 |
| 63 | TICKS += 1 |
| 64 | |
| 65 | def helper1(): |
| 66 | # 4 calls |
| 67 | # 30 ticks total: 29 ticks local, 1 tick in subfunctions |
| 68 | global TICKS |
| 69 | TICKS += 10 |
| 70 | hasattr(C(), "foo") # 1 |
| 71 | TICKS += 19 |
| 72 | lst = [] |
| 73 | lst.append(42) # 0 |
| 74 | sys.exc_info() # 0 |
| 75 | |
| 76 | def helper2_indirect(): |
| 77 | helper2() # 50 |
| 78 | factorial(3) # 20 |
| 79 | |
| 80 | def helper2(): |
| 81 | # 8 calls |
| 82 | # 50 ticks local: 39 ticks local, 11 ticks in subfunctions |
| 83 | global TICKS |
| 84 | TICKS += 11 |
| 85 | hasattr(C(), "bar") # 1 |
| 86 | TICKS += 13 |
| 87 | subhelper() # 10 |
| 88 | TICKS += 15 |
| 89 | |
| 90 | def subhelper(): |
| 91 | # 8 calls |
| 92 | # 10 ticks total: 8 ticks local, 2 ticks in subfunctions |
| 93 | global TICKS |
| 94 | TICKS += 2 |
| 95 | for i in range(2): # 0 |
| 96 | try: |
| 97 | C().foo # 1 x 2 |
| 98 | except AttributeError: |
| 99 | TICKS += 3 # 3 x 2 |
| 100 | |
| 101 | class C: |
| 102 | def __getattr__(self, name): |
| 103 | # 28 calls |
| 104 | # 1 tick, local |
| 105 | global TICKS |
| 106 | TICKS += 1 |
| 107 | raise AttributeError |
| 108 | |
| 109 | def test_main(): |
| 110 | """ |
| 111 | >>> prof = cProfile.Profile(timer, 0.001) |
| 112 | >>> prof.runctx("testfunc()", globals(), locals()) #doctest: +ELLIPSIS |
| 113 | <cProfile.Profile object at ...> |
| 114 | >>> timer() |
| 115 | 43000 |
| 116 | >>> stats = pstats.Stats(prof) |
| 117 | >>> stats.strip_dirs().sort_stats("stdname") #doctest: +ELLIPSIS |
| 118 | <pstats.Stats ...> |
| 119 | >>> stats.print_stats() #doctest: +ELLIPSIS |
| 120 | 126 function calls (106 primitive calls) in 1.000 CPU seconds |
| 121 | <BLANKLINE> |
| 122 | Ordered by: standard name |
| 123 | <BLANKLINE> |
| 124 | ncalls tottime percall cumtime percall filename:lineno(function) |
| 125 | 1 0.000 0.000 1.000 1.000 <string>:1(<module>) |
| 126 | 28 0.028 0.001 0.028 0.001 test_cprofile.py:102(__getattr__) |
| 127 | 1 0.270 0.270 1.000 1.000 test_cprofile.py:17(testfunc) |
| 128 | 23/3 0.150 0.007 0.170 0.057 test_cprofile.py:27(factorial) |
| 129 | 20 0.020 0.001 0.020 0.001 test_cprofile.py:40(mul) |
| 130 | 2 0.040 0.020 0.600 0.300 test_cprofile.py:47(helper) |
| 131 | 4 0.116 0.029 0.120 0.030 test_cprofile.py:65(helper1) |
| 132 | 2 0.000 0.000 0.140 0.070 test_cprofile.py:76(helper2_indirect) |
| 133 | 8 0.312 0.039 0.400 0.050 test_cprofile.py:80(helper2) |
| 134 | 8 0.064 0.008 0.080 0.010 test_cprofile.py:90(subhelper) |
| 135 | 12 0.000 0.000 0.012 0.001 {hasattr} |
| 136 | 4 0.000 0.000 0.000 0.000 {method 'append' of 'list' objects} |
| 137 | 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} |
| 138 | 8 0.000 0.000 0.000 0.000 {range} |
| 139 | 4 0.000 0.000 0.000 0.000 {sys.exc_info} |
| 140 | <BLANKLINE> |
| 141 | <BLANKLINE> |
| 142 | <pstats.Stats instance at ...> |
| 143 | >>> stats.print_callers() #doctest: +ELLIPSIS |
| 144 | Ordered by: standard name |
| 145 | <BLANKLINE> |
| 146 | Function was called by... |
| 147 | ncalls tottime cumtime |
| 148 | <string>:1(<module>) <- |
| 149 | test_cprofile.py:102(__getattr__) <- 16 0.016 0.016 test_cprofile.py:90(subhelper) |
| 150 | 12 0.012 0.012 {hasattr} |
| 151 | test_cprofile.py:17(testfunc) <- 1 0.270 1.000 <string>:1(<module>) |
| 152 | test_cprofile.py:27(factorial) <- 1 0.014 0.130 test_cprofile.py:17(testfunc) |
| 153 | 20/3 0.130 0.147 test_cprofile.py:27(factorial) |
| 154 | 2 0.006 0.040 test_cprofile.py:76(helper2_indirect) |
| 155 | test_cprofile.py:40(mul) <- 20 0.020 0.020 test_cprofile.py:27(factorial) |
| 156 | test_cprofile.py:47(helper) <- 2 0.040 0.600 test_cprofile.py:17(testfunc) |
| 157 | test_cprofile.py:65(helper1) <- 4 0.116 0.120 test_cprofile.py:47(helper) |
| 158 | test_cprofile.py:76(helper2_indirect) <- 2 0.000 0.140 test_cprofile.py:47(helper) |
| 159 | test_cprofile.py:80(helper2) <- 6 0.234 0.300 test_cprofile.py:47(helper) |
| 160 | 2 0.078 0.100 test_cprofile.py:76(helper2_indirect) |
| 161 | test_cprofile.py:90(subhelper) <- 8 0.064 0.080 test_cprofile.py:80(helper2) |
| 162 | {hasattr} <- 4 0.000 0.004 test_cprofile.py:65(helper1) |
| 163 | 8 0.000 0.008 test_cprofile.py:80(helper2) |
| 164 | {method 'append' of 'list' objects} <- 4 0.000 0.000 test_cprofile.py:65(helper1) |
| 165 | {method 'disable' of '_lsprof.Profiler' objects} <- |
| 166 | {range} <- 8 0.000 0.000 test_cprofile.py:90(subhelper) |
| 167 | {sys.exc_info} <- 4 0.000 0.000 test_cprofile.py:65(helper1) |
| 168 | <BLANKLINE> |
| 169 | <BLANKLINE> |
| 170 | <pstats.Stats instance at ...> |
| 171 | >>> stats.print_callees() #doctest: +ELLIPSIS |
| 172 | Ordered by: standard name |
| 173 | <BLANKLINE> |
| 174 | Function called... |
| 175 | ncalls tottime cumtime |
| 176 | <string>:1(<module>) -> 1 0.270 1.000 test_cprofile.py:17(testfunc) |
| 177 | test_cprofile.py:102(__getattr__) -> |
| 178 | test_cprofile.py:17(testfunc) -> 1 0.014 0.130 test_cprofile.py:27(factorial) |
| 179 | 2 0.040 0.600 test_cprofile.py:47(helper) |
| 180 | test_cprofile.py:27(factorial) -> 20/3 0.130 0.147 test_cprofile.py:27(factorial) |
| 181 | 20 0.020 0.020 test_cprofile.py:40(mul) |
| 182 | test_cprofile.py:40(mul) -> |
| 183 | test_cprofile.py:47(helper) -> 4 0.116 0.120 test_cprofile.py:65(helper1) |
| 184 | 2 0.000 0.140 test_cprofile.py:76(helper2_indirect) |
| 185 | 6 0.234 0.300 test_cprofile.py:80(helper2) |
| 186 | test_cprofile.py:65(helper1) -> 4 0.000 0.004 {hasattr} |
| 187 | 4 0.000 0.000 {method 'append' of 'list' objects} |
| 188 | 4 0.000 0.000 {sys.exc_info} |
| 189 | test_cprofile.py:76(helper2_indirect) -> 2 0.006 0.040 test_cprofile.py:27(factorial) |
| 190 | 2 0.078 0.100 test_cprofile.py:80(helper2) |
| 191 | test_cprofile.py:80(helper2) -> 8 0.064 0.080 test_cprofile.py:90(subhelper) |
| 192 | 8 0.000 0.008 {hasattr} |
| 193 | test_cprofile.py:90(subhelper) -> 16 0.016 0.016 test_cprofile.py:102(__getattr__) |
| 194 | 8 0.000 0.000 {range} |
| 195 | {hasattr} -> 12 0.012 0.012 test_cprofile.py:102(__getattr__) |
| 196 | {method 'append' of 'list' objects} -> |
| 197 | {method 'disable' of '_lsprof.Profiler' objects} -> |
| 198 | {range} -> |
| 199 | {sys.exc_info} -> |
| 200 | <BLANKLINE> |
| 201 | <BLANKLINE> |
| 202 | <pstats.Stats instance at ...> |
| 203 | """ |
| 204 | from test import test_cprofile |
| 205 | test.test_support.run_doctest(test_cprofile) |
| 206 | |
| 207 | if __name__ == "__main__": |
| 208 | test_main() |