← Back to branch summary

~bzr-pqm/bzr/bzr.dev

« back to all changes in this revision

Viewing changes to bzrlib/lsprof.py

  • Committer: Ian Clatworthy
  • Date: 2007-08-13 14:16:53 UTC
  • mto: (2733.1.1 ianc-integration)
  • mto: This revision was merged to the branch mainline in revision 2734.
  • Revision ID: ian.clatworthy@internode.on.net-20070813141653-3cbrp00xowq58zv1
Added mini tutorial

Show diffs side-by-side

added added

removed removed

Lines of Context:
bzrlib/lsprof.py
10
10
import threading
11
11
from _lsprof import Profiler, profiler_entry
12
12
 
13
 
from bzrlib import errors
14
 
 
15
13
__all__ = ['profile', 'Stats']
16
14
 
 
15
_g_threadmap = {}
 
16
 
 
17
 
 
18
def _thread_profile(f, *args, **kwds):
 
19
    # we lose the first profile point for a new thread in order to trampoline
 
20
    # a new Profile object into place
 
21
    global _g_threadmap
 
22
    thr = thread.get_ident()
 
23
    _g_threadmap[thr] = p = Profiler()
 
24
    # this overrides our sys.setprofile hook:
 
25
    p.enable(subcalls=True, builtins=True)
 
26
 
 
27
 
17
28
def profile(f, *args, **kwds):
18
 
    """Run a function profile.
19
 
 
20
 
    Exceptions are not caught: If you need stats even when exceptions are to be
21
 
    raised, pass in a closure that will catch the exceptions and transform them
22
 
    appropriately for your driver function.
23
 
 
24
 
    Important caveat: only one profile can execute at a time. See BzrProfiler
25
 
    for details.
26
 
 
27
 
    :return: The functions return value and a stats object.
28
 
    """
29
 
    profiler = BzrProfiler()
30
 
    profiler.start()
 
29
    """XXX docstring"""
 
30
    global _g_threadmap
 
31
    p = Profiler()
 
32
    p.enable(subcalls=True)
 
33
    threading.setprofile(_thread_profile)
31
34
    try:
32
35
        ret = f(*args, **kwds)
33
36
    finally:
34
 
        stats = profiler.stop()
35
 
    return ret, stats
36
 
 
37
 
 
38
 
class BzrProfiler(object):
39
 
    """Bzr utility wrapper around Profiler.
 
37
        p.disable()
 
38
        for pp in _g_threadmap.values():
 
39
            pp.disable()
 
40
        threading.setprofile(None)
40
41
    
41
 
    For most uses the module level 'profile()' function will be suitable.
42
 
    However profiling when a simple wrapped function isn't available may
43
 
    be easier to accomplish using this class.
44
 
 
45
 
    To use it, create a BzrProfiler and call start() on it. Some arbitrary
46
 
    time later call stop() to stop profiling and retrieve the statistics
47
 
    from the code executed in the interim.
48
 
 
49
 
    Note that profiling involves a threading.Lock around the actual profiling.
50
 
    This is needed because profiling involves global manipulation of the python
51
 
    interpreter state. As such you cannot perform multiple profiles at once.
52
 
    Trying to do so will lock out the second profiler unless the global 
53
 
    bzrlib.lsprof.BzrProfiler.profiler_block is set to 0. Setting it to 0 will
54
 
    cause profiling to fail rather than blocking.
55
 
    """
56
 
 
57
 
    profiler_block = 1
58
 
    """Serialise rather than failing to profile concurrent profile requests."""
59
 
 
60
 
    profiler_lock = threading.Lock()
61
 
    """Global lock used to serialise profiles."""
62
 
 
63
 
    def start(self):
64
 
        """Start profiling.
65
 
        
66
 
        This hooks into threading and will record all calls made until
67
 
        stop() is called.
68
 
        """
69
 
        self._g_threadmap = {}
70
 
        self.p = Profiler()
71
 
        permitted = self.__class__.profiler_lock.acquire(
72
 
            self.__class__.profiler_block)
73
 
        if not permitted:
74
 
            raise errors.InternalBzrError(msg="Already profiling something")
75
 
        try:
