diff options
Diffstat (limited to 'Doc')
| -rw-r--r-- | Doc/Makefile | 4 | ||||
| -rw-r--r-- | Doc/lib.tex | 5 | ||||
| -rw-r--r-- | Doc/lib/lib.tex | 5 | ||||
| -rw-r--r-- | Doc/lib/libprofile.tex | 752 | ||||
| -rw-r--r-- | Doc/libprofile.tex | 752 |
5 files changed, 1514 insertions, 4 deletions
diff --git a/Doc/Makefile b/Doc/Makefile index 95ff674..a3200ec 100644 --- a/Doc/Makefile +++ b/Doc/Makefile @@ -45,8 +45,8 @@ libmac.tex libmacconsole.tex libmacfs.tex libmactcp.tex libmacspeech.tex \ libmd5.tex libmimetools.tex libmm.tex libmods.tex libmpz.tex \ libnntplib.tex \ libobjs.tex libos.tex \ -libpanel.tex libposix.tex libposixfile.tex libppath.tex libpickle.tex \ - libpwd.tex \ +libpanel.tex libpickle.tex libposix.tex libposixfile.tex \ + libppath.tex libprofile.tex libpwd.tex \ librand.tex libregex.tex libregsub.tex \ librfc822.tex librgbimg.tex librotor.tex \ libselect.tex libsgi.tex libsgmllib.tex \ diff --git a/Doc/lib.tex b/Doc/lib.tex index aa1846e..0d2f7b7 100644 --- a/Doc/lib.tex +++ b/Doc/lib.tex @@ -77,7 +77,10 @@ language. \input{libtypes2} % types is already taken :-( \input{libtempfile} \input{libtraceback} -\input{libpdb} + +\input{libpdb} % The Python Debugger + +\input{libprofile} % The Python Profiler \input{libunix} % UNIX ONLY \input{libdbm} diff --git a/Doc/lib/lib.tex b/Doc/lib/lib.tex index aa1846e..0d2f7b7 100644 --- a/Doc/lib/lib.tex +++ b/Doc/lib/lib.tex @@ -77,7 +77,10 @@ language. \input{libtypes2} % types is already taken :-( \input{libtempfile} \input{libtraceback} -\input{libpdb} + +\input{libpdb} % The Python Debugger + +\input{libprofile} % The Python Profiler \input{libunix} % UNIX ONLY \input{libdbm} diff --git a/Doc/lib/libprofile.tex b/Doc/lib/libprofile.tex new file mode 100644 index 0000000..8c2599e --- /dev/null +++ b/Doc/lib/libprofile.tex @@ -0,0 +1,752 @@ +\chapter{The Python Profiler} +\stmodindex{profile} +\stmodindex{pstats} + +Copyright 1994, by InfoSeek Corporation, all rights reserved. + +Written by James Roskind% +\footnote{ +Updated and converted to LaTeX by Guido van Rossum. The references to +the old profiler are left in the text, although it no longer exists. +} + +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: +\code{jar@infoseek.com}. I won't promise \emph{any} support. ...but +I'd appreciate the feedback. + + +\section{Introduction} + +A \dfn{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 +\code{profile} and \code{pstats.} This profiler provides +\dfn{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. + + +\section{How Is This Profiler Different From The Old Profiler?} + +The big changes from old 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: + +\begin{description} + +\item[Bugs removed:] +Local stack frame is no longer molested, execution time is now charged +to correct functions. + +\item[Accuracy increased:] +Profiler execution time is no longer charged to user's code, +calibration for platform is supported, file reads are not done \emph{by} +profiler \emph{during} profiling (and charged to user's code!). + +\item[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 (\code{pstats}) is not needed +during profiling. + +\item[Recursive functions support:] +Cumulative times in recursive functions are correctly calculated; +recursive entries are counted. + +\item[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. + +\end{description} + + +\section{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 \samp{foo()}, you +would add the following to your module: + +\begin{verbatim} + import profile + profile.run("foo()") +\end{verbatim} + +The above action would cause \samp{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 \code{run()} +function: + +\begin{verbatim} + import profile + profile.run("foo()", 'fooprof') +\end{verbatim} + +When you wish to review the profile, you should use the methods in the +\code{pstats} module. Typically you would load the statistics data as +follows: + +\begin{verbatim} + import pstats + p = pstats.Stats('fooprof') +\end{verbatim} + +The class \code{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 \samp{p}. When you ran +\code{profile.run()} above, what was printed was the result of three +method calls: + +\begin{verbatim} + p.strip_dirs().sort_stats(-1).print_stats() +\end{verbatim} + +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: + +\begin{verbatim} + p.sort_stats('name') + p.print_stats() +\end{verbatim} + +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: + +\begin{verbatim} + p.sort_stats('cumulative').print_stats(10) +\end{verbatim} + +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: + +\begin{verbatim} + p.sort_stats('time').print_stats(10) +\end{verbatim} + +to sort according to time spent within each function, and then print +the statistics for the top ten functions. + +You might also try: + +\begin{verbatim} + p.sort_stats('file').print_stats('__init__') +\end{verbatim} + +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 \code{__init__} in them). As one final example, you could try: + +\begin{verbatim} + p.sort_stats('time', 'cum').print_stats(.5, 'init') +\end{verbatim} + +This line sorts statistics 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: \samp{.5}) +of its original size, then only lines containing \code{init} are +maintained, and that sub-sub-list is printed. + +If you wondered what functions called the above functions, you could +now (\samp{p} is still sorted according to the last criteria) do: + +\begin{verbatim} + p.print_callers(.5, 'init') +\end{verbatim} + +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: + +\begin{verbatim} + p.print_callees() + p.add('fooprof') +\end{verbatim} + + +\section{What Is Deterministic Profiling?} + +\dfn{Deterministic profiling} is meant to reflect the fact that all +\dfn{function call}, \dfn{function return}, and \dfn{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, \dfn{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 \dfn{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, 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. + + +\section{Reference Manual} + +\renewcommand{\indexsubitem}{} + +The primary entry point for the profiler is the global function +\code{profile.run()}. It is typically used to create any profile +information. The reports are formatted and printed using methods of +the class \code{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. + +\begin{funcdesc}{profile.run}{string\optional{\, filename}} + +This function takes a single argument that has can be passed to the +\code{exec} statement, and an optional file name. In all cases this +routine attempts to \code{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: + +\begin{verbatim} + 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) + ... +\end{verbatim} + +The first line indicates that this profile was generated by the call:\\ +\code{profile.run('main()')}, and hence the exec'ed string is +\code{'main()'}. The second line indicates that 2706 calls were +monitored. Of those calls, 2004 were \dfn{primitive}. We define +\dfn{primitive} to mean that the call was not induced via recursion. +The next line: \code{Ordered by:\ standard name}, indicates that +the text string in the far right column was used to sort the output. +The column headings include: + +\begin{description} + +\item[ncalls ] +for the number of calls, + +\item[tottime ] +for the total time spent in the given function (and excluding time +made in calls to sub-functions), + +\item[percall ] +is the quotient of \code{tottime} divided by \code{ncalls} + +\item[cumtime ] +is the total time spent in this and all subfunctions (i.e., from +invocation till exit). This figure is accurate \emph{even} for recursive +functions. + +\item[percall ] +is the quotient of \code{cumtime} divided by primitive calls + +\item[filename:lineno(function) ] +provides the respective data of each function + +\end{description} + +When there are two numbers in the first column (e.g.: \samp{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. +\end{funcdesc} + +\begin{funcdesc}{pstats.Stats}{filename\optional{\, ...}} +This class constructor creates an instance of a ``statistics object'' +from a \var{filename} (or set of filenames). \code{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 \code{profile}. To be specific, there is +\emph{NO} file compatibility guaranteed with future versions of this +profiler, and there is no compatibility with files produced by other +profilers (e.g., the old 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 \code{Stats} object, the +\code{add()} method can be used. +\end{funcdesc} + + +\subsection{Methods Of The \sectcode{Stats} Class} + +\renewcommand{\indexsubitem}{(Stats method)} + +\begin{funcdesc}{strip_dirs}{} +This method for the code{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 stripped 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 \code{strip_dirs()} 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. +\end{funcdesc} + + +\begin{funcdesc}{add}{filename\optional{\, ...}} +This method of the code{Stats} class accumulates additional profiling +information into the current profiling object. Its arguments should +refer to filenames created by the corresponding version of +\code{profile.run()}. Statistics for identically named (re: file, +line, name) functions are automatically accumulated into single +function statistics. +\end{funcdesc} + +\begin{funcdesc}{sort_stats}{key\optional{\, ...}} +This method modifies the code{Stats} object by sorting it according to the +supplied criteria. The argument is typically a string identifying the +basis of a sort (example: \code{"time"} or \code{"name"}). + +When more than one key is provided, then additional keys are used as +secondary criteria when the 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: + +\begin{tableii}{|l|l|}{code}{Valid Arg}{Meaning} +\lineii{"calls"}{call count} +\lineii{"cumulative"}{cumulative time} +\lineii{"file"}{file name} +\lineii{"module"}{file name} +\lineii{"pcalls"}{primitive call count} +\lineii{"line"}{line number} +\lineii{"name"}{function name} +\lineii{"nfl"}{name/file/line} +\lineii{"stdname"}{standard name} +\lineii{"time"}{internal time} +\end{tableii} + +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 \code{"nfl"} and \code{"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, \code{"nfl"} does a numeric +compare of the line numbers. In fact, \code{sort_stats("nfl")} is the +same as \code{sort_stats("name", "file", "line")}. + +For compatibility with the old profiler, the numeric arguments +\samp{-1}, \samp{0}, \samp{1}, and \samp{2} are permitted. They are +interpreted as \code{"stdname"}, \code{"calls"}, \code{"time"}, and +\code{"cumulative"} respectively. If this old style format (numeric) +is used, only one sort key (the numeric key) will be used, and +additional arguments will be silently ignored. +\end{funcdesc} + + +\begin{funcdesc}{reverse_order}{} +This method for the code{Stats} class reverses the ordering of the basic +list within the object. This method is provided primarily for +compatibility with the old profiler. Its utility is questionable +now that ascending vs descending order is properly selected based on +the sort key of choice. +\end{funcdesc} + +\begin{funcdesc}{print_stats}{restriction\optional{\, ...}} +This method for the code{Stats} class prints out a report as described +in the \code{profile.run()} definition. + +The order of the printing is based on the last \code{sort_stats()} +operation done on the object (subject to caveats in \code{add()} and +\code{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: + +\begin{verbatim} + print_stats(.1, "foo:") +\end{verbatim} + +would first limit the printing to first 10\% of list, and then only +print functions that were part of filename \samp{.*foo:}. In +contrast, the command: + +\begin{verbatim} + print_stats("foo:", .1) +\end{verbatim} + +would limit the list to all functions having file names \samp{.*foo:}, +and then proceed to only print the first 10\% of them. +\end{funcdesc} + + +\begin{funcdesc}{print_callers}{restrictions\optional{\, ...}} +This method for the code{Stats} class prints a list of all functions +that called each function in the profiled database. The ordering is +identical to that provided by \code{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. +\end{funcdesc} + +\begin{funcdesc}{print_callees}{restrictions\optional{\, ...}} +This method for the code{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 \code{print_callers()} method. +\end{funcdesc} + +\begin{funcdesc}{ignore}{} +This method of the code{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: + +\begin{verbatim} +pstats.Stats('foofile').strip_dirs().sort_stats('cum').print_stats().ignore() +\end{verbatim} + +would perform all the indicated functions, but it would not return +the final reference to the code{Stats} instance.% +\footnote{ +This was once necessary, when Python would print any unused expression +result that was not \code{None}. The method is still defined for +backward compatibility. +} +\end{funcdesc} + + +\section{Limitations} + +There are two fundamental limitations on this profiler. The first is +that it relies on the Python interpreter to dispatch \dfn{call}, +\dfn{return}, and \dfn{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 that 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 +\emph{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 +\emph{can} accumulate and become very significant. This profiler +provides a means of calibrating itself for a given 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 \emph{NOT} be alarmed by negative numbers in +the profile. They should \emph{only} appear if you have calibrated +your profiler, and the results are actually better than without +calibration. + + +\section{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 section Limitations above). + +\begin{verbatim} + import profile + pr = profile.Profile() + pr.calibrate(100) + pr.calibrate(100) + pr.calibrate(100) +\end{verbatim} + +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 \emph{very} +fast, you might have to do: + +\begin{verbatim} + pr.calibrate(1000) +\end{verbatim} + +or even: + +\begin{verbatim} + pr.calibrate(10000) +\end{verbatim} + +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: + +\begin{verbatim} + 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 +\end{verbatim} + +Note that if there is no calibration constant, then the line +containing the callibration constant should simply say: + +\begin{verbatim} + t = t[0] + t[1] - self.t # no calibration constant +\end{verbatim} + +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 \emph{very} fancy +coding, or else the use of a variable where the constant \samp{.00053} +was placed in the code shown. This is a \strong{VERY} critical +performance section, and there is no reason to use a variable lookup +at this point, when a constant can be used. + + +\section{Extensions: Deriving Better Profilers} + +The \code{Profile} class of module \code{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: + +\begin{verbatim} + pr = profile.Profile(your_time_func) +\end{verbatim} + +The resulting profiler will call \code{your_time_func()} instead of +\code{os.times()}. The function should return either a single number +or a list of numbers (like what \code{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 \emph{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 \emph{pretty} bad, 'cause +it returns a tuple of floating point values, so all arithmetic is +floating point in the profiler!). If you want to 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 :-). + + +\subsection{OldProfile Class} + +The following derived profiler simulates the old style profiler, +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 \emph{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. + +\begin{verbatim} +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 +\end{verbatim} + + +\subsection{HotProfile Class} + +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. + +\begin{verbatim} +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, {} +\end{verbatim} diff --git a/Doc/libprofile.tex b/Doc/libprofile.tex new file mode 100644 index 0000000..8c2599e --- /dev/null +++ b/Doc/libprofile.tex @@ -0,0 +1,752 @@ +\chapter{The Python Profiler} +\stmodindex{profile} +\stmodindex{pstats} + +Copyright 1994, by InfoSeek Corporation, all rights reserved. + +Written by James Roskind% +\footnote{ +Updated and converted to LaTeX by Guido van Rossum. The references to +the old profiler are left in the text, although it no longer exists. +} + +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: +\code{jar@infoseek.com}. I won't promise \emph{any} support. ...but +I'd appreciate the feedback. + + +\section{Introduction} + +A \dfn{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 +\code{profile} and \code{pstats.} This profiler provides +\dfn{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. + + +\section{How Is This Profiler Different From The Old Profiler?} + +The big changes from old 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: + +\begin{description} + +\item[Bugs removed:] +Local stack frame is no longer molested, execution time is now charged +to correct functions. + +\item[Accuracy increased:] +Profiler execution time is no longer charged to user's code, +calibration for platform is supported, file reads are not done \emph{by} +profiler \emph{during} profiling (and charged to user's code!). + +\item[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 (\code{pstats}) is not needed +during profiling. + +\item[Recursive functions support:] +Cumulative times in recursive functions are correctly calculated; +recursive entries are counted. + +\item[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. + +\end{description} + + +\section{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 \samp{foo()}, you +would add the following to your module: + +\begin{verbatim} + import profile + profile.run("foo()") +\end{verbatim} + +The above action would cause \samp{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 \code{run()} +function: + +\begin{verbatim} + import profile + profile.run("foo()", 'fooprof') +\end{verbatim} + +When you wish to review the profile, you should use the methods in the +\code{pstats} module. Typically you would load the statistics data as +follows: + +\begin{verbatim} + import pstats + p = pstats.Stats('fooprof') +\end{verbatim} + +The class \code{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 \samp{p}. When you ran +\code{profile.run()} above, what was printed was the result of three +method calls: + +\begin{verbatim} + p.strip_dirs().sort_stats(-1).print_stats() +\end{verbatim} + +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: + +\begin{verbatim} + p.sort_stats('name') + p.print_stats() +\end{verbatim} + +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: + +\begin{verbatim} + p.sort_stats('cumulative').print_stats(10) +\end{verbatim} + +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: + +\begin{verbatim} + p.sort_stats('time').print_stats(10) +\end{verbatim} + +to sort according to time spent within each function, and then print +the statistics for the top ten functions. + +You might also try: + +\begin{verbatim} + p.sort_stats('file').print_stats('__init__') +\end{verbatim} + +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 \code{__init__} in them). As one final example, you could try: + +\begin{verbatim} + p.sort_stats('time', 'cum').print_stats(.5, 'init') +\end{verbatim} + +This line sorts statistics 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: \samp{.5}) +of its original size, then only lines containing \code{init} are +maintained, and that sub-sub-list is printed. + +If you wondered what functions called the above functions, you could +now (\samp{p} is still sorted according to the last criteria) do: + +\begin{verbatim} + p.print_callers(.5, 'init') +\end{verbatim} + +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: + +\begin{verbatim} + p.print_callees() + p.add('fooprof') +\end{verbatim} + + +\section{What Is Deterministic Profiling?} + +\dfn{Deterministic profiling} is meant to reflect the fact that all +\dfn{function call}, \dfn{function return}, and \dfn{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, \dfn{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 \dfn{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, 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. + + +\section{Reference Manual} + +\renewcommand{\indexsubitem}{} + +The primary entry point for the profiler is the global function +\code{profile.run()}. It is typically used to create any profile +information. The reports are formatted and printed using methods of +the class \code{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. + +\begin{funcdesc}{profile.run}{string\optional{\, filename}} + +This function takes a single argument that has can be passed to the +\code{exec} statement, and an optional file name. In all cases this +routine attempts to \code{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: + +\begin{verbatim} + 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) + ... +\end{verbatim} + +The first line indicates that this profile was generated by the call:\\ +\code{profile.run('main()')}, and hence the exec'ed string is +\code{'main()'}. The second line indicates that 2706 calls were +monitored. Of those calls, 2004 were \dfn{primitive}. We define +\dfn{primitive} to mean that the call was not induced via recursion. +The next line: \code{Ordered by:\ standard name}, indicates that +the text string in the far right column was used to sort the output. +The column headings include: + +\begin{description} + +\item[ncalls ] +for the number of calls, + +\item[tottime ] +for the total time spent in the given function (and excluding time +made in calls to sub-functions), + +\item[percall ] +is the quotient of \code{tottime} divided by \code{ncalls} + +\item[cumtime ] +is the total time spent in this and all subfunctions (i.e., from +invocation till exit). This figure is accurate \emph{even} for recursive +functions. + +\item[percall ] +is the quotient of \code{cumtime} divided by primitive calls + +\item[filename:lineno(function) ] +provides the respective data of each function + +\end{description} + +When there are two numbers in the first column (e.g.: \samp{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. +\end{funcdesc} + +\begin{funcdesc}{pstats.Stats}{filename\optional{\, ...}} +This class constructor creates an instance of a ``statistics object'' +from a \var{filename} (or set of filenames). \code{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 \code{profile}. To be specific, there is +\emph{NO} file compatibility guaranteed with future versions of this +profiler, and there is no compatibility with files produced by other +profilers (e.g., the old 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 \code{Stats} object, the +\code{add()} method can be used. +\end{funcdesc} + + +\subsection{Methods Of The \sectcode{Stats} Class} + +\renewcommand{\indexsubitem}{(Stats method)} + +\begin{funcdesc}{strip_dirs}{} +This method for the code{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 stripped 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 \code{strip_dirs()} 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. +\end{funcdesc} + + +\begin{funcdesc}{add}{filename\optional{\, ...}} +This method of the code{Stats} class accumulates additional profiling +information into the current profiling object. Its arguments should +refer to filenames created by the corresponding version of +\code{profile.run()}. Statistics for identically named (re: file, +line, name) functions are automatically accumulated into single +function statistics. +\end{funcdesc} + +\begin{funcdesc}{sort_stats}{key\optional{\, ...}} +This method modifies the code{Stats} object by sorting it according to the +supplied criteria. The argument is typically a string identifying the +basis of a sort (example: \code{"time"} or \code{"name"}). + +When more than one key is provided, then additional keys are used as +secondary criteria when the 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: + +\begin{tableii}{|l|l|}{code}{Valid Arg}{Meaning} +\lineii{"calls"}{call count} +\lineii{"cumulative"}{cumulative time} +\lineii{"file"}{file name} +\lineii{"module"}{file name} +\lineii{"pcalls"}{primitive call count} +\lineii{"line"}{line number} +\lineii{"name"}{function name} +\lineii{"nfl"}{name/file/line} +\lineii{"stdname"}{standard name} +\lineii{"time"}{internal time} +\end{tableii} + +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 \code{"nfl"} and \code{"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, \code{"nfl"} does a numeric +compare of the line numbers. In fact, \code{sort_stats("nfl")} is the +same as \code{sort_stats("name", "file", "line")}. + +For compatibility with the old profiler, the numeric arguments +\samp{-1}, \samp{0}, \samp{1}, and \samp{2} are permitted. They are +interpreted as \code{"stdname"}, \code{"calls"}, \code{"time"}, and +\code{"cumulative"} respectively. If this old style format (numeric) +is used, only one sort key (the numeric key) will be used, and +additional arguments will be silently ignored. +\end{funcdesc} + + +\begin{funcdesc}{reverse_order}{} +This method for the code{Stats} class reverses the ordering of the basic +list within the object. This method is provided primarily for +compatibility with the old profiler. Its utility is questionable +now that ascending vs descending order is properly selected based on +the sort key of choice. +\end{funcdesc} + +\begin{funcdesc}{print_stats}{restriction\optional{\, ...}} +This method for the code{Stats} class prints out a report as described +in the \code{profile.run()} definition. + +The order of the printing is based on the last \code{sort_stats()} +operation done on the object (subject to caveats in \code{add()} and +\code{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: + +\begin{verbatim} + print_stats(.1, "foo:") +\end{verbatim} + +would first limit the printing to first 10\% of list, and then only +print functions that were part of filename \samp{.*foo:}. In +contrast, the command: + +\begin{verbatim} + print_stats("foo:", .1) +\end{verbatim} + +would limit the list to all functions having file names \samp{.*foo:}, +and then proceed to only print the first 10\% of them. +\end{funcdesc} + + +\begin{funcdesc}{print_callers}{restrictions\optional{\, ...}} +This method for the code{Stats} class prints a list of all functions +that called each function in the profiled database. The ordering is +identical to that provided by \code{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. +\end{funcdesc} + +\begin{funcdesc}{print_callees}{restrictions\optional{\, ...}} +This method for the code{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 \code{print_callers()} method. +\end{funcdesc} + +\begin{funcdesc}{ignore}{} +This method of the code{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: + +\begin{verbatim} +pstats.Stats('foofile').strip_dirs().sort_stats('cum').print_stats().ignore() +\end{verbatim} + +would perform all the indicated functions, but it would not return +the final reference to the code{Stats} instance.% +\footnote{ +This was once necessary, when Python would print any unused expression +result that was not \code{None}. The method is still defined for +backward compatibility. +} +\end{funcdesc} + + +\section{Limitations} + +There are two fundamental limitations on this profiler. The first is +that it relies on the Python interpreter to dispatch \dfn{call}, +\dfn{return}, and \dfn{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 that 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 +\emph{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 +\emph{can} accumulate and become very significant. This profiler +provides a means of calibrating itself for a given 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 \emph{NOT} be alarmed by negative numbers in +the profile. They should \emph{only} appear if you have calibrated +your profiler, and the results are actually better than without +calibration. + + +\section{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 section Limitations above). + +\begin{verbatim} + import profile + pr = profile.Profile() + pr.calibrate(100) + pr.calibrate(100) + pr.calibrate(100) +\end{verbatim} + +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 \emph{very} +fast, you might have to do: + +\begin{verbatim} + pr.calibrate(1000) +\end{verbatim} + +or even: + +\begin{verbatim} + pr.calibrate(10000) +\end{verbatim} + +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: + +\begin{verbatim} + 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 +\end{verbatim} + +Note that if there is no calibration constant, then the line +containing the callibration constant should simply say: + +\begin{verbatim} + t = t[0] + t[1] - self.t # no calibration constant +\end{verbatim} + +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 \emph{very} fancy +coding, or else the use of a variable where the constant \samp{.00053} +was placed in the code shown. This is a \strong{VERY} critical +performance section, and there is no reason to use a variable lookup +at this point, when a constant can be used. + + +\section{Extensions: Deriving Better Profilers} + +The \code{Profile} class of module \code{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: + +\begin{verbatim} + pr = profile.Profile(your_time_func) +\end{verbatim} + +The resulting profiler will call \code{your_time_func()} instead of +\code{os.times()}. The function should return either a single number +or a list of numbers (like what \code{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 \emph{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 \emph{pretty} bad, 'cause +it returns a tuple of floating point values, so all arithmetic is +floating point in the profiler!). If you want to 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 :-). + + +\subsection{OldProfile Class} + +The following derived profiler simulates the old style profiler, +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 \emph{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. + +\begin{verbatim} +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 +\end{verbatim} + + +\subsection{HotProfile Class} + +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. + +\begin{verbatim} +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, {} +\end{verbatim} |