← Back to branch summary

~bzr-pqm/bzr/bzr.dev

« back to all changes in this revision

Viewing changes to bzrlib/lsprof.py

  • Committer: Martin Packman
  • Date: 2011-11-17 13:45:49 UTC
  • mto: This revision was merged to the branch mainline in revision 6271.
  • Revision ID: martin.packman@canonical.com-20111117134549-080e1fhtrzoicexg
https://launchpad.net/bugs/891582
Only assert FileExists path in test_transform directory clash tests to avoid stringification fallout

Show diffs side-by-side

added added

removed removed

Lines of Context:
bzrlib/lsprof.py
 
1
# this is copied from the lsprof distro because somehow
 
2
# it is not installed by distutils
 
3
# I made one modification to profile so that it returns a pair
 
4
# instead of just the Stats object
 
5
 
 
6
import cPickle
 
7
import os
 
8
import sys
 
9
import thread
 
10
import threading
 
11
from _lsprof import Profiler, profiler_entry
 
12
 
 
13
from bzrlib import errors
 
14
 
 
15
__all__ = ['profile', 'Stats']
 
16
 
 
17
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()
 
31
    try:
 
32
        ret = f(*args, **kwds)
 
33
    finally:
 
34
        stats = profiler.stop()
 
35
    return ret, stats
 
36
 
 
37
 
 
38
class BzrProfiler(object):
 
39
    """Bzr utility wrapper around Profiler.
 
40
    
 
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)
 
112
 
 
113
 
 
114
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
    """
 
121
 
 
122
    def __init__(self, data, threads):
 
123
        self.data = data
 
124
        self.threads = threads
 
125
 
 
126
    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."""
 
130
        if crit not in profiler_entry.__dict__:
 
131
            raise ValueError, "Can't sort by %s" % crit
 
132
        self.data.sort(lambda b, a: cmp(getattr(a, crit),
 
133
                                        getattr(b, crit)))
 
134
        for e in self.data:
 
135
            if e.calls:
 
136
                e.calls.sort(lambda b, a: cmp(getattr(a, crit),
 
137
                                              getattr(b, crit)))
 
138
 
 
139
    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."""
 
146
        if file is None:
 
147
            file = sys.stdout
 
148
        d = self.data
 
149
        if top is not None:
 
150
            d = d[:top]
 
151
        cols = "% 12s %12s %11.4f %11.4f   %s\n"
 
152
        hcols = "% 12s %12s %12s %12s %s\n"
 
153
        cols2 = "+%12s %12s %11.4f %11.4f +  %s\n"
 
154
        file.write(hcols % ("CallCount", "Recursive", "Total(ms)",
 
155
                            "Inline(ms)", "module:lineno(function)"))
 
156
        for e in d:
 
157
            file.write(cols % (e.callcount, e.reccallcount, e.totaltime,
 
158
                               e.inlinetime, label(e.code)))
 
159
            if e.calls:
 
160
                for se in e.calls:
 
161
                    file.write(cols % ("+%s" % se.callcount, se.reccallcount,
 
162
                                       se.totaltime, se.inlinetime,
 
163
                                       "+%s" % label(se.code)))
 
164
 
 
165
    def freeze(self):
 
166
        """Replace all references to code objects with string
 
167
        descriptions; this makes it possible to pickle the instance."""
 
168
 
 
169
        # this code is probably rather ickier than it needs to be!
 
170
        for i in range(len(self.data)):
 
171
            e = self.data[i]
 
172
            if not isinstance(e.code, str):
 
173
                self.data[i] = type(e)((label(e.code),) + e[1:])
 
174
            if e.calls:
 
175
                for j in range(len(e.calls)):
 
176
                    se = e.calls[j]
 
177
                    if not isinstance(se.code, str):
 
178
                        e.calls[j] = type(se)((label(se.code),) + se[1:])
 
179
        for s in self.threads.values():
 
180
            s.freeze()
 
181
 
 
182
    def calltree(self, file):
 
183
        """Output profiling data in calltree format (for KCacheGrind)."""
 
184
        _CallTreeFilter(self.data).output(file)
 
185
 
 
186
    def save(self, filename, format=None):
 
187
        """Save profiling data to a file.
 
188
 
 
189
        :param filename: the name of the output file
 
190
        :param format: 'txt' for a text representation;
 
191
            'callgrind' for calltree format;
 
192
            otherwise a pickled Python object. A format of None indicates
 
193
            that the format to use is to be found from the filename. If
 
194
            the name starts with callgrind.out, callgrind format is used
 
195
            otherwise the format is given by the filename extension.
 
196
        """
 
