← Back to branch summary

~bzr-pqm/bzr/bzr.dev

« back to all changes in this revision

Viewing changes to profile_imports.py

Turn completion assertions into separate methods.

Many common assertions used to be expressed as arguments to the complete
method.  This makes the checks more explicit, and the code easier to read.

Show diffs side-by-side

added added

removed removed

Lines of Context:
profile_imports.py
1
 
# Copyright (C) 2006, 2008, 2009, 2010 by Canonical Ltd
2
 
# Written by John Arbash Meinel <john@arbash-meinel.com>
3
 
#
4
 
# This program is free software; you can redistribute it and/or modify
5
 
# it under the terms of the GNU General Public License as published by
6
 
# the Free Software Foundation; either version 2 of the License, or
7
 
# (at your option) any later version.
8
 
#
9
 
# This program is distributed in the hope that it will be useful,
10
 
# but WITHOUT ANY WARRANTY; without even the implied warranty of
11
 
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
12
 
# GNU General Public License for more details.
13
 
#
14
 
# You should have received a copy of the GNU General Public License
15
 
# along with this program; if not, write to the Free Software
16
 
# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
17
 
 
18
 
"""A custom importer and regex compiler which logs time spent."""
19
 
 
20
 
import sys
21
 
import time
22
 
 
23
 
 
24
 
import re
25
 
 
26
 
 
27
 
_parent_stack = []
28
 
_total_stack = {}
29
 
_info = {}
30
 
_cur_id = 0
31
 
_timer = time.time
32
 
if sys.platform == 'win32':
33
 
    _timer = time.clock
34
 
 
35
 
 
36
 
def stack_add(name, frame_name, frame_lineno, scope_name=None):
37
 
    """Start a new record on the stack"""
38
 
    global _cur_id
39
 
    _cur_id += 1
40
 
    this_stack = (_cur_id, name)
41
 
 
42
 
    if _parent_stack:
43
 
        _total_stack[_parent_stack[-1]].append(this_stack)
44
 
    _total_stack[this_stack] = []
45
 
    _parent_stack.append(this_stack)
46
 
    _info[this_stack] = [len(_parent_stack)-1, frame_name, frame_lineno, scope_name]
47
 
 
48
 
    return this_stack
49
 
 
50
 
 
51
 
def stack_finish(this, cost):
52
 
    """Finish a given entry, and record its cost in time"""
53
 
    global _parent_stack
54
 
 
55
 
    assert _parent_stack[-1] == this, \
56
 
        'import stack does not end with this %s: %s' % (this, _parent_stack)
57
 
    _parent_stack.pop()
58
 
    _info[this].append(cost)
59
 
 
60
 
 
61
 
def log_stack_info(out_file, sorted=True, hide_fast=True):
62
 
    # Find all of the roots with import = 0
63
 
    out_file.write('%5s %5s %-40s @ %s:%s\n'
64
 
        % ('cum', 'inline', 'name', 'file', 'line'))
65
 
    todo = [(value[-1], key) for key,value in _info.iteritems() if value[0] == 0]
66
 
 
67
 
    if sorted:
68
 
        todo.sort()
69
 
 
70
 
    while todo:
71
 
        cum_time, cur = todo.pop()
72
 
        children = _total_stack[cur]
73
 
 
74
 
        c_times = []
75
 
 
76
 
        info = _info[cur]
77
 
        if hide_fast and info[-1] < 0.0001:
78
 
            continue
79
 
 
80
 
        # Compute the module time by removing the children times
81
 
        mod_time = info[-1]
82
 
        for child in children:
83
 
            c_info = _info[child]
84
 
            mod_time -= c_info[-1]
85
 
            c_times.append((c_info[-1], child))
86
 
 
87
 
        # indent, cum_time, mod_time, name,
88
 
        # scope_name, frame_name, frame_lineno
89
 
        out_file.write('%5.1f %5.1f %-40s @ %s:%d\n'
90
 
            % (info[-1]*1000., mod_time*1000.,
91
 
               ('+'*info[0] + cur[1]),
92
 
               info[1], info[2]))
93
 
 
94
 
        if sorted:
95
 
            c_times.sort()
96
 
        else:
97
 
            c_times.reverse()
98
 
        todo.extend(c_times)
