~bzr-pqm/bzr/bzr.dev

1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
1
# Copyright (C) 2006 by Canonical Ltd
1724.2.13 by John Arbash Meinel
Remove pprint dependency
2
# Written by John Arbash Meinel <john@arbash-meinel.com>
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
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., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
17
1724.2.7 by John Arbash Meinel
It seems you cannot override __builtins__.__import__ in a sub-module.
18
"""A custom importer and regex compiler which logs time spent."""
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
19
1724.2.7 by John Arbash Meinel
It seems you cannot override __builtins__.__import__ in a sub-module.
20
import sre
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
21
import sys
22
import time
1724.2.7 by John Arbash Meinel
It seems you cannot override __builtins__.__import__ in a sub-module.
23
24
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
25
_parent_stack = []
26
_total_stack = {}
27
_info = {}
28
_cur_id = 0
3696.1.1 by John Arbash Meinel
Use the right timing function on win32
29
_timer = time.time
30
if sys.platform == 'win32':
31
    _timer = time.clock
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
32
33
34
def stack_add(name, frame_name, frame_lineno, scope_name=None):
35
    """Start a new record on the stack"""
36
    global _cur_id
37
    _cur_id += 1
38
    this_stack = (_cur_id, name)
39
40
    if _parent_stack:
41
        _total_stack[_parent_stack[-1]].append(this_stack)
42
    _total_stack[this_stack] = []
43
    _parent_stack.append(this_stack)
44
    _info[this_stack] = [len(_parent_stack)-1, frame_name, frame_lineno, scope_name]
45
46
    return this_stack
47
48
49
def stack_finish(this, cost):
50
    """Finish a given entry, and record its cost in time"""
51
    global _parent_stack
52
1724.2.13 by John Arbash Meinel
Remove pprint dependency
53
    assert _parent_stack[-1] == this, \
54
        'import stack does not end with this %s: %s' % (this, _parent_stack)
55
    _parent_stack.pop()
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
56
    _info[this].append(cost)
57
58
1724.2.12 by John Arbash Meinel
Default to hiding things that take less that .1ms to keep the output clean.
59
def log_stack_info(out_file, sorted=True, hide_fast=True):
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
60
    # Find all of the roots with import = 0
1724.2.12 by John Arbash Meinel
Default to hiding things that take less that .1ms to keep the output clean.
61
    out_file.write(' cum  inline name\t\t\t\t\t\tframe\n')
1724.2.10 by John Arbash Meinel
More layout work
62
    todo = [(value[-1], key) for key,value in _info.iteritems() if value[0] == 0]
63
64
    if sorted:
65
        todo.sort()
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
66
67
    while todo:
1724.2.10 by John Arbash Meinel
More layout work
68
        cum_time, cur = todo.pop()
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
69
        children = _total_stack[cur]
70
1724.2.10 by John Arbash Meinel
More layout work
71
        c_times = []
72
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
73
        info = _info[cur]
1724.2.12 by John Arbash Meinel
Default to hiding things that take less that .1ms to keep the output clean.
74
        if hide_fast and info[-1] < 0.0001:
75
            continue
76
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
77
        # Compute the module time by removing the children times
78
        mod_time = info[-1]
79
        for child in children:
80
            c_info = _info[child]
81
            mod_time -= c_info[-1]
1724.2.10 by John Arbash Meinel
More layout work
82
            c_times.append((c_info[-1], child))
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
83
84
        # indent, cum_time, mod_time, name,
85
        # scope_name, frame_name, frame_lineno
1724.2.11 by John Arbash Meinel
Remove scope name for now, still log it, in case we need it for demandload.
86
        out_file.write('%5.1f %5.1f %s %-35s\t@ %s:%d\n'
1724.2.9 by John Arbash Meinel
change layout to be easier to mentally parse.
87
            % (info[-1]*1000., mod_time*1000., '+'*info[0], 
1996.3.16 by John Arbash Meinel
Update output of --profile-imports to understand from foo import bar time
88
               cur[1][:35], info[1], info[2]))
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
89
1724.2.10 by John Arbash Meinel
More layout work
90
        if sorted:
91
            c_times.sort()
92
        else:
93
            c_times.reverse()
94
        todo.extend(c_times)
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
95
96
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
97
_real_import = __import__
98
1724.2.7 by John Arbash Meinel
It seems you cannot override __builtins__.__import__ in a sub-module.
99
def timed_import(name, globals, locals, fromlist):
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
100
    """Wrap around standard importer to log import time"""
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
101
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
102
    scope_name = globals.get('__name__', None)
