Merge pull request #621 from JackDandy/feature/UpdateProfilehooks

Update profilehooks 1.4 to 1.8.2.dev0 (ee3f1a8).
This commit is contained in:
JackDandy 2016-01-12 03:34:16 +00:00
commit 5c490ac740
2 changed files with 174 additions and 114 deletions

View file

@ -15,6 +15,7 @@
* Update Hachoir library 1.3.4 (r1383) to 1.3.4 (r1435) * Update Hachoir library 1.3.4 (r1383) to 1.3.4 (r1435)
* Update html5lib 0.999 to 0.99999999/1.0b9 (46dae3d) * Update html5lib 0.999 to 0.99999999/1.0b9 (46dae3d)
* Update PNotify library 2.0.1 to 2.1.0 * Update PNotify library 2.0.1 to 2.1.0
* Update profilehooks 1.4 to 1.8.2.dev0 (ee3f1a8)
### 0.11.0 (2016-01-10 22:30:00 UTC) ### 0.11.0 (2016-01-10 22:30:00 UTC)

View file

@ -16,7 +16,19 @@ Usage example (Python 2.4 or newer)::
if n < 2: return 1 if n < 2: return 1
else: return n * fn(n-1) else: return n * fn(n-1)
print fn(42) print(fn(42))
Or without imports, with some hack
$ python -m profilehooks yourmodule
@profile # or @coverage
def fn(n):
if n < 2: return 1
else: return n * fn(n-1)
print(fn(42))
Usage example (Python 2.3 or older):: Usage example (Python 2.3 or older)::
@ -62,7 +74,7 @@ Caveats
executed. For this reason coverage analysis now uses trace.py which is executed. For this reason coverage analysis now uses trace.py which is
slower, but more accurate. slower, but more accurate.
Copyright (c) 2004--2008 Marius Gedminas <marius@pov.lt> Copyright (c) 2004--2014 Marius Gedminas <marius@pov.lt>
Copyright (c) 2007 Hanno Schlichting Copyright (c) 2007 Hanno Schlichting
Copyright (c) 2008 Florian Schulze Copyright (c) 2008 Florian Schulze
@ -88,19 +100,19 @@ Released under the MIT licence since December 2006:
(Previously it was distributed under the GNU General Public Licence.) (Previously it was distributed under the GNU General Public Licence.)
""" """
# $Id: profilehooks.py 29 2010-08-13 16:29:20Z mg $
__author__ = "Marius Gedminas (marius@gedmin.as)" __author__ = "Marius Gedminas <marius@gedmin.as>"
__copyright__ = "Copyright 2004-2009 Marius Gedminas" __copyright__ = "Copyright 2004-2015 Marius Gedminas and contributors"
__license__ = "MIT" __license__ = "MIT"
__version__ = "1.4" __version__ = '1.8.2.dev0'
__date__ = "2009-03-31" __date__ = "2015-11-21"
import atexit import atexit
import inspect import inspect
import sys import sys
import re import re
import os
# For profiling # For profiling
from profile import Profile from profile import Profile
@ -134,17 +146,21 @@ import time
# registry of available profilers # registry of available profilers
AVAILABLE_PROFILERS = {} AVAILABLE_PROFILERS = {}
__all__ = ['coverage', 'coverage_with_hotshot', 'profile', 'timecall']
def profile(fn=None, skip=0, filename=None, immediate=False, dirs=False, def profile(fn=None, skip=0, filename=None, immediate=False, dirs=False,
sort=None, entries=40, sort=None, entries=40,
profiler=('cProfile', 'profile', 'hotshot')): profiler=('cProfile', 'profile', 'hotshot'),
stdout=True):
"""Mark `fn` for profiling. """Mark `fn` for profiling.
If `skip` is > 0, first `skip` calls to `fn` will not be profiled. If `skip` is > 0, first `skip` calls to `fn` will not be profiled.
If `immediate` is False, profiling results will be printed to If `immediate` is False, profiling results will be printed to
sys.stdout on program termination. Otherwise results will be printed sys.stdout on program termination. Otherwise results will be printed
after each call. after each call. (If you don't want this, set stdout=False and specify a
`filename` to store profile data.)
If `dirs` is False only the name of the file will be printed. If `dirs` is False only the name of the file will be printed.
Otherwise the full path is used. Otherwise the full path is used.
@ -170,7 +186,8 @@ def profile(fn=None, skip=0, filename=None, immediate=False, dirs=False,
'profile', 'hotshot'). 'profile', 'hotshot').
If `filename` is specified, the profile stats will be stored in the If `filename` is specified, the profile stats will be stored in the
named file. You can load them pstats.Stats(filename). named file. You can load them with pstats.Stats(filename) or use a
visualization tool like RunSnakeRun.
Usage:: Usage::
@ -192,12 +209,12 @@ def profile(fn=None, skip=0, filename=None, immediate=False, dirs=False,
... ...
""" """
if fn is None: # @profile() syntax -- we are a decorator maker if fn is None: # @profile() syntax -- we are a decorator maker
def decorator(fn): def decorator(fn):
return profile(fn, skip=skip, filename=filename, return profile(fn, skip=skip, filename=filename,
immediate=immediate, dirs=dirs, immediate=immediate, dirs=dirs,
sort=sort, entries=entries, sort=sort, entries=entries,
profiler=profiler) profiler=profiler, stdout=stdout)
return decorator return decorator
# @profile syntax -- we are a decorator. # @profile syntax -- we are a decorator.
if isinstance(profiler, str): if isinstance(profiler, str):
@ -208,14 +225,13 @@ def profile(fn=None, skip=0, filename=None, immediate=False, dirs=False,
break break
else: else:
raise ValueError('only these profilers are available: %s' raise ValueError('only these profilers are available: %s'
% ', '.join(AVAILABLE_PROFILERS)) % ', '.join(sorted(AVAILABLE_PROFILERS)))
fp = profiler_class(fn, skip=skip, filename=filename, fp = profiler_class(fn, skip=skip, filename=filename,
immediate=immediate, dirs=dirs, immediate=immediate, dirs=dirs,
sort=sort, entries=entries) sort=sort, entries=entries, stdout=stdout)
# fp = HotShotFuncProfile(fn, skip=skip, filename=filename, ...)
# or HotShotFuncProfile
# We cannot return fp or fp.__call__ directly as that would break method # We cannot return fp or fp.__call__ directly as that would break method
# definitions, instead we need to return a plain function. # definitions, instead we need to return a plain function.
def new_fn(*args, **kw): def new_fn(*args, **kw):
return fp(*args, **kw) return fp(*args, **kw)
new_fn.__doc__ = fn.__doc__ new_fn.__doc__ = fn.__doc__
@ -244,9 +260,10 @@ def coverage(fn):
... ...
""" """
fp = TraceFuncCoverage(fn) # or HotShotFuncCoverage fp = TraceFuncCoverage(fn) # or HotShotFuncCoverage
# We cannot return fp or fp.__call__ directly as that would break method # We cannot return fp or fp.__call__ directly as that would break method
# definitions, instead we need to return a plain function. # definitions, instead we need to return a plain function.
def new_fn(*args, **kw): def new_fn(*args, **kw):
return fp(*args, **kw) return fp(*args, **kw)
new_fn.__doc__ = fn.__doc__ new_fn.__doc__ = fn.__doc__
@ -268,6 +285,7 @@ def coverage_with_hotshot(fn):
fp = HotShotFuncCoverage(fn) fp = HotShotFuncCoverage(fn)
# We cannot return fp or fp.__call__ directly as that would break method # We cannot return fp or fp.__call__ directly as that would break method
# definitions, instead we need to return a plain function. # definitions, instead we need to return a plain function.
def new_fn(*args, **kw): def new_fn(*args, **kw):
return fp(*args, **kw) return fp(*args, **kw)
new_fn.__doc__ = fn.__doc__ new_fn.__doc__ = fn.__doc__
@ -286,7 +304,7 @@ class FuncProfile(object):
Profile = Profile Profile = Profile
def __init__(self, fn, skip=0, filename=None, immediate=False, dirs=False, def __init__(self, fn, skip=0, filename=None, immediate=False, dirs=False,
sort=None, entries=40): sort=None, entries=40, stdout=True):
"""Creates a profiler for a function. """Creates a profiler for a function.
Every profiler has its own log file (the name of which is derived Every profiler has its own log file (the name of which is derived
@ -299,6 +317,7 @@ class FuncProfile(object):
self.skip = skip self.skip = skip
self.filename = filename self.filename = filename
self.immediate = immediate self.immediate = immediate
self.stdout = stdout
self.dirs = dirs self.dirs = dirs
self.sort = sort or ('cumulative', 'time', 'calls') self.sort = sort or ('cumulative', 'time', 'calls')
if isinstance(self.sort, str): if isinstance(self.sort, str):
@ -332,25 +351,26 @@ class FuncProfile(object):
def print_stats(self): def print_stats(self):
"""Print profile information to sys.stdout.""" """Print profile information to sys.stdout."""
funcname = self.fn.__name__
filename = self.fn.func_code.co_filename
lineno = self.fn.func_code.co_firstlineno
print
print "*** PROFILER RESULTS ***"
print "%s (%s:%s)" % (funcname, filename, lineno)
print "function called %d times" % self.ncalls,
if self.skipped:
print "(%d calls not profiled)" % self.skipped
else:
print
print
stats = self.stats stats = self.stats
if self.filename: if self.filename:
stats.dump_stats(self.filename) stats.dump_stats(self.filename)
if not self.dirs: if self.stdout:
stats.strip_dirs() funcname = self.fn.__name__
stats.sort_stats(*self.sort) filename = self.fn.__code__.co_filename
stats.print_stats(self.entries) lineno = self.fn.__code__.co_firstlineno
print("")
print("*** PROFILER RESULTS ***")
print("%s (%s:%s)" % (funcname, filename, lineno))
if self.skipped:
skipped = " (%d calls not profiled)" % self.skipped
else:
skipped = ""
print("function called %d times%s" % (self.ncalls, skipped))
print("")
if not self.dirs:
stats.strip_dirs()
stats.sort_stats(*self.sort)
stats.print_stats(self.entries)
def reset_stats(self): def reset_stats(self):
"""Reset accumulated profiler statistics.""" """Reset accumulated profiler statistics."""
@ -364,6 +384,7 @@ class FuncProfile(object):
This function is registered as an atexit hook. This function is registered as an atexit hook.
""" """
# XXX: uh, why even register this as an atexit hook if immediate is True?
if not self.immediate: if not self.immediate:
self.print_stats() self.print_stats()
@ -383,13 +404,14 @@ if cProfile is not None:
if hotshot is not None: if hotshot is not None:
class HotShotFuncProfile(object): class HotShotFuncProfile(FuncProfile):
"""Profiler for a function (uses hotshot).""" """Profiler for a function (uses hotshot)."""
# This flag is shared between all instances # This flag is shared between all instances
in_profiler = False in_profiler = False
def __init__(self, fn, skip=0, filename=None): def __init__(self, fn, skip=0, filename=None, immediate=False,
dirs=False, sort=None, entries=40, stdout=True):
"""Creates a profiler for a function. """Creates a profiler for a function.
Every profiler has its own log file (the name of which is derived Every profiler has its own log file (the name of which is derived
@ -401,17 +423,13 @@ if hotshot is not None:
The log file is not removed and remains there to clutter the The log file is not removed and remains there to clutter the
current working directory. current working directory.
""" """
self.fn = fn if filename:
self.filename = filename
if self.filename:
self.logfilename = filename + ".raw" self.logfilename = filename + ".raw"
else: else:
self.logfilename = fn.__name__ + ".prof" self.logfilename = "%s.%d.prof" % (fn.__name__, os.getpid())
self.profiler = hotshot.Profile(self.logfilename) super(HotShotFuncProfile, self).__init__(
self.ncalls = 0 fn, skip=skip, filename=filename, immediate=immediate,
self.skip = skip dirs=dirs, sort=sort, entries=entries, stdout=stdout)
self.skipped = 0
atexit.register(self.atexit)
def __call__(self, *args, **kw): def __call__(self, *args, **kw):
"""Profile a singe call to the function.""" """Profile a singe call to the function."""
@ -423,43 +441,32 @@ if hotshot is not None:
if HotShotFuncProfile.in_profiler: if HotShotFuncProfile.in_profiler:
# handle recursive calls # handle recursive calls
return self.fn(*args, **kw) return self.fn(*args, **kw)
if self.profiler is None:
self.profiler = hotshot.Profile(self.logfilename)
try: try:
HotShotFuncProfile.in_profiler = True HotShotFuncProfile.in_profiler = True
return self.profiler.runcall(self.fn, *args, **kw) return self.profiler.runcall(self.fn, *args, **kw)
finally: finally:
HotShotFuncProfile.in_profiler = False HotShotFuncProfile.in_profiler = False
if self.immediate:
self.print_stats()
self.reset_stats()
def atexit(self): def print_stats(self):
"""Stop profiling and print profile information to sys.stderr. if self.profiler is None:
self.stats = pstats.Stats(Profile())
This function is registered as an atexit hook.
"""
self.profiler.close()
funcname = self.fn.__name__
filename = self.fn.func_code.co_filename
lineno = self.fn.func_code.co_firstlineno
print
print "*** PROFILER RESULTS ***"
print "%s (%s:%s)" % (funcname, filename, lineno)
print "function called %d times" % self.ncalls,
if self.skipped:
print "(%d calls not profiled)" % self.skipped
else: else:
print self.profiler.close()
print self.stats = hotshot.stats.load(self.logfilename)
stats = hotshot.stats.load(self.logfilename) super(HotShotFuncProfile, self).print_stats()
# hotshot.stats.load takes ages, and the .prof file eats megabytes, but
# a saved stats object is small and fast def reset_stats(self):
if self.filename: self.profiler = None
stats.dump_stats(self.filename) self.ncalls = 0
# it is best to save before strip_dirs self.skipped = 0
stats.strip_dirs()
stats.sort_stats('cumulative', 'time', 'calls')
stats.print_stats(40)
AVAILABLE_PROFILERS['hotshot'] = HotShotFuncProfile AVAILABLE_PROFILERS['hotshot'] = HotShotFuncProfile
class HotShotFuncCoverage: class HotShotFuncCoverage:
"""Coverage analysis for a function (uses _hotshot). """Coverage analysis for a function (uses _hotshot).
@ -482,7 +489,7 @@ if hotshot is not None:
current working directory. current working directory.
""" """
self.fn = fn self.fn = fn
self.logfilename = fn.__name__ + ".cprof" self.logfilename = "%s.%d.cprof" % (fn.__name__, os.getpid())
self.profiler = _hotshot.coverage(self.logfilename) self.profiler = _hotshot.coverage(self.logfilename)
self.ncalls = 0 self.ncalls = 0
atexit.register(self.atexit) atexit.register(self.atexit)
@ -490,7 +497,11 @@ if hotshot is not None:
def __call__(self, *args, **kw): def __call__(self, *args, **kw):
"""Profile a singe call to the function.""" """Profile a singe call to the function."""
self.ncalls += 1 self.ncalls += 1
return self.profiler.runcall(self.fn, args, kw) old_trace = sys.gettrace()
try:
return self.profiler.runcall(self.fn, args, kw)
finally: # pragma: nocover
sys.settrace(old_trace)
def atexit(self): def atexit(self):
"""Stop profiling and print profile information to sys.stderr. """Stop profiling and print profile information to sys.stderr.
@ -499,13 +510,13 @@ if hotshot is not None:
""" """
self.profiler.close() self.profiler.close()
funcname = self.fn.__name__ funcname = self.fn.__name__
filename = self.fn.func_code.co_filename filename = self.fn.__code__.co_filename
lineno = self.fn.func_code.co_firstlineno lineno = self.fn.__code__.co_firstlineno
print print("")
print "*** COVERAGE RESULTS ***" print("*** COVERAGE RESULTS ***")
print "%s (%s:%s)" % (funcname, filename, lineno) print("%s (%s:%s)" % (funcname, filename, lineno))
print "function called %d times" % self.ncalls print("function called %d times" % self.ncalls)
print print("")
fs = FuncSource(self.fn) fs = FuncSource(self.fn)
reader = hotshot.log.LogReader(self.logfilename) reader = hotshot.log.LogReader(self.logfilename)
for what, (filename, lineno, funcname), tdelta in reader: for what, (filename, lineno, funcname), tdelta in reader:
@ -522,7 +533,10 @@ if hotshot is not None:
lineno = fs.firstcodelineno lineno = fs.firstcodelineno
fs.mark(lineno) fs.mark(lineno)
reader.close() reader.close()
print fs print(fs)
never_executed = fs.count_never_executed()
if never_executed:
print("%d lines were not executed." % never_executed)
class TraceFuncCoverage: class TraceFuncCoverage:
@ -552,19 +566,21 @@ class TraceFuncCoverage:
current working directory. current working directory.
""" """
self.fn = fn self.fn = fn
self.logfilename = fn.__name__ + ".cprof" self.logfilename = "%s.%d.cprof" % (fn.__name__, os.getpid())
self.ncalls = 0 self.ncalls = 0
atexit.register(self.atexit) atexit.register(self.atexit)
def __call__(self, *args, **kw): def __call__(self, *args, **kw):
"""Profile a singe call to the function.""" """Profile a singe call to the function."""
self.ncalls += 1 self.ncalls += 1
if TraceFuncCoverage.tracing: if TraceFuncCoverage.tracing: # pragma: nocover
return self.fn(*args, **kw) return self.fn(*args, **kw)
old_trace = sys.gettrace()
try: try:
TraceFuncCoverage.tracing = True TraceFuncCoverage.tracing = True
return self.tracer.runfunc(self.fn, *args, **kw) return self.tracer.runfunc(self.fn, *args, **kw)
finally: finally: # pragma: nocover
sys.settrace(old_trace)
TraceFuncCoverage.tracing = False TraceFuncCoverage.tracing = False
def atexit(self): def atexit(self):
@ -573,22 +589,22 @@ class TraceFuncCoverage:
This function is registered as an atexit hook. This function is registered as an atexit hook.
""" """
funcname = self.fn.__name__ funcname = self.fn.__name__
filename = self.fn.func_code.co_filename filename = self.fn.__code__.co_filename
lineno = self.fn.func_code.co_firstlineno lineno = self.fn.__code__.co_firstlineno
print print("")
print "*** COVERAGE RESULTS ***" print("*** COVERAGE RESULTS ***")
print "%s (%s:%s)" % (funcname, filename, lineno) print("%s (%s:%s)" % (funcname, filename, lineno))
print "function called %d times" % self.ncalls print("function called %d times" % self.ncalls)
print print("")
fs = FuncSource(self.fn) fs = FuncSource(self.fn)
for (filename, lineno), count in self.tracer.counts.items(): for (filename, lineno), count in self.tracer.counts.items():
if filename != fs.filename: if filename != fs.filename:
continue continue
fs.mark(lineno, count) fs.mark(lineno, count)
print fs print(fs)
never_executed = fs.count_never_executed() never_executed = fs.count_never_executed()
if never_executed: if never_executed:
print "%d lines were not executed." % never_executed print("%d lines were not executed." % never_executed)
class FuncSource: class FuncSource:
@ -599,20 +615,28 @@ class FuncSource:
def __init__(self, fn): def __init__(self, fn):
self.fn = fn self.fn = fn
self.filename = inspect.getsourcefile(fn) self.filename = inspect.getsourcefile(fn)
self.source, self.firstlineno = inspect.getsourcelines(fn)
self.sourcelines = {} self.sourcelines = {}
self.firstcodelineno = self.firstlineno self.source = []
self.find_source_lines() self.firstlineno = self.firstcodelineno = 0
try:
self.source, self.firstlineno = inspect.getsourcelines(fn)
self.firstcodelineno = self.firstlineno
self.find_source_lines()
except IOError:
self.filename = None
def find_source_lines(self): def find_source_lines(self):
"""Mark all executable source lines in fn as executed 0 times.""" """Mark all executable source lines in fn as executed 0 times."""
if self.filename is None:
return
strs = trace.find_strings(self.filename) strs = trace.find_strings(self.filename)
lines = trace.find_lines_from_code(self.fn.func_code, strs) lines = trace.find_lines_from_code(self.fn.__code__, strs)
self.firstcodelineno = sys.maxint
for lineno in lines: for lineno in lines:
self.firstcodelineno = min(self.firstcodelineno, lineno)
self.sourcelines.setdefault(lineno, 0) self.sourcelines.setdefault(lineno, 0)
if self.firstcodelineno == sys.maxint: if lines:
self.firstcodelineno = min(lines)
else: # pragma: nocover
# This branch cannot be reached, I'm just being paranoid.
self.firstcodelineno = self.firstlineno self.firstcodelineno = self.firstlineno
def mark(self, lineno, count=1): def mark(self, lineno, count=1):
@ -635,6 +659,8 @@ class FuncSource:
def __str__(self): def __str__(self):
"""Return annotated source code for the function.""" """Return annotated source code for the function."""
if self.filename is None:
return "cannot show coverage data since co_filename is None"
lines = [] lines = []
lineno = self.firstlineno lineno = self.firstlineno
for line in self.source: for line in self.source:
@ -642,7 +668,10 @@ class FuncSource:
if counter is None: if counter is None:
prefix = ' ' * 7 prefix = ' ' * 7
elif counter == 0: elif counter == 0:
if self.blank_rx.match(line): if self.blank_rx.match(line): # pragma: nocover
# This is an workaround for an ancient bug I can't
# reproduce, perhaps because it was fixed, or perhaps
# because I can't remember all the details.
prefix = ' ' * 7 prefix = ' ' * 7
else: else:
prefix = '>' * 6 + ' ' prefix = '>' * 6 + ' '
@ -653,7 +682,7 @@ class FuncSource:
return ''.join(lines) return ''.join(lines)
def timecall(fn=None, immediate=True, timer=time.time): def timecall(fn=None, immediate=True, timer=None):
"""Wrap `fn` and print its execution time. """Wrap `fn` and print its execution time.
Example:: Example::
@ -675,14 +704,17 @@ def timecall(fn=None, immediate=True, timer=time.time):
@timecall(timer=time.clock) @timecall(timer=time.clock)
""" """
if fn is None: # @timecall() syntax -- we are a decorator maker if fn is None: # @timecall() syntax -- we are a decorator maker
def decorator(fn): def decorator(fn):
return timecall(fn, immediate=immediate, timer=timer) return timecall(fn, immediate=immediate, timer=timer)
return decorator return decorator
# @timecall syntax -- we are a decorator. # @timecall syntax -- we are a decorator.
if timer is None:
timer = time.time
fp = FuncTimer(fn, immediate=immediate, timer=timer) fp = FuncTimer(fn, immediate=immediate, timer=timer)
# We cannot return fp or fp.__call__ directly as that would break method # We cannot return fp or fp.__call__ directly as that would break method
# definitions, instead we need to return a plain function. # definitions, instead we need to return a plain function.
def new_fn(*args, **kw): def new_fn(*args, **kw):
return fp(*args, **kw) return fp(*args, **kw)
new_fn.__doc__ = fn.__doc__ new_fn.__doc__ = fn.__doc__
@ -716,18 +748,45 @@ class FuncTimer(object):
self.totaltime += duration self.totaltime += duration
if self.immediate: if self.immediate:
funcname = fn.__name__ funcname = fn.__name__
filename = fn.func_code.co_filename filename = fn.__code__.co_filename
lineno = fn.func_code.co_firstlineno lineno = fn.__code__.co_firstlineno
print >> sys.stderr, "\n %s (%s:%s):\n %.3f seconds\n" % ( sys.stderr.write("\n %s (%s:%s):\n %.3f seconds\n\n" % (
funcname, filename, lineno, duration) funcname, filename, lineno, duration
))
sys.stderr.flush()
def atexit(self): def atexit(self):
if not self.ncalls: if not self.ncalls:
return return
funcname = self.fn.__name__ funcname = self.fn.__name__
filename = self.fn.func_code.co_filename filename = self.fn.__code__.co_filename
lineno = self.fn.func_code.co_firstlineno lineno = self.fn.__code__.co_firstlineno
print ("\n %s (%s:%s):\n" print("\n %s (%s:%s):\n"
" %d calls, %.3f seconds (%.3f seconds per call)\n" % ( " %d calls, %.3f seconds (%.3f seconds per call)\n" % (
funcname, filename, lineno, self.ncalls, funcname, filename, lineno, self.ncalls,
self.totaltime, self.totaltime / self.ncalls)) self.totaltime, self.totaltime / self.ncalls)
)
if __name__ == '__main__':
local = dict((name, globals()[name]) for name in __all__)
message = """********
Injected `profilehooks`
--------
{}
********
""".format("\n".join(local.keys()))
def interact_():
from code import interact
interact(message, local=local)
def run_():
from runpy import run_module
print(message)
run_module(sys.argv[1], init_globals=local)
if len(sys.argv) == 1:
interact_()
else:
run_()