76
 
            self.p.enable(subcalls=True)
77
 
            threading.setprofile(self._thread_profile)
78
 
        except:
79
 
            self.__class__.profiler_lock.release()
80
 
            raise
81
 
 
82
 
    def stop(self):
83
 
        """Stop profiling.
84
 
 
85
 
        This unhooks from threading and cleans up the profiler, returning
86
 
        the gathered Stats object.
87
 
 
88
 
        :return: A bzrlib.lsprof.Stats object.
89
 
        """
90
 
        try:
91
 
            self.p.disable()
92
 
            for pp in self._g_threadmap.values():
93
 
                pp.disable()
94
 
            threading.setprofile(None)
95
 
            p = self.p
96
 
            self.p = None
97
 
            threads = {}
98
 
            for tid, pp in self._g_threadmap.items():
99
 
                threads[tid] = Stats(pp.getstats(), {})
100
 
            self._g_threadmap = None
101
 
            return Stats(p.getstats(), threads)
102
 
        finally:
103
 
            self.__class__.profiler_lock.release()
104
 
 
105
 
    def _thread_profile(self, f, *args, **kwds):
106
 
        # we lose the first profile point for a new thread in order to
107
 
        # trampoline a new Profile object into place
108
 
        thr = thread.get_ident()
109
 
        self._g_threadmap[thr] = p = Profiler()
110
 
        # this overrides our sys.setprofile hook:
111
 
        p.enable(subcalls=True, builtins=True)
 
42
    threads = {}
 
43
    for tid, pp in _g_threadmap.items():
 
44
        threads[tid] = Stats(pp.getstats(), {})
 
45
    _g_threadmap = {}
 
46
    return ret, Stats(p.getstats(), threads)
112
47
 
113
48
 
114
49
class Stats(object):
115
 
    """Wrapper around the collected data.
116
 
 
117
 
    A Stats instance is created when the profiler finishes. Normal
118
 
    usage is to use save() to write out the data to a file, or pprint()
119
 
    to write human-readable information to the command line.
120
 
    """
 
50
    """XXX docstring"""
121
51
 
122
52
    def __init__(self, data, threads):
123
53
        self.data = data
124
54
        self.threads = threads
125
55
 
126
56
    def sort(self, crit="inlinetime"):
127
 
        """Sort the data by the supplied critera.
128
 
 
129
 
        :param crit: the data attribute used as the sort key."""
 
57
        """XXX docstring"""
130
58
        if crit not in profiler_entry.__dict__:
131
59
            raise ValueError, "Can't sort by %s" % crit
132
60
        self.data.sort(lambda b, a: cmp(getattr(a, crit),
137
65
                                              getattr(b, crit)))
138
66
 
139
67
    def pprint(self, top=None, file=None):
140
 
        """Pretty-print the data as plain text for human consumption.
141
 
 
142
 
        :param top: only output the top n entries.
143
 
            The default value of None means output all data.
144
 
        :param file: the output file; if None, output will
145
 
            default to stdout."""
 
68
        """XXX docstring"""
146
69
        if file is None:
147
70
            file = sys.stdout
148
71
        d = self.data
195
118
            otherwise the format is given by the filename extension.
196
119
        """
197
120
        if format is None:
198
 
            basename = os.path.basename(filename)
199
 
            if basename.startswith('callgrind.out'):
 
121
            if filename.startswith('callgrind.out'):
200
122
                format = "callgrind"
201
123
            else:
202
124
                ext = os.path.splitext(filename)[1]
220
142
 
221
143
    This code is taken from http://ddaa.net/blog/python/lsprof-calltree
222
144
    with the changes made by J.P. Calderone and Itamar applied. Note that
223
 
    isinstance(code, str) needs to be used at times to determine if the code
 
145
    isinstance(code, str) needs to be used at times to determine if the code 
224
146
    object is actually an external code object (with a filename, etc.) or
225
147
    a Python built-in.
226
148
    """
230
152
        self.out_file = None
231
153
 
232
154
    def output(self, out_file):
233
 
        self.out_file = out_file
234
 
        out_file.write('events: Ticks\n')
 
155
        self.out_file = out_file        
 