197
        if format is None:
 
198
            basename = os.path.basename(filename)
 
199
            if basename.startswith('callgrind.out'):
 
200
                format = "callgrind"
 
201
            else:
 
202
                ext = os.path.splitext(filename)[1]
 
203
                if len(ext) > 1:
 
204
                    format = ext[1:]
 
205
        outfile = open(filename, 'wb')
 
206
        try:
 
207
            if format == "callgrind":
 
208
                self.calltree(outfile)
 
209
            elif format == "txt":
 
210
                self.pprint(file=outfile)
 
211
            else:
 
212
                self.freeze()
 
213
                cPickle.dump(self, outfile, 2)
 
214
        finally:
 
215
            outfile.close()
 
216
 
 
217
 
 
218
class _CallTreeFilter(object):
 
219
    """Converter of a Stats object to input suitable for KCacheGrind.
 
220
 
 
221
    This code is taken from http://ddaa.net/blog/python/lsprof-calltree
 
222
    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
 
224
    object is actually an external code object (with a filename, etc.) or
 
225
    a Python built-in.
 
226
    """
 
227
 
 
228
    def __init__(self, data):
 
229
        self.data = data
 
230
        self.out_file = None
 
231
 
 
232
    def output(self, out_file):
 
233
        self.out_file = out_file
 
234
        out_file.write('events: Ticks\n')
 
235
        self._print_summary()
 
236
        for entry in self.data:
 
237
            self._entry(entry)
 
238
 
 
239
    def _print_summary(self):
 
240
        max_cost = 0
 
241
        for entry in self.data:
 
242
            totaltime = int(entry.totaltime * 1000)
 
243
            max_cost = max(max_cost, totaltime)
 
244
        self.out_file.write('summary: %d\n' % (max_cost,))
 
245
 
 
246
    def _entry(self, entry):
 
247
        out_file = self.out_file
 
248
        code = entry.code
 
249
        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))
 
260
        # recursive calls are counted in entry.calls
 
261
        if entry.calls:
 
262
            calls = entry.calls
 
263
        else:
 
264
            calls = []
 
265
        if isinstance(code, str):
 
266
            lineno = 0
 
267
        else:
 
268
            lineno = code.co_firstlineno
 
269
        for subentry in calls:
 
270
            self._subentry(lineno, subentry)
 
271
        out_file.write('\n')
 
272
 
 
273
    def _subentry(self, lineno, subentry):
 
274
        out_file = self.out_file
 
275
        code = subentry.code
 
276
        totaltime = int(subentry.totaltime * 1000)
 
277
        #out_file.write('cob=%s\n' % (code.co_filename,))
 
278
        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,))
 
282
        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))
 
288
 
 
289
_fn2mod = {}
 
290
 
 
291
def label(code, calltree=False):
 
292
    if isinstance(code, str):
 
293
        return code
 
294
    try:
 
295
        mname = _fn2mod[code.co_filename]
 
296
    except KeyError:
 
297
        for k, v in sys.modules.items():
 
298
            if v is None:
 
299
                continue
 
300
            if getattr(v, '__file__', None) is None:
 
301
                continue
 
302
            if not isinstance(v.__file__, str):
 
303
                continue
 
304
            if v.__file__.startswith(code.co_filename):
 
305
                mname = _fn2mod[code.co_filename] = k
 
306
                break
 
307
        else:
 
308
            mname = _fn2mod[code.co_filename] = '<%s>'%code.co_filename
 
309
    if calltree:
 
310
        return '%s %s:%d' % (code.co_name, mname, code.co_firstlineno)
 
311
    else:
 
312
        return '%s:%d(%s)' % (mname, code.co_firstlineno, code.co_name)
 
313
 
 
314
 
 
315
if __name__ == '__main__':
 
316
    import os
 
317
    sys.argv = sys.argv[1:]
 
318
    if not sys.argv:
 
319
        sys.stderr.write("usage: lsprof.py <script> <arguments...>\n")
 
320
        sys.exit(2)
 
321
    sys.path.insert(0, os.path.abspath(os.path.dirname(sys.argv[0])))
 
322
    stats = profile(execfile, sys.argv[0], globals(), locals())
 
323
    stats.sort()
 
324
    stats.pprint()