103
    if scope_name is None:
104
        scope_name = globals.get('__file__', None)
105
    if scope_name is None:
106
        scope_name = globals.keys()
107
    else:
108
        # Trim out paths before bzrlib
109
        loc = scope_name.find('bzrlib')
110
        if loc != -1:
111
            scope_name = scope_name[loc:]
112
        # For stdlib, trim out early paths
113
        loc = scope_name.find('python2.4')
114
        if loc != -1:
115
            scope_name = scope_name[loc:]
116
117
    # Figure out the frame that is doing the importing
118
    frame = sys._getframe(1)
119
    frame_name = frame.f_globals.get('__name__', '<unknown>')
120
    extra = ''
121
    if frame_name.endswith('demandload'):
122
        # If this was demandloaded, we have 3 frames to ignore
2063.4.3 by John Arbash Meinel
Update profile imports to be aware of the new compiler
123
        extra = '(demandload) '
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
124
        frame = sys._getframe(4)
1996.3.2 by John Arbash Meinel
Make profile_imports aware of lazy_import stuff
125
        frame_name = frame.f_globals.get('__name__', '<unknown>')
126
    elif frame_name.endswith('lazy_import'):
127
        # If this was lazily imported, we have 3 frames to ignore
2063.4.3 by John Arbash Meinel
Update profile imports to be aware of the new compiler
128
        extra = '[l] '
1996.3.2 by John Arbash Meinel
Make profile_imports aware of lazy_import stuff
129
        frame = sys._getframe(4)
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
130
        frame_name = frame.f_globals.get('__name__', '<unknown>')
1996.3.16 by John Arbash Meinel
Update output of --profile-imports to understand from foo import bar time
131
    if fromlist:
132
        extra += ' [%s]' % (', '.join(map(str, fromlist)),)
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
133
    frame_lineno = frame.f_lineno
134
2063.4.3 by John Arbash Meinel
Update profile imports to be aware of the new compiler
135
    this = stack_add(extra + name, frame_name, frame_lineno, scope_name)
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
136
3696.1.1 by John Arbash Meinel
Use the right timing function on win32
137
    tstart = _timer()
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
138
    try:
139
        # Do the import
140
        mod = _real_import(name, globals, locals, fromlist)
141
    finally:
3696.1.1 by John Arbash Meinel
Use the right timing function on win32
142
        tload = _timer()-tstart
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
143
        stack_finish(this, tload)
144
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
145
    return mod
146
147
148
_real_compile = sre._compile
149
1724.2.7 by John Arbash Meinel
It seems you cannot override __builtins__.__import__ in a sub-module.
150
def timed_compile(*args, **kwargs):
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
151
    """Log how long it takes to compile a regex"""
152
153
    # And who is requesting this?
154
    frame = sys._getframe(2)
155
    frame_name = frame.f_globals.get('__name__', '<unknown>')
2063.4.3 by John Arbash Meinel
Update profile imports to be aware of the new compiler
156
157
    extra = ''
158
    if frame_name.endswith('lazy_regex'):
159
        # If this was lazily compiled, we have 3 more frames to ignore
160
        extra = '[l] '
161
        frame = sys._getframe(5)
162
        frame_name = frame.f_globals.get('__name__', '<unknown>')
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
163
    frame_lineno = frame.f_lineno
2063.4.3 by John Arbash Meinel
Update profile imports to be aware of the new compiler
164
    this = stack_add(extra+repr(args[0]), frame_name, frame_lineno)
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
165
3696.1.1 by John Arbash Meinel
Use the right timing function on win32
166
    tstart = _timer()
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
167
    try:
168
        # Measure the compile time
169
        comp = _real_compile(*args, **kwargs)
170
    finally:
3696.1.1 by John Arbash Meinel
Use the right timing function on win32
171
        tcompile = _timer() - tstart
1724.2.8 by John Arbash Meinel
New --profile-imports output which puts parents before children.
172
        stack_finish(this, tcompile)
173
1724.2.4 by John Arbash Meinel
Move the custom importers into a separate module
174
    return comp
1724.2.14 by John Arbash Meinel
Refactor import stuff into separate functions. Update news
175
176
177
def install():
178
    """Install the hooks for measuring import and regex compile time."""
179
    __builtins__['__import__'] = timed_import
180
    sre._compile = timed_compile
181
182
183
def uninstall():
184
    """Remove the import and regex compile timing hooks."""
185
    __builtins__['__import__'] = _real_import
186
    sre._compile = _real_compile
187