156
        print >> out_file, 'events: Ticks'
235
157
        self._print_summary()
236
158
        for entry in self.data:
237
159
            self._entry(entry)
241
163
        for entry in self.data:
242
164
            totaltime = int(entry.totaltime * 1000)
243
165
            max_cost = max(max_cost, totaltime)
244
 
        self.out_file.write('summary: %d\n' % (max_cost,))
 
166
        print >> self.out_file, 'summary: %d' % (max_cost,)
245
167
 
246
168
    def _entry(self, entry):
247
169
        out_file = self.out_file
248
170
        code = entry.code
249
171
        inlinetime = int(entry.inlinetime * 1000)
250
 
        #out_file.write('ob=%s\n' % (code.co_filename,))
251
 
        if isinstance(code, str):
252
 
            out_file.write('fi=~\n')
253
 
        else:
254
 
            out_file.write('fi=%s\n' % (code.co_filename,))
255
 
        out_file.write('fn=%s\n' % (label(code, True),))
256
 
        if isinstance(code, str):
257
 
            out_file.write('0  %s\n' % (inlinetime,))
258
 
        else:
259
 
            out_file.write('%d %d\n' % (code.co_firstlineno, inlinetime))
 
172
        #print >> out_file, 'ob=%s' % (code.co_filename,)
 
173
        if isinstance(code, str):
 
174
            print >> out_file, 'fi=~'
 
175
        else:
 
176
            print >> out_file, 'fi=%s' % (code.co_filename,)
 
177
        print >> out_file, 'fn=%s' % (label(code, True),)
 
178
        if isinstance(code, str):
 
179
            print >> out_file, '0 ', inlinetime
 
180
        else:
 
181
            print >> out_file, '%d %d' % (code.co_firstlineno, inlinetime)
260
182
        # recursive calls are counted in entry.calls
261
183
        if entry.calls:
262
184
            calls = entry.calls
268
190
            lineno = code.co_firstlineno
269
191
        for subentry in calls:
270
192
            self._subentry(lineno, subentry)
271
 
        out_file.write('\n')
 
193
        print >> out_file
272
194
 
273
195
    def _subentry(self, lineno, subentry):
274
196
        out_file = self.out_file
275
197
        code = subentry.code
276
198
        totaltime = int(subentry.totaltime * 1000)
277
 
        #out_file.write('cob=%s\n' % (code.co_filename,))
 
199
        #print >> out_file, 'cob=%s' % (code.co_filename,)
 
200
        print >> out_file, 'cfn=%s' % (label(code, True),)
278
201
        if isinstance(code, str):
279
 
            out_file.write('cfi=~\n')
280
 
            out_file.write('cfn=%s\n' % (label(code, True),))
281
 
            out_file.write('calls=%d 0\n' % (subentry.callcount,))
 
202
            print >> out_file, 'cfi=~'
 
203
            print >> out_file, 'calls=%d 0' % (subentry.callcount,)
282
204
        else:
283
 
            out_file.write('cfi=%s\n' % (code.co_filename,))
284
 
            out_file.write('cfn=%s\n' % (label(code, True),))
285
 
            out_file.write('calls=%d %d\n' % (
286
 
                subentry.callcount, code.co_firstlineno))
287
 
        out_file.write('%d %d\n' % (lineno, totaltime))
 
205
            print >> out_file, 'cfi=%s' % (code.co_filename,)
 
206
            print >> out_file, 'calls=%d %d' % (
 
207
                subentry.callcount, code.co_firstlineno)
 
208
        print >> out_file, '%d %d' % (lineno, totaltime)
288
209
 
289
210
_fn2mod = {}
290
211
 
316
237
    import os
317
238
    sys.argv = sys.argv[1:]
318
239
    if not sys.argv:
319
 
        sys.stderr.write("usage: lsprof.py <script> <arguments...>\n")
 
240
        print >> sys.stderr, "usage: lsprof.py <script> <arguments...>"
320
241
        sys.exit(2)
321
242
    sys.path.insert(0, os.path.abspath(os.path.dirname(sys.argv[0])))
322
243
    stats = profile(execfile, sys.argv[0], globals(), locals())