Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 1 | # |
| 2 | # Class for profiling python code. |
| 3 | # Author: Sjoerd Mullender |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 4 | # Hacked somewhat by: Guido van Rossum |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 5 | # |
| 6 | # See the accompanying document profile.doc for more information. |
| 7 | |
| 8 | import sys |
| 9 | import codehack |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 10 | import os |
| 11 | import string |
| 12 | import fpformat |
| 13 | import marshal |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 14 | |
Guido van Rossum | d316607 | 1993-05-24 14:16:22 +0000 | [diff] [blame] | 15 | class Profile: |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 16 | |
| 17 | def init(self): |
| 18 | self.timings = {} |
| 19 | self.debug = None |
| 20 | self.call_level = 0 |
| 21 | self.profile_func = None |
| 22 | self.profiling = 0 |
| 23 | return self |
| 24 | |
| 25 | def profile(self, funcname): |
| 26 | if not self.profile_func: |
| 27 | self.profile_func = {} |
| 28 | self.profile_func[funcname] = 1 |
| 29 | |
| 30 | def trace_dispatch(self, frame, event, arg): |
| 31 | if event == 'call': |
| 32 | funcname = codehack.getcodename(frame.f_code) |
| 33 | if self.profile_func and not self.profiling: |
| 34 | if self.profile_func.has_key(funcname): |
| 35 | return |
| 36 | self.profiling = 1 |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 37 | t = os.times() |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 38 | t = t[0] + t[1] |
Sjoerd Mullender | 4fddf33 | 1993-08-25 14:09:01 +0000 | [diff] [blame] | 39 | if frame.f_locals.has_key('__key'): |
| 40 | key = frame.f_locals['__key'] |
| 41 | else: |
| 42 | lineno = codehack.getlineno(frame.f_code) |
| 43 | filename = frame.f_code.co_filename |
| 44 | key = filename + ':' + `lineno` + '(' + funcname + ')' |
| 45 | frame.f_locals['__key'] = key |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 46 | self.call_level = depth(frame) |
| 47 | self.cur_frame = frame |
| 48 | pframe = frame.f_back |
| 49 | if self.debug: |
| 50 | s0 = 'call: ' + key + ' depth: ' + `self.call_level` + ' time: ' + `t` |
| 51 | if pframe: |
Sjoerd Mullender | 4fddf33 | 1993-08-25 14:09:01 +0000 | [diff] [blame] | 52 | if pframe.f_locals.has_key('__key'): |
| 53 | pkey = pframe.f_locals['__key'] |
| 54 | else: |
| 55 | pkey = pframe.f_code.co_filename + \ |
| 56 | ':' + \ |
| 57 | `codehack.getlineno(pframe.f_code)` \ |
| 58 | + '(' + \ |
| 59 | codehack.getcodename(pframe.f_code) \ |
| 60 | + ')' |
| 61 | pframe.f_locals['__key'] = pkey |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 62 | if self.debug: |
| 63 | s1 = 'parent: ' + pkey |
| 64 | if pframe.f_locals.has_key('__start_time'): |
| 65 | st = pframe.f_locals['__start_time'] |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 66 | nc, tt, ct, callers, callees = \ |
| 67 | self.timings[pkey] |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 68 | if self.debug: |
| 69 | s1 = s1+' before: st='+`st`+' nc='+`nc`+' tt='+`tt`+' ct='+`ct` |
| 70 | if callers.has_key(key): |
| 71 | callers[key] = callers[key] + 1 |
| 72 | else: |
| 73 | callers[key] = 1 |
| 74 | if self.debug: |
| 75 | s1 = s1+' after: st='+`st`+' nc='+`nc`+' tt='+`tt+(t-st)`+' ct='+`ct` |
| 76 | self.timings[pkey] = nc, tt + (t - st), ct, callers, callees |
| 77 | if self.timings.has_key(key): |
| 78 | nc, tt, ct, callers, callees = self.timings[key] |
| 79 | else: |
| 80 | nc, tt, ct, callers, callees = 0, 0, 0, {}, {} |
| 81 | if self.debug: |
| 82 | s0 = s0+' before: nc='+`nc`+' tt='+`tt`+' ct='+`ct` |
| 83 | s0 = s0+' after: nc='+`nc+1`+' tt='+`tt`+' ct='+`ct` |
| 84 | if pframe: |
| 85 | if callees.has_key(pkey): |
| 86 | callees[pkey] = callees[pkey] + 1 |
| 87 | else: |
| 88 | callees[pkey] = 1 |
| 89 | self.timings[key] = nc + 1, tt, ct, callers, callees |
| 90 | frame.f_locals['__start_time'] = t |
| 91 | if self.debug: |
| 92 | print s0 |
| 93 | print s1 |
| 94 | return |
| 95 | if event == 'return': |
| 96 | if self.profile_func: |
| 97 | if not self.profiling: |
| 98 | return |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 99 | if self.profile_func.has_key( \ |
| 100 | codehack.getcodename(frame.f_code)): |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 101 | self.profiling = 0 |
| 102 | self.call_level = depth(frame) |
| 103 | self.cur_frame = frame |
| 104 | pframe = frame.f_back |
| 105 | if self.debug: |
| 106 | s0 = 'return: ' |
| 107 | else: |
| 108 | s0 = None |
| 109 | self.handle_return(pframe, frame, s0) |
| 110 | return |
| 111 | if event == 'exception': |
| 112 | if self.profile_func and not self.profiling: |
| 113 | return |
| 114 | call_level = depth(frame) |
| 115 | if call_level < self.call_level: |
| 116 | if call_level <> self.call_level - 1: |
| 117 | print 'heh!',call_level,self.call_level |
| 118 | if self.debug: |
| 119 | s0 = 'exception: ' |
| 120 | else: |
| 121 | s0 = None |
| 122 | self.handle_return(self.cur_frame, frame, s0) |
| 123 | self.call_level = call_level |
| 124 | self.cur_frame = frame |
| 125 | return |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 126 | print 'profile.Profile.dispatch: unknown debugging event:', |
| 127 | print `event` |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 128 | return |
| 129 | |
| 130 | def handle_return(self, pframe, frame, s0): |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 131 | t = os.times() |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 132 | t = t[0] + t[1] |
Sjoerd Mullender | 4fddf33 | 1993-08-25 14:09:01 +0000 | [diff] [blame] | 133 | if frame.f_locals.has_key('__key'): |
| 134 | key = frame.f_locals['__key'] |
| 135 | else: |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 136 | funcname = codehack.getcodename(frame.f_code) |
| 137 | lineno = codehack.getlineno(frame.f_code) |
| 138 | filename = frame.f_code.co_filename |
Sjoerd Mullender | 4fddf33 | 1993-08-25 14:09:01 +0000 | [diff] [blame] | 139 | key = filename + ':' + `lineno` + '(' + funcname + ')' |
| 140 | frame.f_locals['__key'] = key |
| 141 | if self.debug: |
| 142 | s0 = s0 + key + ' depth: ' + `self.call_level` + ' time: ' + `t` |
| 143 | if pframe: |
| 144 | if pframe.f_locals.has_key('__key'): |
| 145 | pkey = pframe.f_locals['__key'] |
| 146 | else: |
| 147 | funcname = codehack.getcodename(frame.f_code) |
| 148 | lineno = codehack.getlineno(frame.f_code) |
| 149 | filename = frame.f_code.co_filename |
| 150 | pkey = filename + ':' + `lineno` + '(' + funcname + ')' |
| 151 | pframe.f_locals['__key'] = pkey |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 152 | if self.debug: |
| 153 | s1 = 'parent: '+pkey |
| 154 | if pframe.f_locals.has_key('__start_time') and \ |
| 155 | self.timings.has_key(pkey): |
| 156 | st = pframe.f_locals['__start_time'] |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 157 | nc, tt, ct, callers, callees = \ |
| 158 | self.timings[pkey] |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 159 | if self.debug: |
| 160 | s1 = s1+' before: st='+`st`+' nc='+`nc`+' tt='+`tt`+' ct='+`ct` |
| 161 | s1 = s1+' after: st='+`t`+' nc='+`nc`+' tt='+`tt`+' ct='+`ct+(t-st)` |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 162 | self.timings[pkey] = \ |
| 163 | nc, tt, ct + (t - st), callers, callees |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 164 | pframe.f_locals['__start_time'] = t |
| 165 | if self.timings.has_key(key): |
| 166 | nc, tt, ct, callers, callees = self.timings[key] |
| 167 | else: |
| 168 | nc, tt, ct, callers, callees = 0, 0, 0, {}, {} |
| 169 | if frame.f_locals.has_key('__start_time'): |
| 170 | st = frame.f_locals['__start_time'] |
| 171 | else: |
| 172 | st = t |
| 173 | if self.debug: |
| 174 | s0 = s0+' before: st='+`st`+' nc='+`nc`+' tt='+`tt`+' ct='+`ct` |
| 175 | s0 = s0+' after: nc='+`nc`+' tt='+`tt+(t-st)`+' ct='+`ct+(t-st)` |
| 176 | print s0 |
| 177 | print s1 |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 178 | self.timings[key] = \ |
| 179 | nc, tt + (t - st), ct + (t - st), callers, callees |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 180 | |
| 181 | def print_stats(self): |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 182 | # Print in reverse order by ct |
| 183 | print_title() |
| 184 | list = [] |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 185 | for key in self.timings.keys(): |
| 186 | nc, tt, ct, callers, callees = self.timings[key] |
| 187 | if nc == 0: |
| 188 | continue |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 189 | list.append(ct, tt, nc, key) |
| 190 | list.sort() |
| 191 | list.reverse() |
| 192 | for ct, tt, nc, key in list: |
| 193 | print_line(nc, tt, ct, os.path.basename(key)) |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 194 | |
| 195 | def dump_stats(self, file): |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 196 | f = open(file, 'w') |
| 197 | marshal.dump(self.timings, f) |
| 198 | f.close() |
| 199 | |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 200 | # The following two methods can be called by clients to use |
| 201 | # a profiler to profile a statement, given as a string. |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 202 | |
| 203 | def run(self, cmd): |
| 204 | import __main__ |
| 205 | dict = __main__.__dict__ |
| 206 | self.runctx(cmd, dict, dict) |
| 207 | |
| 208 | def runctx(self, cmd, globals, locals): |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 209 | sys.setprofile(self.trace_dispatch) |
| 210 | try: |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 211 | exec(cmd + '\n', globals, locals) |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 212 | finally: |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 213 | sys.setprofile(None) |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 214 | |
| 215 | # This method is more useful to profile a single function call. |
| 216 | |
| 217 | def runcall(self, func, *args): |
| 218 | sys.setprofile(self.trace_dispatch) |
| 219 | try: |
| 220 | apply(func, args) |
| 221 | finally: |
| 222 | sys.setprofile(None) |
| 223 | |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 224 | |
| 225 | def depth(frame): |
| 226 | d = 0 |
| 227 | while frame: |
| 228 | d = d + 1 |
| 229 | frame = frame.f_back |
| 230 | return d |
| 231 | |
Guido van Rossum | d316607 | 1993-05-24 14:16:22 +0000 | [diff] [blame] | 232 | class Stats: |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 233 | def init(self, file): |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 234 | f = open(file, 'r') |
| 235 | self.stats = marshal.load(f) |
| 236 | f.close() |
| 237 | self.stats_list = None |
| 238 | return self |
| 239 | |
| 240 | def print_stats(self): |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 241 | print_title() |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 242 | if self.stats_list: |
| 243 | for i in range(len(self.stats_list)): |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 244 | nc, tt, ct, callers, callees, key = \ |
| 245 | self.stats_list[i] |
| 246 | print_line(nc, tt, ct, key) |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 247 | else: |
| 248 | for key in self.stats.keys(): |
| 249 | nc, tt, ct, callers, callees = self.stats[key] |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 250 | print_line(nc, tt, ct, key) |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 251 | |
| 252 | def print_callers(self): |
| 253 | if self.stats_list: |
| 254 | for i in range(len(self.stats_list)): |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 255 | nc, tt, ct, callers, callees, key = \ |
| 256 | self.stats_list[i] |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 257 | print key, |
| 258 | for func in callers.keys(): |
| 259 | print func+'('+`callers[func]`+')', |
| 260 | print |
| 261 | else: |
| 262 | for key in self.stats.keys(): |
| 263 | nc, tt, ct, callers, callees = self.stats[key] |
| 264 | print key, |
| 265 | for func in callers.keys(): |
| 266 | print func+'('+`callers[func]`+')', |
| 267 | print |
| 268 | |
| 269 | def print_callees(self): |
| 270 | if self.stats_list: |
| 271 | for i in range(len(self.stats_list)): |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 272 | nc, tt, ct, callers, callees, key = \ |
| 273 | self.stats_list[i] |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 274 | print key, |
| 275 | for func in callees.keys(): |
| 276 | print func+'('+`callees[func]`+')', |
| 277 | print |
| 278 | else: |
| 279 | for key in self.stats.keys(): |
| 280 | nc, tt, ct, callers, callees = self.stats[key] |
| 281 | print key, |
| 282 | for func in callees.keys(): |
| 283 | print func+'('+`callees[func]`+')', |
| 284 | print |
| 285 | |
| 286 | def sort_stats(self, field): |
| 287 | stats_list = [] |
| 288 | for key in self.stats.keys(): |
| 289 | t = self.stats[key] |
| 290 | nt = () |
| 291 | for i in range(len(t)): |
| 292 | if i == field: |
| 293 | nt = (t[i],) + nt[:] |
| 294 | else: |
| 295 | nt = nt[:] + (t[i],) |
| 296 | if field == -1: |
| 297 | nt = (key,) + nt |
| 298 | else: |
| 299 | nt = nt + (key,) |
| 300 | stats_list.append(nt) |
| 301 | stats_list.sort() |
| 302 | self.stats_list = [] |
| 303 | for i in range(len(stats_list)): |
| 304 | t = stats_list[i] |
| 305 | if field == -1: |
| 306 | nt = t[1:] + t[0:1] |
| 307 | else: |
| 308 | nt = t[1:] |
| 309 | nt = nt[:field] + t[0:1] + nt[field:] |
| 310 | self.stats_list.append(nt) |
| 311 | |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 312 | def reverse_order(self): |
| 313 | self.stats_list.reverse() |
| 314 | |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 315 | def strip_dirs(self): |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 316 | newstats = {} |
| 317 | for key in self.stats.keys(): |
| 318 | nc, tt, ct, callers, callees = self.stats[key] |
| 319 | newkey = os.path.basename(key) |
| 320 | newcallers = {} |
| 321 | for c in callers.keys(): |
| 322 | newcallers[os.path.basename(c)] = callers[c] |
| 323 | newcallees = {} |
| 324 | for c in callees.keys(): |
| 325 | newcallees[os.path.basename(c)] = callees[c] |
| 326 | newstats[newkey] = nc, tt, ct, newcallers, newcallees |
| 327 | self.stats = newstats |
| 328 | self.stats_list = None |
| 329 | |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 330 | def print_title(): |
| 331 | print string.rjust('ncalls', 8), |
| 332 | print string.rjust('tottime', 8), |
| 333 | print string.rjust('percall', 8), |
| 334 | print string.rjust('cumtime', 8), |
| 335 | print string.rjust('percall', 8), |
| 336 | print 'filename:lineno(function)' |
| 337 | |
| 338 | def print_line(nc, tt, ct, key): |
| 339 | print string.rjust(`nc`, 8), |
| 340 | print f8(tt), |
| 341 | if nc == 0: |
| 342 | print ' '*8, |
| 343 | else: |
| 344 | print f8(tt/nc), |
| 345 | print f8(ct), |
| 346 | if nc == 0: |
| 347 | print ' '*8, |
| 348 | else: |
| 349 | print f8(ct/nc), |
| 350 | print key |
| 351 | |
| 352 | def f8(x): |
| 353 | return string.rjust(fpformat.fix(x, 3), 8) |
| 354 | |
| 355 | # simplified user interface |
| 356 | def run(statement, *args): |
| 357 | prof = Profile().init() |
| 358 | try: |
| 359 | prof.run(statement) |
| 360 | except SystemExit: |
| 361 | pass |
| 362 | if len(args) == 0: |
| 363 | prof.print_stats() |
| 364 | else: |
| 365 | prof.dump_stats(args[0]) |
| 366 | |
| 367 | # test command with debugging |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 368 | def debug(): |
| 369 | prof = Profile().init() |
| 370 | prof.debug = 1 |
| 371 | try: |
| 372 | prof.run('import x; x.main()') |
| 373 | except SystemExit: |
| 374 | pass |
| 375 | prof.print_stats() |
| 376 | |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 377 | # test command |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 378 | def test(): |
| 379 | run('import x; x.main()') |
Guido van Rossum | e61fa0a | 1993-10-22 13:56:35 +0000 | [diff] [blame] | 380 | |
| 381 | # print help |
| 382 | def help(): |
| 383 | for dirname in sys.path: |
| 384 | fullname = os.path.join(dirname, 'profile.doc') |
| 385 | if os.path.exists(fullname): |
| 386 | sts = os.system('${PAGER-more} '+fullname) |
| 387 | if sts: print '*** Pager exit status:', sts |
| 388 | break |
| 389 | else: |
| 390 | print 'Sorry, can\'t find the help file "profile.doc"', |
| 391 | print 'along the Python search path' |