\chapter{The Python Profilers \label{profile}} \sectionauthor{James Roskind}{} Copyright \copyright{} 1994, by InfoSeek Corporation, all rights reserved.\index{InfoSeek Corporation} Written by James Roskind.\footnote{  Updated and converted to \LaTeX\ by Guido van Rossum.  Further updated by Armin Rigo to integrate the documentation for the new  \module{cProfile} module of Python 2.5.} Permission to use, copy, modify, and distribute this Python softwareand its associated documentation for any purpose (subject to therestriction in the following sentence) without fee is hereby granted,provided that the above copyright notice appears in all copies, andthat both that copyright notice and this permission notice appear insupporting documentation, and that the name of InfoSeek not be used inadvertising or publicity pertaining to distribution of the softwarewithout specific, written prior permission.  This permission isexplicitly restricted to the copying and modification of the softwareto remain in Python, compiled Python, or other languages (such as C)wherein the modified or derived code is exclusively imported into aPython module. INFOSEEK CORPORATION DISCLAIMS ALL WARRANTIES WITH REGARD TO THISSOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY ANDFITNESS. IN NO EVENT SHALL INFOSEEK CORPORATION BE LIABLE FOR ANYSPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVERRESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OFCONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR INCONNECTION 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 torepeat code fragments, but I'm sure I did some stuff in really awkwardways at times.  Please send suggestions for improvements to:\email{jar@netscape.com}.  I won't promise \emph{any} support.  ...butI'd appreciate the feedback.  \section{Introduction to the profilers}\nodename{Profiler Introduction} A \dfn{profiler} is a program that describes the run time performanceof a program, providing a variety of statistics.  This documentationdescribes the profiler functionality provided in the modules\module{profile} and \module{pstats}.  This profiler provides\dfn{deterministic profiling} of any Python programs.  It alsoprovides a series of report generation tools to allow users to rapidlyexamine the results of a profile operation.\index{deterministic profiling}\index{profiling, deterministic} The Python standard library provides three different profilers: \begin{enumerate}\item \module{profile}, a pure Python module, described in the sequel.  Copyright \copyright{} 1994, by InfoSeek Corporation.  \versionchanged[also reports the time spent in calls to built-in  functions and methods]{2.4} \item \module{cProfile}, a module written in C, with a reasonable  overhead that makes it suitable for profiling long-running programs.  Based on \module{lsprof}, contributed by Brett Rosen and Ted Czotter.  \versionadded{2.5} \item \module{hotshot}, a C module focusing on minimizing the overhead  while profiling, at the expense of long data post-processing times.  \versionchanged[the results should be more meaningful than in the  past: the timing core contained a critical bug]{2.5}\end{enumerate} The \module{profile} and \module{cProfile} modules export the sameinterface, so they are mostly interchangeables; \module{cProfile} has amuch lower overhead but is not so far as well-tested and might not beavailable on all systems.  \module{cProfile} is really a compatibilitylayer on top of the internal \module{_lsprof} module.  The\module{hotshot} module is reserved to specialized usages. %\section{How Is This Profiler Different From The Old Profiler?}%\nodename{Profiler Changes}%%(This section is of historical importance only; the old profiler%discussed here was last seen in Python 1.1.)%%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 (\module{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 User's Manual \label{profile-instant}} This section is provided for users that ``don't want to read themanual.'' It provides a very brief overview, and allows a user torapidly perform profiling on an existing application. To profile an application with a main entry point of \function{foo()},you would add the following to your module: \begin{verbatim}import cProfilecProfile.run('foo()')\end{verbatim} (Use \module{profile} instead of \module{cProfile} if the latter is notavailable on your system.) The above action would cause \function{foo()} to be run, and a series ofinformative lines (the profile) to be printed.  The above approach ismost useful when working with the interpreter.  If you would like tosave the results of a profile into a file for later examination, youcan supply a file name as the second argument to the \function{run()}function: \begin{verbatim}import cProfilecProfile.run('foo()', 'fooprof')\end{verbatim} The file \file{cProfile.py} can also be invoked asa script to profile another script.  For example: \begin{verbatim}python -m cProfile myscript.py\end{verbatim} \file{cProfile.py} accepts two optional arguments on the command line: \begin{verbatim}cProfile.py [-o output_file] [-s sort_order]\end{verbatim} \programopt{-s} only applies to standard output (\programopt{-o} isnot supplied).  Look in the \class{Stats} documentation for valid sortvalues. When you wish to review the profile, you should use the methods in the\module{pstats} module.  Typically you would load the statistics data asfollows: \begin{verbatim}import pstatsp = pstats.Stats('fooprof')\end{verbatim} The class \class{Stats} (the above code just created an instance ofthis class) has a variety of methods for manipulating and printing thedata that was just read into \code{p}.  When you ran\function{cProfile.run()} above, what was printed was the result of threemethod calls: \begin{verbatim}p.strip_dirs().sort_stats(-1).print_stats()\end{verbatim} The first method removed the extraneous path from all the modulenames. The second method sorted all the entries according to thestandard module/line/name string that is printed.%(this is to comply with the semantics of the old profiler).The third method printed outall 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 thesecond call will print out the statistics.  The following are someinteresting 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 onlyprints the ten most significant lines.  If you want to understand whatalgorithms are taking time, the above line is what you would use. If you were looking to see what functions were looping a lot, andtaking 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 printthe 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 outstatistics for only the class init methods (since they are spelledwith \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 secondarykey 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} aremaintained, and that sub-sub-list is printed. If you wondered what functions called the above functions, you couldnow (\code{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 themanual, or guess what the following functions do: \begin{verbatim}p.print_callees()p.add('fooprof')\end{verbatim} Invoked as a script, the \module{pstats} module is a statisticsbrowser for reading and examining profile dumps.  It has a simpleline-oriented interface (implemented using \refmodule{cmd}) andinteractive help. \section{What Is Deterministic Profiling?}\nodename{Deterministic Profiling} \dfn{Deterministic profiling} is meant to reflect the fact that all\emph{function call}, \emph{function return}, and \emph{exception} eventsare monitored, and precise timings are made for the intervals betweenthese events (during which time the user's code is executing).  Incontrast, \dfn{statistical profiling} (which is not done by thismodule) randomly samples the effective instruction pointer, anddeduces where time is being spent.  The latter technique traditionallyinvolves 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, thepresence of instrumented code is not required to do deterministicprofiling.  Python automatically provides a \dfn{hook} (optionalcallback) for each event.  In addition, the interpreted nature ofPython tends to add so much overhead to execution, that deterministicprofiling tends to only add small processing overhead in typicalapplications.  The result is that deterministic profiling is not thatexpensive, yet provides extensive run time statistics about theexecution of a Python program. Call count statistics can be used to identify bugs in code (surprisingcounts), and to identify possible inline-expansion points (high callcounts).  Internal time statistics can be used to identify ``hotloops'' that should be carefully optimized.  Cumulative timestatistics should be used to identify high level errors in theselection of algorithms.  Note that the unusual handling of cumulativetimes in this profiler allows statistics for recursive implementationsof algorithms to be directly compared to iterative implementations.  \section{Reference Manual -- \module{profile} and \module{cProfile}} \declaremodule{standard}{profile}\declaremodule{standard}{cProfile}\modulesynopsis{Python profiler}   The primary entry point for the profiler is the global function\function{profile.run()} (resp. \function{cProfile.run()}).It is typically used to create any profileinformation.  The reports are formatted and printed using methods ofthe class \class{pstats.Stats}.  The following is a description of allof these standard entry points and functions.  For a more in-depthview of some of the code, consider reading the later section onProfiler Extensions, which includes discussion of how to derive``better'' profilers from the classes presented, or reading the sourcecode for these modules. \begin{funcdesc}{run}{command\optional{, filename}} This function takes a single argument that can be passed to the\keyword{exec} statement, and an optional file name.  In all cases thisroutine attempts to \keyword{exec} its first argument, and gather profilingstatistics from the execution. If no file name is present, then thisfunction automatically prints a simple profiling report, sorted by thestandard name string (file/line/function-name) that is presented ineach line.  The following is a typical output from such a call: \begin{verbatim}      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 2706 calls weremonitored.  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 thatthe 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 timemade 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 (from invocationtill exit). This figure is accurate \emph{even} for recursivefunctions. \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 (for example,\samp{43/3}), then the latter is the number of primitive calls, andthe former is the actual number of calls.  Note that when the functiondoes not recurse, these two values are the same, and only the singlefigure is printed. \end{funcdesc} \begin{funcdesc}{runctx}{command, globals, locals\optional{, filename}}This function is similar to \function{run()}, with addedarguments to supply the globals and locals dictionaries for the\var{command} string.\end{funcdesc} Analysis of the profiler data is done using the \class{Stats} class. \note{The \class{Stats} class is defined in the \module{pstats} module.} % now switch modules....% (This \stmodindex use may be hard to change ;-( )\stmodindex{pstats} \begin{classdesc}{Stats}{filename\optional{, stream=sys.stdout\optional{, \moreargs}}}This class constructor creates an instance of a ``statistics object''from a \var{filename} (or set of filenames).  \class{Stats} objects aremanipulated by methods, in order to print useful reports.  You may specifyan alternate output stream by giving the keyword argument, \code{stream}. The file selected by the above constructor must have been created by thecorresponding version of \module{profile} or \module{cProfile}.  To bespecific, there is \emph{no} file compatibility guaranteed with futureversions of this profiler, and there is no compatibility with files producedby other profilers.%(such as the old system profiler). If several files are provided, all the statistics for identicalfunctions will be coalesced, so that an overall view of severalprocesses can be considered in a single report.  If additional filesneed to be combined with data in an existing \class{Stats} object, the\method{add()} method can be used. \versionchanged[The \var{stream} parameter was added]{2.5}\end{classdesc}  \subsection{The \class{Stats} Class \label{profile-stats}} \class{Stats} objects have the following methods: \begin{methoddesc}[Stats]{strip_dirs}{}This method for the \class{Stats} class removes all leading pathinformation from file names.  It is very useful in reducing the sizeof the printout to fit within (close to) 80 columns.  This methodmodifies the object, and the stripped information is lost.  Afterperforming a strip operation, the object is considered to have itsentries in a ``random'' order, as it was just after objectinitialization and loading.  If \method{strip_dirs()} causes twofunction names to be indistinguishable (they are on the sameline of the same filename, and have the same function name), then thestatistics for these two entries are accumulated into a single entry.\end{methoddesc}  \begin{methoddesc}[Stats]{add}{filename\optional{, \moreargs}}This method of the \class{Stats} class accumulates additionalprofiling information into the current profiling object.  Itsarguments should refer to filenames created by the correspondingversion of \function{profile.run()} or \function{cProfile.run()}.Statistics for identically named(re: file, line, name) functions are automatically accumulated intosingle function statistics.\end{methoddesc} \begin{methoddesc}[Stats]{dump_stats}{filename}Save the data loaded into the \class{Stats} object to a file named\var{filename}.  The file is created if it does not exist, and isoverwritten if it already exists.  This is equivalent to the method ofthe same name on the \class{profile.Profile} and\class{cProfile.Profile} classes.\versionadded{2.3}\end{methoddesc} \begin{methoddesc}[Stats]{sort_stats}{key\optional{, \moreargs}}This method modifies the \class{Stats} object by sorting it accordingto the supplied criteria.  The argument is typically a stringidentifying the basis of a sort (example: \code{'time'} or\code{'name'}). When more than one key is provided, then additional keys are used assecondary criteria when there is equality in all keys selectedbefore them.  For example, \code{sort_stats('name', 'file')} will sortall 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 theabbreviation is unambiguous.  The following are the keys currentlydefined: \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 (placingmost time consuming items first), where as name, file, and line numbersearches are in ascending order (alphabetical). The subtledistinction between \code{'nfl'} and \code{'stdname'} is that thestandard name is a sort of the name as printed, which means that theembedded line numbers get compared in an odd way.  For example, lines3, 20, and 40 would (if the file names were the same) appear in thestring order 20, 3 and 40.  In contrast, \code{'nfl'} does a numericcompare of the line numbers.  In fact, \code{sort_stats('nfl')} is thesame as \code{sort_stats('name', 'file', 'line')}. %For compatibility with the old profiler,For backward-compatibility reasons, the numeric arguments\code{-1}, \code{0}, \code{1}, and \code{2} are permitted.  They areinterpreted 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

Lines 1–500 of 722. Load more