13
11
from _lsprof import Profiler, profiler_entry
15
from bzrlib import errors
17
17
__all__ = ['profile', 'Stats']
22
def _thread_profile(f, *args, **kwds):
23
# we lose the first profile point for a new thread in order to trampoline
24
# a new Profile object into place
26
thr = thread.get_ident()
27
_g_threadmap[thr] = p = Profiler()
28
# this overrides our sys.setprofile hook:
29
p.enable(subcalls=True, builtins=True)
19
32
def profile(f, *args, **kwds):
20
"""Run a function profile.
22
Exceptions are not caught: If you need stats even when exceptions are to be
23
raised, pass in a closure that will catch the exceptions and transform them
24
appropriately for your driver function.
26
Important caveat: only one profile can execute at a time. See BzrProfiler
29
:return: The functions return value and a stats object.
31
profiler = BzrProfiler()
36
p.enable(subcalls=True)
37
threading.setprofile(_thread_profile)
38
# Note: The except clause is needed below so that profiling data still
39
# gets dumped even when exceptions are encountered. The except clause code
40
# is taken straight from run_bzr_catch_errrors() in commands.py and ought
41
# to be kept in sync with it.
34
ret = f(*args, **kwds)
44
ret = f(*args, **kwds)
45
except (KeyboardInterrupt, Exception), e:
47
bzrlib.trace.report_exception(sys.exc_info(), sys.stderr)
36
stats = profiler.stop()
40
class BzrProfiler(object):
41
"""Bzr utility wrapper around Profiler.
51
for pp in _g_threadmap.values():
53
threading.setprofile(None)
43
For most uses the module level 'profile()' function will be suitable.
44
However profiling when a simple wrapped function isn't available may
45
be easier to accomplish using this class.
47
To use it, create a BzrProfiler and call start() on it. Some arbitrary
48
time later call stop() to stop profiling and retrieve the statistics
49
from the code executed in the interim.
51
Note that profiling involves a threading.Lock around the actual profiling.
52
This is needed because profiling involves global manipulation of the python
53
interpreter state. As such you cannot perform multiple profiles at once.
54
Trying to do so will lock out the second profiler unless the global
55
bzrlib.lsprof.BzrProfiler.profiler_block is set to 0. Setting it to 0 will
56
cause profiling to fail rather than blocking.
60
"""Serialise rather than failing to profile concurrent profile requests."""
62
profiler_lock = threading.Lock()
63
"""Global lock used to serialise profiles."""
68
This hooks into threading and will record all calls made until
71
self._g_threadmap = {}
73
permitted = self.__class__.profiler_lock.acquire(
74
self.__class__.profiler_block)
76
raise errors.InternalBzrError(msg="Already profiling something")
78
self.p.enable(subcalls=True)
79
threading.setprofile(self._thread_profile)
81
self.__class__.profiler_lock.release()
87
This unhooks from threading and cleans up the profiler, returning
88
the gathered Stats object.
90
:return: A bzrlib.lsprof.Stats object.
94
for pp in self._g_threadmap.values():
96
threading.setprofile(None)
100
for tid, pp in self._g_threadmap.items():
101
threads[tid] = Stats(pp.getstats(), {})
102
self._g_threadmap = None
103
return Stats(p.getstats(), threads)
105
self.__class__.profiler_lock.release()
107
def _thread_profile(self, f, *args, **kwds):
108
# we lose the first profile point for a new thread in order to
109
# trampoline a new Profile object into place
110
thr = thread.get_ident()
111
self._g_threadmap[thr] = p = Profiler()
112
# this overrides our sys.setprofile hook:
113
p.enable(subcalls=True, builtins=True)
56
for tid, pp in _g_threadmap.items():
57
threads[tid] = Stats(pp.getstats(), {})
59
return ret, Stats(p.getstats(), threads)
116
62
class Stats(object):
117
"""Wrapper around the collected data.
119
A Stats instance is created when the profiler finishes. Normal
120
usage is to use save() to write out the data to a file, or pprint()
121
to write human-readable information to the command line.
124
65
def __init__(self, data, threads):
126
67
self.threads = threads
128
69
def sort(self, crit="inlinetime"):
129
"""Sort the data by the supplied critera.
131
:param crit: the data attribute used as the sort key."""
132
71
if crit not in profiler_entry.__dict__:
133
72
raise ValueError, "Can't sort by %s" % crit
134
73
self.data.sort(lambda b, a: cmp(getattr(a, crit),
243
177
for entry in self.data:
244
178
totaltime = int(entry.totaltime * 1000)
245
179
max_cost = max(max_cost, totaltime)
246
self.out_file.write('summary: %d\n' % (max_cost,))
180
print >> self.out_file, 'summary: %d' % (max_cost,)
248
182
def _entry(self, entry):
249
183
out_file = self.out_file
250
184
code = entry.code
251
185
inlinetime = int(entry.inlinetime * 1000)
252
#out_file.write('ob=%s\n' % (code.co_filename,))
253
if isinstance(code, str):
254
out_file.write('fi=~\n')
256
out_file.write('fi=%s\n' % (code.co_filename,))
257
out_file.write('fn=%s\n' % (label(code, True),))
258
if isinstance(code, str):
259
out_file.write('0 %s\n' % (inlinetime,))
261
out_file.write('%d %d\n' % (code.co_firstlineno, inlinetime))
186
#print >> out_file, 'ob=%s' % (code.co_filename,)
187
if isinstance(code, str):
188
print >> out_file, 'fi=~'
190
print >> out_file, 'fi=%s' % (code.co_filename,)
191
print >> out_file, 'fn=%s' % (label(code, True),)
192
if isinstance(code, str):
193
print >> out_file, '0 ', inlinetime
195
print >> out_file, '%d %d' % (code.co_firstlineno, inlinetime)
262
196
# recursive calls are counted in entry.calls
264
198
calls = entry.calls
270
204
lineno = code.co_firstlineno
271
205
for subentry in calls:
272
206
self._subentry(lineno, subentry)
275
209
def _subentry(self, lineno, subentry):
276
210
out_file = self.out_file
277
211
code = subentry.code
278
212
totaltime = int(subentry.totaltime * 1000)
279
#out_file.write('cob=%s\n' % (code.co_filename,))
213
#print >> out_file, 'cob=%s' % (code.co_filename,)
214
print >> out_file, 'cfn=%s' % (label(code, True),)
280
215
if isinstance(code, str):
281
out_file.write('cfi=~\n')
282
out_file.write('cfn=%s\n' % (label(code, True),))
283
out_file.write('calls=%d 0\n' % (subentry.callcount,))
216
print >> out_file, 'cfi=~'
217
print >> out_file, 'calls=%d 0' % (subentry.callcount,)
285
out_file.write('cfi=%s\n' % (code.co_filename,))
286
out_file.write('cfn=%s\n' % (label(code, True),))
287
out_file.write('calls=%d %d\n' % (
288
subentry.callcount, code.co_firstlineno))
289
out_file.write('%d %d\n' % (lineno, totaltime))
219
print >> out_file, 'cfi=%s' % (code.co_filename,)
220
print >> out_file, 'calls=%d %d' % (
221
subentry.callcount, code.co_firstlineno)
222
print >> out_file, '%d %d' % (lineno, totaltime)