1 """

     2 Profiling hooks

     3 

     4 This module contains a couple of decorators (`profile` and `coverage`) that

     5 can be used to wrap functions and/or methods to produce profiles and line

     6 coverage reports.

     7 

     8 Usage example (Python 2.4 or newer):

     9 

    10     from profilehooks import profile, coverage

    11 

    12     @profile    # or @coverage

    13     def fn(n):

    14         if n < 2: return 1

    15         else: return n * fn(n-1)

    16 

    17     print fn(42)

    18 

    19 Usage example (Python 2.3 or older):

    20 

    21     from profilehooks import profile, coverage

    22 

    23     def fn(n):

    24         if n < 2: return 1

    25         else: return n * fn(n-1)

    26 

    27     # Now wrap that function in a decorator

    28     fn = profile(fn) # or coverage(fn)

    29 

    30     print fn(42)

    31 

    32 Reports for all thusly decorated functions will be printed to sys.stdout

    33 on program termination.  You can alternatively request for immediate

    34 reports for each call by passing immediate=True to the profile decorator.

    35 

    36 There's also a @timecall decorator for printing the time to sys.stderr

    37 every time a function is called, when you just want to get a rough measure

    38 instead of a detailed (but costly) profile.

    39 

    40 Caveats

    41 

    42   A thread on python-dev convinced me that hotshot produces bogus numbers.

    43   See http://mail.python.org/pipermail/python-dev/2005-November/058264.html

    44 

    45   I don't know what will happen if a decorated function will try to call

    46   another decorated function.  All decorators probably need to explicitly

    47   support nested profiling (currently TraceFuncCoverage is the only one that

    48   supports this, while HotShotFuncProfile has support for recursive functions.)

    49 

    50   Profiling with hotshot creates temporary files (*.prof and *.prof.pickle for

    51   profiling, *.cprof for coverage) in the current directory.  These files are

    52   not cleaned up.  (In fact, the *.pickle versions are intentionally written

    53   out in case you want to look at the profiler results without having to parse

    54   the big *.prof file with hotshot.stats.load, which takes ages.  Just unpickle

    55   the file and you'll get a pstats object.)

    56 

    57   Coverage analysis with hotshot seems to miss some executions resulting in

    58   lower line counts and some lines errorneously marked as never executed.  For

    59   this reason coverage analysis now uses trace.py which is slower, but more

    60   accurate.

    61 

    62   Decorating functions causes doctest.testmod() to ignore doctests in those

    63   functions.

    64 

    65 Copyright (c) 2004--2006 Marius Gedminas <marius@pov.lt>

    66 

    67 Released under the MIT licence since December 2006:

    68 

    69     Permission is hereby granted, free of charge, to any person obtaining a

    70     copy of this software and associated documentation files (the "Software"),

    71     to deal in the Software without restriction, including without limitation

    72     the rights to use, copy, modify, merge, publish, distribute, sublicense,

    73     and/or sell copies of the Software, and to permit persons to whom the

    74     Software is furnished to do so, subject to the following conditions:

    75 

    76     The above copyright notice and this permission notice shall be included in

    77     all copies or substantial portions of the Software.

    78 

    79     THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR

    80     IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,

    81     FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE

    82     AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER

    83     LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING

    84     FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER

    85     DEALINGS IN THE SOFTWARE.

    86 

    87 (Previously it was distributed under the GNU General Public Licence.)

    88 """

    89 # $Id: profilehooks.py,v 1.2 2008/07/18 14:51:08 tflorac Exp $

    90 

    91 __author__ = "Marius Gedminas (marius@gedmin.as)"

    92 __copyright__ = "Copyright 2004-2006, Marius Gedminas"

    93 __license__ = "MIT"

    94 __version__ = "1.0"

    95 __date__ = "2006-12-06"

    96 

    97 

    98 import atexit

    99 import inspect

   100 import sys

   101 import re

   102 import cPickle as pickle

   103 

   104 # For profiling

   105 from profile import Profile

   106 import pstats

   107 

   108 # For hotshot profiling (inaccurate!)

   109 import hotshot

   110 import hotshot.stats

   111 

   112 # For trace.py coverage

   113 import trace

   114 

   115 # For hotshot coverage (inaccurate!; uses undocumented APIs; might break)

   116 import _hotshot

   117 import hotshot.log

   118 

   119 # For timecall

   120 import time

   121 

   122 

   123 def profile(fn=None, skip=0, filename=None, immediate=False):

   124     """Mark `fn` for profiling.

   125 

   126     If `immediate` is False, profiling results will be printed to sys.stdout on

   127     program termination.  Otherwise results will be printed after each call.

   128 

   129     If `skip` is > 0, first `skip` calls to `fn` will not be profiled.

   130 

   131     If `filename` is specified, the profile stats will be pickled and stored in

   132     a file.

   133 

   134     Usage:

   135 

   136         def fn(...):

   137             ...

   138         fn = profile(fn, skip=1)

   139 

   140     If you are using Python 2.4, you should be able to use the decorator

   141     syntax:

   142 

   143         @profile(skip=3)

   144         def fn(...):

   145             ...

   146 

   147     or just

   148 

   149         @profile

   150         def fn(...):

   151             ...

   152 

   153     """

   154     if fn is None: # @profile() syntax -- we are a decorator maker

   155         def decorator(fn):

   156             return profile(fn, skip=skip, filename=filename,

   157                            immediate=immediate)

   158         return decorator

   159     # @profile syntax -- we are a decorator.

   160     fp = FuncProfile(fn, skip=skip, filename=filename, immediate=immediate)

   161     # or HotShotFuncProfile

   162     # We cannot return fp or fp.__call__ directly as that would break method

   163     # definitions, instead we need to return a plain function.

   164     def new_fn(*args, **kw):

   165         return fp(*args, **kw)

   166     new_fn.__doc__ = fn.__doc__

   167     return new_fn

   168 

   169 

   170 def coverage(fn):

   171     """Mark `fn` for line coverage analysis.

   172 

   173     Results will be printed to sys.stdout on program termination.

   174 

   175     Usage:

   176 

   177         def fn(...):

   178             ...

   179         fn = coverage(fn)

   180 

   181     If you are using Python 2.4, you should be able to use the decorator

   182     syntax:

   183 

   184         @coverage

   185         def fn(...):

   186             ...

   187 

   188     """

   189     fp = TraceFuncCoverage(fn) # or HotShotFuncCoverage

   190     # We cannot return fp or fp.__call__ directly as that would break method

   191     # definitions, instead we need to return a plain function.

   192     def new_fn(*args, **kw):

   193         return fp(*args, **kw)

   194     new_fn.__doc__ = fn.__doc__

   195     return new_fn

   196 

   197 

   198 def coverage_with_hotshot(fn):

   199     """Mark `fn` for line coverage analysis.

   200 

   201     Uses the 'hotshot' module for fast coverage analysis.

   202 

   203     BUG: Produces inaccurate results.

   204 

   205     See the docstring of `coverage` for usage examples.

   206     """

   207     fp = HotShotFuncCoverage(fn)

   208     # We cannot return fp or fp.__call__ directly as that would break method

   209     # definitions, instead we need to return a plain function.

   210     def new_fn(*args, **kw):

   211         return fp(*args, **kw)

   212     new_fn.__doc__ = fn.__doc__

   213     return new_fn

   214 

   215 

   216 class FuncProfile:

   217     """Profiler for a function (uses profile)."""

   218 

   219     # This flag is shared between all instances

   220     in_profiler = False

   221 

   222     def __init__(self, fn, skip=0, filename=None, immediate=False):

   223         """Creates a profiler for a function.

   224 

   225         Every profiler has its own log file (the name of which is derived from

   226         the function name).

   227 

   228         HotShotFuncProfile registers an atexit handler that prints profiling

   229         information to sys.stderr when the program terminates.

   230 

   231         The log file is not removed and remains there to clutter the current

   232         working directory.

   233         """

   234         self.fn = fn

   235         self.filename = filename

   236         self.immediate = immediate

   237         self.stats = pstats.Stats(Profile())

   238         self.ncalls = 0

   239         self.skip = skip

   240         self.skipped = 0

   241         atexit.register(self.atexit)

   242 

   243     def __call__(self, *args, **kw):

   244         """Profile a singe call to the function."""

   245         self.ncalls += 1

   246         if self.skip > 0:

   247             self.skip -= 1

   248             self.skipped += 1

   249             return self.fn(*args, **kw)

   250         if FuncProfile.in_profiler:

   251             # handle recursive calls

   252             return self.fn(*args, **kw)

   253         # You cannot reuse the same profiler for many calls and accumulate

   254         # stats that way.  :-/

   255         profiler = Profile()

   256         try:

   257             FuncProfile.in_profiler = True

   258             return profiler.runcall(self.fn, *args, **kw)

   259         finally:

   260             FuncProfile.in_profiler = False

   261             self.stats.add(profiler)

   262             if self.immediate:

   263                 self.print_stats()

   264                 self.reset_stats()

   265 

   266     def print_stats(self):

   267         """Print profile information to sys.stdout."""

   268         funcname = self.fn.__name__

   269         filename = self.fn.func_code.co_filename

   270         lineno = self.fn.func_code.co_firstlineno

   271         print

   272         print "*** PROFILER RESULTS ***"

   273         print "%s (%s:%s)" % (funcname, filename, lineno)

   274         print "function called %d times" % self.ncalls,

   275         if self.skipped:

   276             print "(%d calls not profiled)" % self.skipped

   277         else:

   278             print

   279         print

   280         stats = self.stats

   281         if self.filename:

   282             pickle.dump(stats, file(self.filename, 'w'))

   283         stats.strip_dirs()

   284         stats.sort_stats('cumulative', 'time', 'calls')

   285         stats.print_stats(40)

   286 

   287     def reset_stats(self):

   288         """Reset accumulated profiler statistics."""

   289         self.stats = pstats.Stats(Profile())

   290         self.ncalls = 0

   291         self.skipped = 0

   292 

   293     def atexit(self):

   294         """Stop profiling and print profile information to sys.stdout.

   295 

   296         This function is registered as an atexit hook.

   297         """

   298         if not self.immediate:

   299             self.print_stats()

   300 

   301 

   302 class HotShotFuncProfile:

   303     """Profiler for a function (uses hotshot)."""

   304 

   305     # This flag is shared between all instances

   306     in_profiler = False

   307 

   308     def __init__(self, fn, skip=0, filename=None):

   309         """Creates a profiler for a function.

   310 

   311         Every profiler has its own log file (the name of which is derived from

   312         the function name).

   313 

   314         HotShotFuncProfile registers an atexit handler that prints profiling

   315         information to sys.stderr when the program terminates.

   316 

   317         The log file is not removed and remains there to clutter the current

   318         working directory.

   319         """

   320         self.fn = fn

   321         self.filename = filename

   322         if self.filename:

   323             self.logfilename = filename + ".raw"

   324         else:

   325             self.logfilename = fn.__name__ + ".prof"

   326         self.profiler = hotshot.Profile(self.logfilename)

   327         self.ncalls = 0

   328         self.skip = skip

   329         self.skipped = 0

   330         atexit.register(self.atexit)

   331 

   332     def __call__(self, *args, **kw):

   333         """Profile a singe call to the function."""

   334         self.ncalls += 1

   335         if self.skip > 0:

   336             self.skip -= 1

   337             self.skipped += 1

   338             return self.fn(*args, **kw)

   339         if HotShotFuncProfile.in_profiler:

   340             # handle recursive calls

   341             return self.fn(*args, **kw)

   342         try:

   343             HotShotFuncProfile.in_profiler = True

   344             return self.profiler.runcall(self.fn, *args, **kw)

   345         finally:

   346             HotShotFuncProfile.in_profiler = False

   347 

   348     def atexit(self):

   349         """Stop profiling and print profile information to sys.stderr.

   350 

   351         This function is registered as an atexit hook.

   352         """

   353         self.profiler.close()

   354         funcname = self.fn.__name__

   355         filename = self.fn.func_code.co_filename

   356         lineno = self.fn.func_code.co_firstlineno

   357         print

   358         print "*** PROFILER RESULTS ***"

   359         print "%s (%s:%s)" % (funcname, filename, lineno)

   360         print "function called %d times" % self.ncalls,

   361         if self.skipped:

   362             print "(%d calls not profiled)" % self.skipped

   363         else:

   364             print

   365         print

   366         stats = hotshot.stats.load(self.logfilename)

   367         # hotshot.stats.load takes ages, and the .prof file eats megabytes, but

   368         # a pickled stats object is small and fast

   369         if self.filename:

   370             pickle.dump(stats, file(self.filename, 'w'))

   371         # it is best to pickle before strip_dirs

   372         stats.strip_dirs()

   373         stats.sort_stats('cumulative', 'time', 'calls')

   374         stats.print_stats(200)

   375 

   376 

   377 class HotShotFuncCoverage:

   378     """Coverage analysis for a function (uses _hotshot).

   379 

   380     HotShot coverage is reportedly faster than trace.py, but it appears to

   381     have problems with exceptions; also line counts in coverage reports

   382     are generally lower from line counts produced by TraceFuncCoverage.

   383     Is this my bug, or is it a problem with _hotshot?

   384     """

   385 

   386     def __init__(self, fn):

   387         """Creates a profiler for a function.

   388 

   389         Every profiler has its own log file (the name of which is derived from

   390         the function name).

   391 

   392         HotShotFuncCoverage registers an atexit handler that prints profiling

   393         information to sys.stderr when the program terminates.

   394 

   395         The log file is not removed and remains there to clutter the current

   396         working directory.

   397         """

   398         self.fn = fn

   399         self.logfilename = fn.__name__ + ".cprof"

   400         self.profiler = _hotshot.coverage(self.logfilename)

   401         self.ncalls = 0

   402         atexit.register(self.atexit)

   403 

   404     def __call__(self, *args, **kw):

   405         """Profile a singe call to the function."""

   406         self.ncalls += 1

   407         return self.profiler.runcall(self.fn, args, kw)

   408 

   409     def atexit(self):

   410         """Stop profiling and print profile information to sys.stderr.

   411 

   412         This function is registered as an atexit hook.

   413         """

   414         self.profiler.close()

   415         funcname = self.fn.__name__

   416         filename = self.fn.func_code.co_filename

   417         lineno = self.fn.func_code.co_firstlineno

   418         print

   419         print "*** COVERAGE RESULTS ***"

   420         print "%s (%s:%s)" % (funcname, filename, lineno)

   421         print "function called %d times" % self.ncalls

   422         print

   423         fs = FuncSource(self.fn)

   424         reader = hotshot.log.LogReader(self.logfilename)

   425         for what, (filename, lineno, funcname), tdelta in reader:

   426             if filename != fs.filename:

   427                 continue

   428             if what == hotshot.log.LINE:

   429                 fs.mark(lineno)

   430             if what == hotshot.log.ENTER:

   431                 # hotshot gives us the line number of the function definition

   432                 # and never gives us a LINE event for the first statement in

   433                 # a function, so if we didn't perform this mapping, the first

   434                 # statement would be marked as never executed

   435                 if lineno == fs.firstlineno:

   436                     lineno = fs.firstcodelineno

   437                 fs.mark(lineno)

   438         reader.close()

   439         print fs

   440 

   441 

   442 class TraceFuncCoverage:

   443     """Coverage analysis for a function (uses trace module).

   444 

   445     HotShot coverage analysis is reportedly faster, but it appears to have

   446     problems with exceptions.

   447     """

   448 

   449     # Shared between all instances so that nested calls work

   450     tracer = trace.Trace(count=True, trace=False,

   451                          ignoredirs=[sys.prefix, sys.exec_prefix])

   452 

   453     # This flag is also shared between all instances

   454     tracing = False

   455 

   456     def __init__(self, fn):

   457         """Creates a profiler for a function.

   458 

   459         Every profiler has its own log file (the name of which is derived from

   460         the function name).

   461 

   462         TraceFuncCoverage registers an atexit handler that prints profiling

   463         information to sys.stderr when the program terminates.

   464 

   465         The log file is not removed and remains there to clutter the current

   466         working directory.

   467         """

   468         self.fn = fn

   469         self.logfilename = fn.__name__ + ".cprof"

   470         self.ncalls = 0

   471         atexit.register(self.atexit)

   472 

   473     def __call__(self, *args, **kw):

   474         """Profile a singe call to the function."""

   475         self.ncalls += 1

   476         if TraceFuncCoverage.tracing:

   477             return self.fn(*args, **kw)

   478         try:

   479             TraceFuncCoverage.tracing = True

   480             return self.tracer.runfunc(self.fn, *args, **kw)

   481         finally:

   482             TraceFuncCoverage.tracing = False

   483 

   484     def atexit(self):

   485         """Stop profiling and print profile information to sys.stderr.

   486 

   487         This function is registered as an atexit hook.

   488         """

   489         funcname = self.fn.__name__

   490         filename = self.fn.func_code.co_filename

   491         lineno = self.fn.func_code.co_firstlineno

   492         print

   493         print "*** COVERAGE RESULTS ***"

   494         print "%s (%s:%s)" % (funcname, filename, lineno)

   495         print "function called %d times" % self.ncalls

   496         print

   497         fs = FuncSource(self.fn)

   498         for (filename, lineno), count in self.tracer.counts.items():

   499             if filename != fs.filename:

   500                 continue

   501             fs.mark(lineno, count)

   502         print fs

   503         never_executed = fs.count_never_executed()

   504         if never_executed:

   505             print "%d lines were not executed." % never_executed

   506 

   507 

   508 class FuncSource:

   509     """Source code annotator for a function."""

   510 

   511     blank_rx = re.compile(r"^\s*finally:\s*(#.*)?$")

   512 

   513     def __init__(self, fn):

   514         self.fn = fn

   515         self.filename = inspect.getsourcefile(fn)

   516         self.source, self.firstlineno = inspect.getsourcelines(fn)

   517         self.sourcelines = {}

   518         self.firstcodelineno = self.firstlineno

   519         self.find_source_lines()

   520 

   521     def find_source_lines(self):

   522         """Mark all executable source lines in fn as executed 0 times."""

   523         strs = trace.find_strings(self.filename)

   524         lines = trace.find_lines_from_code(self.fn.func_code, strs)

   525         self.firstcodelineno = sys.maxint

   526         for lineno in lines:

   527             self.firstcodelineno = min(self.firstcodelineno, lineno)

   528             self.sourcelines.setdefault(lineno, 0)

   529         if self.firstcodelineno == sys.maxint:

   530             self.firstcodelineno = self.firstlineno

   531 

   532     def mark(self, lineno, count=1):

   533         """Mark a given source line as executed count times.

   534 

   535         Multiple calls to mark for the same lineno add up.

   536         """

   537         self.sourcelines[lineno] = self.sourcelines.get(lineno, 0) + count

   538 

   539     def count_never_executed(self):

   540         """Count statements that were never executed."""

   541         lineno = self.firstlineno

   542         counter = 0

   543         for line in self.source:

   544             if self.sourcelines.get(lineno) == 0:

   545                 if not self.blank_rx.match(line):

   546                     counter += 1

   547             lineno += 1

   548         return counter

   549 

   550     def __str__(self):

   551         """Return annotated source code for the function."""

   552         lines = []

   553         lineno = self.firstlineno

   554         for line in self.source:

   555             counter = self.sourcelines.get(lineno)

   556             if counter is None:

   557                 prefix = ' ' * 7

   558             elif counter == 0:

   559                 if self.blank_rx.match(line):

   560                     prefix = ' ' * 7

   561                 else:

   562                     prefix = '>' * 6 + ' '

   563             else:

   564                 prefix = '%5d: ' % counter

   565             lines.append(prefix + line)

   566             lineno += 1

   567         return ''.join(lines)

   568 

   569 

   570 def timecall(fn):

   571     """Wrap `fn` and print its execution time.

   572 

   573     Example:

   574 

   575         @timecall

   576         def somefunc(x, y):

   577             time.sleep(x * y)

   578 

   579         somefunc(2, 3)

   580 

   581     will print

   582 

   583         somefunc: 6.0 seconds

   584 

   585     """

   586     def new_fn(*args, **kw):

   587         try:

   588             start = time.time()

   589             return fn(*args, **kw)

   590         finally:

   591             duration = time.time() - start

   592             funcname = fn.__name__

   593             filename = fn.func_code.co_filename

   594             lineno = fn.func_code.co_firstlineno

   595             print >> sys.stderr, "\n  %s (%s:%s):\n    %.3f seconds\n" % (

   596                                         funcname, filename, lineno, duration)

   597     new_fn.__doc__ = fn.__doc__

   598     return new_fn

   599