diff options
| -rw-r--r-- | Lib/profile.doc | 702 | ||||
| -rwxr-xr-x | Lib/profile.py | 16 |
2 files changed, 3 insertions, 715 deletions
diff --git a/Lib/profile.doc b/Lib/profile.doc deleted file mode 100644 index 8724484..0000000 --- a/Lib/profile.doc +++ /dev/null @@ -1,702 +0,0 @@ -profile.doc last updated 6/23/94 [by Guido] - - PROFILER DOCUMENTATION and (mini) USER'S MANUAL - -Copyright 1994, by InfoSeek Corporation, all rights reserved. -Written by James Roskind - -Permission to use, copy, modify, and distribute this Python software -and its associated documentation for any purpose (subject to the -restriction in the following sentence) without fee is hereby granted, -provided that the above copyright notice appears in all copies, and -that both that copyright notice and this permission notice appear in -supporting documentation, and that the name of InfoSeek not be used in -advertising or publicity pertaining to distribution of the software -without specific, written prior permission. This permission is -explicitly restricted to the copying and modification of the software -to remain in Python, compiled Python, or other languages (such as C) -wherein the modified or derived code is exclusively imported into a -Python module. - -INFOSEEK CORPORATION DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS -SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND -FITNESS. IN NO EVENT SHALL INFOSEEK CORPORATION BE LIABLE FOR ANY -SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER -RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF -CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN -CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. - - -The profiler was written after only programming in Python for 3 weeks. -As a result, it is probably clumsy code, but I don't know for sure yet -'cause I'm a beginner :-). I did work hard to make the code run fast, -so that profiling would be a reasonable thing to do. I tried not to -repeat code fragments, but I'm sure I did some stuff in really awkward -ways at times. Please send suggestions for improvements to: -jar@infoseek.com. I won't promise *any* support. ...but I'd -appreciate the feedback. - - -SECTION HEADING LIST: - INTRODUCTION - HOW IS THIS profile DIFFERENT FROM THE OLD profile MODULE? - INSTANT USERS MANUAL - WHAT IS DETERMINISTIC PROFILING? - REFERENCE MANUAL - FUNCTION profile.run(string, filename_opt) - CLASS Stats(filename, ...) - METHOD strip_dirs() - METHOD add(filename, ...) - METHOD sort_stats(key, ...) - METHOD reverse_order() - METHOD print_stats(restriction, ...) - METHOD print_callers(restrictions, ...) - METHOD print_callees(restrictions, ...) - METHOD ignore() - LIMITATIONS - CALIBRATION - EXTENSIONS: Deriving Better Profilers - - - -INTRODUCTION - -A "profiler" is a program that describes the run time performance of a -program, providing a variety of statistics. This documentation -describes the profiler functionality provided in the modules -"profile" and "pstats." This profiler provides "deterministic -profiling" of any Python programs. It also provides a series of -report generation tools to allow users to rapidly examine the results -of a profile operation. - - -HOW IS THIS profile DIFFERENT FROM THE OLD profile MODULE? - -The big changes from standard profiling module are that you get more -information, and you pay less CPU time. It's not a trade-off, it's a -trade-up. - -To be specific: - - bugs removed: local stack frame is no longer molested, execution time - is now charged to correct functions, .... - - accuracy increased: profiler execution time is no longer charged to - user's code, calibration for platform is supported, file reads - are not done *by* profiler *during* profiling (and charged to - user's code!), ... - - speed increased: Overhead CPU cost was reduced by more than a factor of - two (perhaps a factor of five), lightweight profiler module is - all that must be loaded, and the report generating module - (pstats) is not needed during profiling. - - recursive functions support: cumulative times in recursive functions - are correctly calculated; recursive entries are counted; ... - - large growth in report generating UI: distinct profiles runs can be added - together forming a comprehensive report; functions that import - statistics take arbitrary lists of files; sorting criteria is now - based on keywords (instead of 4 integer options); reports shows - what functions were profiled as well as what profile file was - referenced; output format has been improved, ... - - -INSTANT USERS MANUAL - -This section is provided for users that "don't want to read the -manual." It provides a very brief overview, and allows a user to -rapidly perform profiling on an existing application. - -To profile an application with a main entry point of "foo()", you -would add the following to your module: - - import profile - profile.run("foo()") - -The above action would cause "foo()" to be run, and a series of -informative lines (the profile) to be printed. The above approach is -most useful when working with the interpreter. If you would like to -save the results of a profile into a file for later examination, you -can supply a file name as the second argument to the run() function: - - import profile - profile.run("foo()", 'fooprof') - -When you wish to review the profile, you should use the methods in the -pstats module. Typically you would load the statistics data as -follows: - - import pstats - p = pstats.Stats('fooprof') - -The class "Stats" (the above code just created an instance of this -class) has a variety of methods for manipulating and printing the data -that was just read into "p". When you ran profile.run() above, what -was printed was the result of three method calls: - - p.strip_dirs().sort_stats(-1).print_stats() - -The first method removed the extraneous path from all the module -names. The second method sorted all the entries according to the -standard module/line/name string that is printed (this is to comply -with the semantics of the old profiler). The third method printed out -all the statistics. You might try the following sort calls: - - p.sort_stats('name') - p.print_stats() - -The first call will actually sort the list by function name, and the -second call will print out the statistics. The following are some -interesting calls to experiment with: - - p.sort_stats('cumulative').print_stats(10) - -This sorts the profile by cumulative time in a function, and then only -prints the ten most significant lines. If you want to understand what -algorithms are taking time, the above line is what you would use. - -If you were looking to see what functions were looping a lot, and -taking a lot of time, you would do: - - p.sort_stats('time').print_stats(10) - -to sort according to time spent within each function, and then print -the statistics for the top ten functions. - -You might also try: - - p.sort_stats('file').print_stats('__init__') - -This will sort all the statistics by file name, and then print out -statistics for only the class init methods ('cause they are spelled -with "__init__" in them). As one final example, you could try: - - p.sort_stats('time', 'cum').print_stats(.5, 'init') - -This line sorts stats with a primary key of time, and a secondary key -of cumulative time, and then prints out some of the statistics. To be -specific, the list is first culled down to 50% (re: .5) of its -original size, then only lines containing "init" are maintained, and -that sub-sub-list is printed. - -If you wondered what functions called the above functions, you could -now (p is still sorted according to the last criteria) do: - - p.print_callers(.5, 'init') - -and you would get a list of callers for each of the listed functions. - -If you want more functionality, you're going to have to read the -manual (or guess) what the following functions do: - - p.print_callees() - p.add('fooprof') - - -WHAT IS DETERMINISTIC PROFILING? - -"Deterministic profiling" is meant to reflect the fact that all -"function call", "function return", and "exception" events are -monitored, and precise timings are made for the intervals between -these events (during which time the user's code is executing). In -contrast, "statistical profiling" (which is not done by this module) -randomly samples the effective instruction pointer, and deduces where -time is being spent. The latter technique traditionally involves less -overhead (as the code does not need to be instrumented), but provides -only relative indications of where time is being spent. - -In Python, since there is an interpreter active during execution, the -presence of instrumented code is not required to do deterministic -profiling. Python automatically provides a hook (optional callback) -for each event. In addition, the interpreted nature of Python tends -to add so much overhead to execution, that deterministic profiling -tends to only add small processing overhead, in typical applications. -The result is that deterministic profiling is not that expensive, but -yet provides extensive run time statistics about the execution of a -Python program. - -Call count statistics can be used to identify bugs in code (surprising -counts), and to identify possible inline-expansion points (high call -counts). Internal time statistics can be used to identify hot loops -that should be carefully optimized. Cumulative time statistics should -be used to identify high level errors in the selection of algorithms. -Note that the unusual handling of cumulative times in this profiler -allows statistics for recursive implementations of algorithms to be -directly compared to iterative implementations. - - -REFERENCE MANUAL - -The primary entry point for the profiler is the global function -profile.run(). It is typically used to create any profile -information. The reports are formatted and printed using methods for -the class pstats.Stats. The following is a description of all of -these standard entry points and functions. For a more in-depth view -of some of the code, consider reading the later section on "Profiler -Extensions," which includes discussion of how to derive "better" -profilers from the classes presented, or reading the source code for -these modules. - - -FUNCTION profile.run(string, filename_opt) - -This function takes a single argument that has can be passed to the -"exec" statement, and an optional file name. In all cases this -routine attempts to "exec" its first argument, and gather profiling -statistics from the execution. If no file name is present, then this -function automatically prints a simple profiling report, sorted by the -standard name string (file/line/function-name) that is presented in -each line. The following is a typical output from such a call: - -cut here---- - - main() - 2706 function calls (2004 primitive calls) in 4.504 CPU seconds - - Ordered by: standard name - - ncalls tottime percall cumtime percall filename:lineno(function) - 2 0.006 0.003 0.953 0.477 pobject.py:75(save_objects) - 43/3 0.533 0.012 0.749 0.250 pobject.py:99(evaluate) - ... - -cut here---- - -The first line indicates that this profile was generated by the call: -profile.run('main()'), and hence the exec'ed string is 'main()'. The -second line indicates that 2706 calls were monitored. Of those calls, -2004 were "primitive." We define "primitive" to mean that the call -was not induced via recursion. The next line: "Ordered by: standard -name", indicates that the text string in the far right column was used -to sort the output. The column headings include: - - "ncalls" for the number of calls, - "tottime" for the total time spent in the given function - (and excluding time made in calls to sub-functions), - "percall" is the quotient of "tottime" divided by "ncalls" - "cumtime" is the total time spent in this and all subfunctions - (i.e., from invocation till exit). This figure is - accurate *even* for recursive functions. - "percall" is the quotient of "cumtime" divided by primitive - calls - "filename:lineno(function)" provides the respective data of - each function - -When there are two numbers in the first column (e.g.: 43/3), then the -latter is the number of primitive calls, and the former is the actual -number of calls. Note that when the function does not recurse, these -two values are the same, and only the single figure is printed. - - -CLASS Stats(filename, ...) - -This class constructor creates an instance of a statistics object from -a filename (or set of filenames). Stats objects are manipulated by -methods, in order to print useful reports. - -The file selected by the above constructor must have been created by -the corresponding version of profile. To be specific, there is *NO* -file compatibility guaranteed with future versions of this profiler, -and there is no compatibility with files produced by other profilers -(e.g., the standard system profiler). - -If several files are provided, all the statistics for identical -functions will be coalesced, so that an overall view of several -processes can be considered in a single report. If additional files -need to be combined with data in an existing Stats object, the add() -method can be used. - - -METHOD strip_dirs() - -This method for the Stats class removes all leading path information -from file names. It is very useful in reducing the size of the -printout to fit within (close to) 80 columns. This method modifies -the object, and the striped information is lost. After performing a -strip operation, the object is considered to have its entries in a -"random" order, as it was just after object initialization and -loading. If strip_dir() causes two function names to be -indistinguishable (i.e., they are on the same line of the same -filename, and have the same function name), then the statistics for -these two entries are accumulated into a single entry. - - -METHOD add(filename, ...) - -This methods of the Stats class accumulates additional profiling -information into the current profiling object. Its arguments should -refer to filenames created my the corresponding version of -profile.run(). Statistics for identically named (re: file, line, -name) functions are automatically accumulated into single function -statistics. - - -METHOD sort_stats(key, ...) - -This method modifies the Stats object by sorting it according to the -supplied criteria. The argument is typically a string identifying the -basis of a sort (example: "time" or "name"). - -When more than one key is provided, then additional keys are used as -secondary criteria when there is equality in all keys selected -before them. For example, sort_stats('name', 'file') will sort all -the entries according to their function name, and resolve all ties -(identical function names) by sorting by file name. - -Abbreviations can be used for any key names, as long as the -abbreviation is unambiguous. The following are the keys currently -defined: - - Valid Arg Meaning - "calls" call count - "cumulative" cumulative time - "file" file name - "module" file name - "pcalls" primitive call count - "line" line number - "name" function name - "nfl" name/file/line - "stdname" standard name - "time" internal time - -Note that all sorts on statistics are in descending order (placing most -time consuming items first), where as name, file, and line number -searches are in ascending order (i.e., alphabetical). The subtle -distinction between "nfl" and "stdname" is that the standard name is a -sort of the name as printed, which means that the embedded line -numbers get compared in an odd way. For example, lines 3, 20, and 40 -would (if the file names were the same) appear in the string order -"20" "3" and "40". In contrast, "nfl" does a numeric compare of the -line numbers. In fact, sort_stats("nfl") is the same as -sort_stats("name", "file", "line"). - -For compatibility with the standard profiler, the numeric argument -1, -0, 1, and 2 are permitted. They are interpreted as "stdname", -"calls", "time", and "cumulative" respectively. If this old style -format (numeric) is used, only one sort key (the numeric key) will be -used, and additionally arguments will be silently ignored. - - -METHOD reverse_order() - -This method for the Stats class reverses the ordering of the basic -list within the object. This method is provided primarily for -compatibility with the standard profiler. Its utility is questionable -now that ascending vs descending order is properly selected based on -the sort key of choice. - - -METHOD print_stats(restriction, ...) - -This method for the Stats class prints out a report as described in -the profile.run() definition. - -The order of the printing is based on the last sort_stats() operation -done on the object (subject to caveats in add() and strip_dirs()). - -The arguments provided (if any) can be used to limit the list down to -the significant entries. Initially, the list is taken to be the -complete set of profiled functions. Each restriction is either an -integer (to select a count of lines), or a decimal fraction between -0.0 and 1.0 inclusive (to select a percentage of lines), or a regular -expression (to pattern match the standard name that is printed). If -several restrictions are provided, then they are applied sequentially. -For example: - - print_stats(.1, "foo:") - -would first limit the printing to first 10% of list, and then only -print functions that were part of filename ".*foo:". In contrast, the -command: - - print_stats("foo:", .1) - -would limit the list to all functions having file names ".*foo:", and -then proceed to only print the first 10% of them. - - -METHOD print_callers(restrictions, ...) - -This method for the Stats class prints a list of all functions that -called each function in the profiled database. The ordering is -identical to that provided by print_stats(), and the definition of the -restricting argument is also identical. For convenience, a number is -shown in parentheses after each caller to show how many times this -specific call was made. A second non-parenthesized number is the -cumulative time spent in the function at the right. - - -METHOD print_callees(restrictions, ...) - -This method for the Stats class prints a list of all function that -were called by the indicated function. Aside from this reversal of -direction of calls (re: called vs was called by), the arguments and -ordering are identical to the print_callers() method. - - -METHOD ignore() - -This method of the Stats class is used to dispose of the value -returned by earlier methods. All standard methods in this class -return the instance that is being processed, so that the commands can -be strung together. For example: - -pstats.Stats('foofile').strip_dirs().sort_stats('cum').print_stats().ignore() - -would perform all the indicated functions, but it would not return -the final reference to the Stats instance. - - - - -LIMITATIONS - -There are two fundamental limitations on this profiler. The first is -that it relies on the Python interpreter to dispatch "call", "return", -and "exception" events. Compiled C code does not get interpreted, -and hence is "invisible" to the profiler. All time spent in C code -(including builtin functions) will be charged to the Python function -that was invoked the C code. IF the C code calls out to some native -Python code, then those calls will be profiled properly. - -The second limitation has to do with accuracy of timing information. -There is a fundamental problem with deterministic profilers involving -accuracy. The most obvious restriction is that the underlying "clock" -is only ticking at a rate (typically) of about .001 seconds. Hence no -measurements will be more accurate than that underlying clock. If -enough measurements are taken, then the "error" will tend to average -out. Unfortunately, removing this first error induces a second source -of error... - -The second problem is that it "takes a while" from when an event is -dispatched until the profiler's call to get the time actually *gets* -the state of the clock. Similarly, there is a certain lag when -exiting the profiler event handler from the time that the clock's -value was obtained (and then squirreled away), until the user's code -is once again executing. As a result, functions that are called many -times, or call many functions, will typically accumulate this error. -The error that accumulates in this fashion is typically less than the -accuracy of the clock (i.e., less than one clock tick), but it *can* -accumulate and become very significant. This profiler provides a -means of calibrating itself for a give platform so that this error can -be probabilistically (i.e., on the average) removed. After the -profiler is calibrated, it will be more accurate (in a least square -sense), but it will sometimes produce negative numbers (when call -counts are exceptionally low, and the gods of probability work against -you :-). ) Do *NOT* be alarmed by negative numbers in the profile. -They should *only* appear if you have calibrated your profiler, and -the results are actually better than without calibration. - - -CALIBRATION - -The profiler class has a hard coded constant that is added to each -event handling time to compensate for the overhead of calling the time -function, and socking away the results. The following procedure can -be used to obtain this constant for a given platform (see discussion -in LIMITATIONS above). - - import profile - pr = profile.Profile() - pr.calibrate(100) - pr.calibrate(100) - pr.calibrate(100) - -The argument to calibrate() is the number of times to try to do the -sample calls to get the CPU times. If your computer is *very* fast, -you might have to do: - - pr.calibrate(1000) - -or even: - - pr.calibrate(10000) - -The object of this exercise is to get a fairly consistent result. -When you have a consistent answer, you are ready to use that number in -the source code. For a Sun Sparcstation 1000 running Solaris 2.3, the -magical number is about .00053. If you have a choice, you are better -off with a smaller constant, and your results will "less often" show -up as negative in profile statistics. - -The following shows how the trace_dispatch() method in the Profile -class should be modified to install the calibration constant on a Sun -Sparcstation 1000: - - def trace_dispatch(self, frame, event, arg): - t = self.timer() - t = t[0] + t[1] - self.t - .00053 # Calibration constant - - if self.dispatch[event](frame,t): - t = self.timer() - self.t = t[0] + t[1] - else: - r = self.timer() - self.t = r[0] + r[1] - t # put back unrecorded delta - return - -Note that if there is no calibration constant, then the line -containing the callibration constant should simply say: - - t = t[0] + t[1] - self.t # no calibration constant - -You can also achieve the same results using a derived class (and the -profiler will actually run equally fast!!), but the above method is -the simplest to use. I could have made the profiler "self -calibrating", but it would have made the initialization of the -profiler class slower, and would have required some *very* fancy -coding, or else the use of a variable where the constant .00053 was -placed in the code shown. This is a ****VERY**** critical performance -section, and there is no reason to use a variable lookup at this -point, when a constant can be used. - - -EXTENSIONS: Deriving Better Profilers - -The Profile class of profile was written so that derived classes -could be developed to extend the profiler. Rather than describing all -the details of such an effort, I'll just present the following two -examples of derived classes that can be used to do profiling. If the -reader is an avid Python programmer, then it should be possible to use -these as a model and create similar (and perchance better) profile -classes. - -If all you want to do is change how the timer is called, or which -timer function is used, then the basic class has an option for that in -the constructor for the class. Consider passing the name of a -function to call into the constructor: - - pr = profile.Profile(your_time_func) - -The resulting profiler will call your time function instead of -os.times(). The function should return either a single number, or a -list of numbers (like what os.times() returns). If the function -returns a single time number, or the list of returned numbers has -length 2, then you will get an especially fast version of the dispatch -routine. - -Be warned that you *should* calibrate the profiler class for the -timer function that you choose. For most machines, a timer that -returns a lone integer value will provide the best results in terms of -low overhead during profiling. (os.times is *pretty* bad, 'cause it -returns a tuple of floating point values, so all arithmetic is -floating point in the profiler!). If you want to be substitute a -better timer in the cleanest fashion, you should derive a class, and -simply put in the replacement dispatch method that better handles your timer -call, along with the appropriate calibration constant :-). - - -cut here------------------------------------------------------------------ -#**************************************************************************** -# OldProfile class documentation -#**************************************************************************** -# -# The following derived profiler simulates the old style profile, providing -# errant results on recursive functions. The reason for the usefulness of this -# profiler is that it runs faster (i.e., less overhead) than the old -# profiler. It still creates all the caller stats, and is quite -# useful when there is *no* recursion in the user's code. It is also -# a lot more accurate than the old profiler, as it does not charge all -# its overhead time to the user's code. -#**************************************************************************** -class OldProfile(Profile): - def trace_dispatch_exception(self, frame, t): - rt, rtt, rct, rfn, rframe, rcur = self.cur - if rcur and not rframe is frame: - return self.trace_dispatch_return(rframe, t) - return 0 - - def trace_dispatch_call(self, frame, t): - fn = `frame.f_code` - - self.cur = (t, 0, 0, fn, frame, self.cur) - if self.timings.has_key(fn): - tt, ct, callers = self.timings[fn] - self.timings[fn] = tt, ct, callers - else: - self.timings[fn] = 0, 0, {} - return 1 - - def trace_dispatch_return(self, frame, t): - rt, rtt, rct, rfn, frame, rcur = self.cur - rtt = rtt + t - sft = rtt + rct - - pt, ptt, pct, pfn, pframe, pcur = rcur - self.cur = pt, ptt+rt, pct+sft, pfn, pframe, pcur - - tt, ct, callers = self.timings[rfn] - if callers.has_key(pfn): - callers[pfn] = callers[pfn] + 1 - else: - callers[pfn] = 1 - self.timings[rfn] = tt+rtt, ct + sft, callers - - return 1 - - - def snapshot_stats(self): - self.stats = {} - for func in self.timings.keys(): - tt, ct, callers = self.timings[func] - nor_func = self.func_normalize(func) - nor_callers = {} - nc = 0 - for func_caller in callers.keys(): - nor_callers[self.func_normalize(func_caller)]=\ - callers[func_caller] - nc = nc + callers[func_caller] - self.stats[nor_func] = nc, nc, tt, ct, nor_callers - - - -#**************************************************************************** -# HotProfile class documentation -#**************************************************************************** -# -# This profiler is the fastest derived profile example. It does not -# calculate caller-callee relationships, and does not calculate cumulative -# time under a function. It only calculates time spent in a function, so -# it runs very quickly (re: very low overhead). In truth, the basic -# profiler is so fast, that is probably not worth the savings to give -# up the data, but this class still provides a nice example. -#**************************************************************************** -class HotProfile(Profile): - def trace_dispatch_exception(self, frame, t): - rt, rtt, rfn, rframe, rcur = self.cur - if rcur and not rframe is frame: - return self.trace_dispatch_return(rframe, t) - return 0 - - def trace_dispatch_call(self, frame, t): - self.cur = (t, 0, frame, self.cur) - return 1 - - def trace_dispatch_return(self, frame, t): - rt, rtt, frame, rcur = self.cur - - rfn = `frame.f_code` - - pt, ptt, pframe, pcur = rcur - self.cur = pt, ptt+rt, pframe, pcur - - if self.timings.has_key(rfn): - nc, tt = self.timings[rfn] - self.timings[rfn] = nc + 1, rt + rtt + tt - else: - self.timings[rfn] = 1, rt + rtt - - return 1 - - - def snapshot_stats(self): - self.stats = {} - for func in self.timings.keys(): - nc, tt = self.timings[func] - nor_func = self.func_normalize(func) - self.stats[nor_func] = nc, nc, tt, 0, {} - - - -cut here------------------------------------------------------------------ diff --git a/Lib/profile.py b/Lib/profile.py index 9d7e284..4b5eb4d 100755 --- a/Lib/profile.py +++ b/Lib/profile.py @@ -4,8 +4,6 @@ # # Based on prior profile module by Sjoerd Mullender... # which was hacked somewhat by: Guido van Rossum -# -# See profile.doc for more information """Class for profiling Python code.""" @@ -94,18 +92,10 @@ def runctx(statement, globals, locals, filename=None): else: return prof.print_stats() -# print help +# Backwards compatibility. def help(): - for dirname in sys.path: - fullname = os.path.join(dirname, 'profile.doc') - if os.path.exists(fullname): - sts = os.system('${PAGER-more} ' + fullname) - if sts: print '*** Pager exit status:', sts - break - else: - print 'Sorry, can\'t find the help file "profile.doc"', - print 'along the Python search path.' - + print "Documentation for the profile module can be found " + print "in the Python Library Reference, section 'The Python Profiler'." if os.name == "mac": import MacOS |