99
 
 
100
 
 
101
 
_real_import = __import__
102
 
 
103
 
def timed_import(name, globals=None, locals=None, fromlist=None, level=None):
104
 
    """Wrap around standard importer to log import time"""
105
 
    # normally there are 4, but if this is called as __import__ eg by
106
 
    # /usr/lib/python2.6/email/__init__.py then there may be only one
107
 
    # parameter
108
 
    # level is only passed by python2.6
109
 
 
110
 
    if globals is None:
111
 
        # can't determine the scope name afaics; we could peek up the stack to
112
 
        # see where this is being called from, but it should be a rare case.
113
 
        scope_name = None
114
 
    else:
115
 
        scope_name = globals.get('__name__', None)
116
 
        if scope_name is None:
117
 
            scope_name = globals.get('__file__', None)
118
 
        if scope_name is None:
119
 
            scope_name = globals.keys()
120
 
        else:
121
 
            # Trim out paths before bzrlib
122
 
            loc = scope_name.find('bzrlib')
123
 
            if loc != -1:
124
 
                scope_name = scope_name[loc:]
125
 
            # For stdlib, trim out early paths
126
 
            loc = scope_name.find('python2.4')
127
 
            if loc != -1:
128
 
                scope_name = scope_name[loc:]
129
 
 
130
 
    # Figure out the frame that is doing the importing
131
 
    frame = sys._getframe(1)
132
 
    frame_name = frame.f_globals.get('__name__', '<unknown>')
133
 
    extra = ''
134
 
    if frame_name.endswith('demandload'):
135
 
        # If this was demandloaded, we have 3 frames to ignore
136
 
        extra = '(demandload) '
137
 
        frame = sys._getframe(4)
138
 
        frame_name = frame.f_globals.get('__name__', '<unknown>')
139
 
    elif frame_name.endswith('lazy_import'):
140
 
        # If this was lazily imported, we have 3 frames to ignore
141
 
        extra = '[l] '
142
 
        frame = sys._getframe(4)
143
 
        frame_name = frame.f_globals.get('__name__', '<unknown>')
144
 
    if fromlist:
145
 
        extra += ' [%s]' % (', '.join(map(str, fromlist)),)
146
 
    frame_lineno = frame.f_lineno
147
 
 
148
 
    this = stack_add(extra + name, frame_name, frame_lineno, scope_name)
149
 
 
150
 
    tstart = _timer()
151
 
    try:
152
 
        # Do the import
153
 
        mod = _real_import(name, globals, locals, fromlist)
154
 
    finally:
155
 
        tload = _timer()-tstart
156
 
        stack_finish(this, tload)
157
 
 
158
 
    return mod
159
 
 
160
 
 
161
 
_real_compile = re._compile
162
 
 
163
 
 
164
 
def timed_compile(*args, **kwargs):
165
 
    """Log how long it takes to compile a regex"""
166
 
 
167
 
    # And who is requesting this?
168
 
    frame = sys._getframe(2)
169
 
    frame_name = frame.f_globals.get('__name__', '<unknown>')
170
 
 
171
 
    extra = ''
172
 
    if frame_name.endswith('lazy_regex'):
173
 
        # If this was lazily compiled, we have 3 more frames to ignore
174
 
        extra = '[l] '
175
 
        frame = sys._getframe(5)
176
 
        frame_name = frame.f_globals.get('__name__', '<unknown>')
177
 
    frame_lineno = frame.f_lineno
178
 
    this = stack_add(extra+repr(args[0]), frame_name, frame_lineno)
179
 
 
180
 
    tstart = _timer()
181
 
    try:
182
 
        # Measure the compile time
183
 
        comp = _real_compile(*args, **kwargs)
184
 
    finally:
185
 
        tcompile = _timer() - tstart
186
 
        stack_finish(this, tcompile)
187
 
 
188
 
    return comp
189
 
 
190
 
 
191
 
def install():
192
 
    """Install the hooks for measuring import and regex compile time."""
193
 
    __builtins__['__import__'] = timed_import
194
 
    re._compile = timed_compile
195
 
 
196
 
 
197
 
def uninstall():
198
 
    """Remove the import and regex compile timing hooks."""
199
 
    __builtins__['__import__'] = _real_import
200
 
    re._compile = _real_compile
201