← Back to branch summary

~bzr-pqm/bzr/bzr.dev

« back to all changes in this revision

Viewing changes to bzrlib/lsprof.py

  • Committer: Patch Queue Manager
  • Date: 2014-04-09 13:36:25 UTC
  • mfrom: (6592.1.2 1303879-py27-issues)
  • Revision ID: pqm@pqm.ubuntu.com-20140409133625-s24spv3kha2w2860
(vila) Fix python-2.7.6 test failures. (Vincent Ladeuil)

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
from __future__ import absolute_import
 
7
 
 
8
import cPickle
 
9
import os
 
10
import sys
 
11
import thread
 
12
import threading
 
13
from _lsprof import Profiler, profiler_entry
 
14
 
 
15
from bzrlib import errors
 
16
 
 
17
__all__ = ['profile', 'Stats']
 
18
 
 
19
def profile(f, *args, **kwds):
 
20
    """Run a function profile.
 
21
 
 
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.
 
25
 
 
26
    Important caveat: only one profile can execute at a time. See BzrProfiler
 
27
    for details.
 
28
 
 
29
    :return: The functions return value and a stats object.
 
30
    """
 
31
    profiler = BzrProfiler()
 
32
    profiler.start()
 
33
    try:
 
34
        ret = f(*args, **kwds)
 
35
    finally:
 
36
        stats = profiler.stop()
 
37
    return ret, stats
 
38
 
 
39
 
 
40
class BzrProfiler(object):
 
41
    """Bzr utility wrapper around Profiler.
 
42
    
 
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.
 
46
 
 
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.
 
50
 
 
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.
 
57
    """
 
58
 
 
59
    profiler_block = 1
 
60
    """Serialise rather than failing to profile concurrent profile requests."""
 
61
 
 
62
    profiler_lock = threading.Lock()
 
63
    """Global lock used to serialise profiles."""
 
64
 
 
65
    def start(self):
 
66
        """Start profiling.
 
67
        
 
68
        This hooks into threading and will record all calls made until
 
69
        stop() is called.
 
70
        """
 
71
        self._g_threadmap = {}
 
72
        self.p = Profiler()
 
73
        permitted = self.__class__.profiler_lock.acquire(
 
74
            self.__class__.profiler_block)
 
75
        if not permitted:
 
76
            raise errors.InternalBzrError(msg="Already profiling something")
 
77
        try:
 
78
            self.p.enable(subcalls=True)
 
79
            threading.setprofile(self._thread_profile)
 
80
        except:
 
81
            self.__class__.profiler_lock.release()
 
82
            raise
 
83
 
 
84
    def stop(self):
 
85
        """Stop profiling.
 
86
 
 
87
        This unhooks from threading and cleans up the profiler, returning
 
88
        the gathered Stats object.
 
89
 
 
90
        :return: A bzrlib.lsprof.Stats object.
 
91
        """
 
92
        try:
 
93
            self.p.disable()
 
94
            for pp in self._g_threadmap.values():
 
95
                pp.disable()
 
96
            threading.setprofile(None)
 
97
            p = self.p
 
98
            self.p = None
 
99
            threads = {}
 
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)
 
104
        finally:
 
105
            self.__class__.profiler_lock.release()
 
106
 
 
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)
 
114
 
 
115
 
 
116
class Stats(object):
 
117
    """Wrapper around the collected data.
 
118
 
 
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.
 
122
    """
 
123
 
 
124
    def __init__(self, data, threads):
 
125
        self.data = data
 
126
        self.threads = threads
 
127
 
 
128
    def sort(self, crit="inlinetime"):
 
129
        """Sort the data by the supplied critera.
 
130
 
 
131
        :param crit: the data attribute used as the sort key."""
 
132
        if crit not in profiler_entry.__dict__:
 
133
            raise ValueError, "Can't sort by %s" % crit
 
134
        self.data.sort(lambda b, a: cmp(getattr(a, crit),
 
135
                                        getattr(b, crit)))
 
136
        for e in self.data:
 
137
            if e.calls:
 
138
                e.calls.sort(lambda b, a: cmp(getattr(a, crit),
 
139
                                              getattr(b, crit)))
 
140
 
 
141
    def pprint(self, top=None, file=None):
 
142
        """Pretty-print the data as plain text for human consumption.
 
143
 
 
144
        :param top: only output the top n entries.
 
145
            The default value of None means output all data.
 
146
        :param file: the output file; if None, output will
 
147
            default to stdout."""
 
148
        if file is None:
 
149
            file = sys.stdout
 
150
        d = self.data
 
151
        if top is not None:
 
152
            d = d[:top]
 
153
        cols = "% 12s %12s %11.4f %11.4f   %s\n"
 
154
        hcols = "% 12s %12s %12s %12s %s\n"
 
155
        cols2 = "+%12s %12s %11.4f %11.4f +  %s\n"
 
156
        file.write(hcols % ("CallCount", "Recursive", "Total(ms)",
 
157
                            "Inline(ms)", "module:lineno(function)"))
 
158
        for e in d:
 
159
            file.write(cols % (e.callcount, e.reccallcount, e.totaltime,
 
160
                               e.inlinetime, label(e.code)))
 
161
            if e.calls:
 
162
                for se in e.calls:
 
163
                    file.write(cols % ("+%s" % se.callcount, se.reccallcount,
 
164
                                       se.totaltime, se.inlinetime,
 
165
                                       "+%s" % label(se.code)))
 
166
 
 
167
    def freeze(self):
 
168
        """Replace all references to code objects with string
 
169
        descriptions; this makes it possible to pickle the instance."""
 
170
 
 
171
        # this code is probably rather ickier than it needs to be!
 
172
        for i in range(len(self.data)):
 
173
            e = self.data[i]
 
174
            if not isinstance(e.code, str):
 
175
                self.data[i] = type(e)((label(e.code),) + e[1:])
 
176
            if e.calls:
 
177
                for j in range(len(e.calls)):
 
178
                    se = e.calls[j]
 
179
                    if not isinstance(se.code, str):
 
180
                        e.calls[j] = type(se)((label(se.code),) + se[1:])
 
181
        for s in self.threads.values():
 
182
            s.freeze()
 
183
 
 
184
    def calltree(self, file):
 
185
        """Output profiling data in calltree format (for KCacheGrind)."""
 
186
        _CallTreeFilter(self.data).output(file)
 
187
 
 
188
    def save(self, filename, format=None):
 
189
        """Save profiling data to a file.
 
190
 
 
191
        :param filename: the name of the output file
 
192
        :param format: 'txt' for a text representation;
 
193
            'callgrind' for calltree format;
 
194
            otherwise a pickled Python object. A format of None indicates
 
195
            that the format to use is to be found from the filename. If
 
196
            the name starts with callgrind.out, callgrind format is used
 
197
            otherwise the format is given by the filename extension.
 
198
        """
 
199
        if format is None:
 
200
            basename = os.path.basename(filename)
 
201
            if basename.startswith('callgrind.out'):
 
202
                format = "callgrind"
 
203
            else:
 
204
                ext = os.path.splitext(filename)[1]
 
205
                if len(ext) > 1:
 
206
                    format = ext[1:]
 
207
        outfile = open(filename, 'wb')
 
208
        try:
 
209
            if format == "callgrind":
 
210
                self.calltree(outfile)
 
211
            elif format == "txt":
 
212
                self.pprint(file=outfile)
 
213
            else:
 
214
                self.freeze()
 
215
                cPickle.dump(self, outfile, 2)
 
216
        finally:
 
217
            outfile.close()
 
218
 
 
219
 
 
220
class _CallTreeFilter(object):
 
221
    """Converter of a Stats object to input suitable for KCacheGrind.
 
222
 
 
223
    This code is taken from http://ddaa.net/blog/python/lsprof-calltree
 
224
    with the changes made by J.P. Calderone and Itamar applied. Note that
 
225
    isinstance(code, str) needs to be used at times to determine if the code
 
226
    object is actually an external code object (with a filename, etc.) or
 
227
    a Python built-in.
 
228
    """
 
229
 
 
230
    def __init__(self, data):
 
231
        self.data = data
 
232
        self.out_file = None
 
233
 
 
234
    def output(self, out_file):
 
235
        self.out_file = out_file
 
236
        out_file.write('events: Ticks\n')
 
237
        self._print_summary()
 
238
        for entry in self.data:
 
239
            self._entry(entry)
 
240
 
 
241
    def _print_summary(self):
 
242
        max_cost = 0
 
243
        for entry in self.data:
 
244
            totaltime = int(entry.totaltime * 1000)
 
245
            max_cost = max(max_cost, totaltime)
 
246
        self.out_file.write('summary: %d\n' % (max_cost,))
 
247
 
 
248
    def _entry(self, entry):
 
249
        out_file = self.out_file
 
250
        code = entry.code
 
251
        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')
 
255
        else:
 
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,))
 
260
        else:
 
261
            out_file.write('%d %d\n' % (code.co_firstlineno, inlinetime))
 
262
        # recursive calls are counted in entry.calls
 
263
        if entry.calls:
 
264
            calls = entry.calls
 
265
        else:
 
266
            calls = []
 
267
        if isinstance(code, str):
 
268
            lineno = 0
 
269
        else:
 
270
            lineno = code.co_firstlineno
 
271
        for subentry in calls:
 
272
            self._subentry(lineno, subentry)
 
273
        out_file.write('\n')
 
274
 
 
275
    def _subentry(self, lineno, subentry):
 
276
        out_file = self.out_file
 
277
        code = subentry.code
 
278
        totaltime = int(subentry.totaltime * 1000)
 
279
        #out_file.write('cob=%s\n' % (code.co_filename,))
 
280
        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,))
 
284
        else:
 
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))
 
290
 
 
291
_fn2mod = {}
 
292
 
 
293
def label(code, calltree=False):
 
294
    if isinstance(code, str):
 
295
        return code
 
296
    try:
 
297
        mname = _fn2mod[code.co_filename]
 
298
    except KeyError:
 
299
        for k, v in sys.modules.items():
 
300
            if v is None:
 
301
                continue
 
302
            if getattr(v, '__file__', None) is None:
 
303
                continue
 
304
            if not isinstance(v.__file__, str):
 
305
                continue
 
306
            if v.__file__.startswith(code.co_filename):
 
307
                mname = _fn2mod[code.co_filename] = k
 
308
                break
 
309
        else:
 
310
            mname = _fn2mod[code.co_filename] = '<%s>'%code.co_filename
 
311
    if calltree:
 
312
        return '%s %s:%d' % (code.co_name, mname, code.co_firstlineno)
 
313
    else:
 
314
        return '%s:%d(%s)' % (mname, code.co_firstlineno, code.co_name)
 
315
 
 
316
 
 
317
if __name__ == '__main__':
 
318
    import os
 
319
    sys.argv = sys.argv[1:]
 
320
    if not sys.argv:
 
321
        sys.stderr.write("usage: lsprof.py <script> <arguments...>\n")
 
322
        sys.exit(2)
 
323
    sys.path.insert(0, os.path.abspath(os.path.dirname(sys.argv[0])))
 
324
    stats = profile(execfile, sys.argv[0], globals(), locals())
 
325
    stats.sort()
 
326
    stats.pprint()