← Back to branch summary

~bzr-pqm/bzr/bzr.dev

« back to all changes in this revision

Viewing changes to profile_imports.py

  • Committer: John Arbash Meinel
  • Date: 2006-06-18 02:21:57 UTC
  • mfrom: (1787 +trunk)
  • mto: This revision was merged to the branch mainline in revision 1794.
  • Revision ID: john@arbash-meinel.com-20060618022157-6e33aa9b67c25e4f
[merge] bzr.dev 1787

Show diffs side-by-side

added added

removed removed

Lines of Context:
profile_imports.py
1
1
# Copyright (C) 2006 by Canonical Ltd
2
 
# Written by John Arbash Meinel <john@arbash-meinel.com>
3
2
#
4
3
# This program is free software; you can redistribute it and/or modify
5
4
# it under the terms of the GNU General Public License as published by
15
14
# along with this program; if not, write to the Free Software
16
15
# Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
17
16
 
18
 
"""A custom importer and regex compiler which logs time spent."""
 
17
"""A custom importer and regex compiler which logs time."""
19
18
 
20
 
import sre
 
19
import os
21
20
import sys
22
21
import time
23
 
 
24
 
 
25
 
_parent_stack = []
26
 
_total_stack = {}
27
 
_info = {}
28
 
_cur_id = 0
29
 
 
30
 
 
31
 
def stack_add(name, frame_name, frame_lineno, scope_name=None):
32
 
    """Start a new record on the stack"""
33
 
    global _cur_id
34
 
    _cur_id += 1
35
 
    this_stack = (_cur_id, name)
36
 
 
37
 
    if _parent_stack:
38
 
        _total_stack[_parent_stack[-1]].append(this_stack)
39
 
    _total_stack[this_stack] = []
40
 
    _parent_stack.append(this_stack)
41
 
    _info[this_stack] = [len(_parent_stack)-1, frame_name, frame_lineno, scope_name]
42
 
 
43
 
    return this_stack
44
 
 
45
 
 
46
 
def stack_finish(this, cost):
47
 
    """Finish a given entry, and record its cost in time"""
48
 
    global _parent_stack
49
 
 
50
 
    assert _parent_stack[-1] == this, \
51
 
        'import stack does not end with this %s: %s' % (this, _parent_stack)
52
 
    _parent_stack.pop()
53
 
    _info[this].append(cost)
54
 
 
55
 
 
56
 
def log_stack_info(out_file, sorted=True, hide_fast=True):
57
 
    # Find all of the roots with import = 0
58
 
    out_file.write(' cum  inline name\t\t\t\t\t\tframe\n')
59
 
    todo = [(value[-1], key) for key,value in _info.iteritems() if value[0] == 0]
60
 
 
61
 
    if sorted:
62
 
        todo.sort()
63
 
 
64
 
    while todo:
65
 
        cum_time, cur = todo.pop()
66
 
        children = _total_stack[cur]
67
 
 
68
 
        c_times = []
69
 
 
70
 
        info = _info[cur]
71
 
        if hide_fast and info[-1] < 0.0001:
72
 
            continue
73
 
 
74
 
        # Compute the module time by removing the children times
75
 
        mod_time = info[-1]
76
 
        for child in children:
77
 
            c_info = _info[child]
78
 
            mod_time -= c_info[-1]
79
 
            c_times.append((c_info[-1], child))
80
 
 
81
 
        # indent, cum_time, mod_time, name,
82
 
        # scope_name, frame_name, frame_lineno
83
 
        out_file.write('%5.1f %5.1f %s %-35s\t@ %s:%d\n'
84
 
            % (info[-1]*1000., mod_time*1000., '+'*info[0], 
85
 
               cur[1][:40], info[1], info[2]))
86
 
 
87
 
        if sorted:
88
 
            c_times.sort()
89
 
        else:
90
 
            c_times.reverse()
91
 
        todo.extend(c_times)
92
 
 
 
22
import sre
 
23
 
 
24
 
 
25
_import_logfile = sys.stderr
 
26
_compile_logfile = sys.stderr
93
27
 
94
28
_real_import = __import__
95
29
 
96
 
def timed_import(name, globals, locals, fromlist):
 
30
def _custom_import(name, globals, locals, fromlist):
97
31
    """Wrap around standard importer to log import time"""
 
32
    if _import_logfile is None:
 
33
        return _real_import(name, globals, locals, fromlist)
98
34
 
99
35
    scope_name = globals.get('__name__', None)
100
36
    if scope_name is None:
110
46
        loc = scope_name.find('python2.4')
111
47
        if loc != -1:
112
48
            scope_name = scope_name[loc:]
 
49
                
 
50
    # Do the import
 
51
    tstart = time.time()
 
52
    mod = _real_import(name, globals, locals, fromlist)
 
53
    tload = time.time()-tstart
113
54
 
114
55
    # Figure out the frame that is doing the importing
115
56
    frame = sys._getframe(1)
124
65
        frame_name = frame.f_globals.get('__name__', '<unknown>')
125
66
    frame_lineno = frame.f_lineno
126
67
 
127
 
    this = stack_add(name+extra, frame_name, frame_lineno, scope_name)
128
 
 
129
 
    tstart = time.time()
130
 
    try:
131
 
        # Do the import
132
 
        mod = _real_import(name, globals, locals, fromlist)
133
 
    finally:
134
 
        tload = time.time()-tstart
135
 
        stack_finish(this, tload)
136
 
 
 
68
    # Log the import
 
69
    _import_logfile.write('%3.0fms %-24s\tfor %-24s\t@ %s:%d%s\n' 
 
70
        % ((time.time()-tstart)*1000, name, scope_name,
 
71
            frame_name, frame_lineno, extra))
 
72
 
 
73
    # If the import took a long time, log the stack that generated
 
74
    # this import. Especially necessary for demandloaded code
 
75
    if tload > 0.01:
 
76
        stack = []
 
77
        for fnum in range(cur_frame+1, cur_frame+10):
 
78
            try:
 
79
                f = sys._getframe(fnum)
 
80
            except ValueError:
 
81
                break
 
82
            stack.append('%s:%i' 
 
83
                    % (f.f_globals.get('__name__', '<unknown>'),
 
84
                        f.f_lineno)
 
85
                    )
 
86
        if stack:
 
87
            _import_logfile.write('\t' + ' '.join(stack) + '\n')
137
88
    return mod
138
89
 
139
90
 
140
91
_real_compile = sre._compile
141
92
 
142
 
def timed_compile(*args, **kwargs):
 
93
def _custom_compile(*args, **kwargs):
143
94
    """Log how long it takes to compile a regex"""
 
95
    if _compile_logfile is None:
 
96
        return _real_compile(*args, **kwargs)
144
97
 
 
98
    # Measure the compile time
 
99
    tstart = time.time()
 
100
    comp = _real_compile(*args, **kwargs)
 
101
    
145
102
    # And who is requesting this?
146
103
    frame = sys._getframe(2)
147
104
    frame_name = frame.f_globals.get('__name__', '<unknown>')
148
105
    frame_lineno = frame.f_lineno
149
 
 
150
 
    this = stack_add(repr(args[0]), frame_name, frame_lineno)
151
 
 
152
 
    tstart = time.time()
153
 
    try:
154
 
        # Measure the compile time
155
 
        comp = _real_compile(*args, **kwargs)
156
 
    finally:
157
 
        tcompile = time.time() - tstart
158
 
        stack_finish(this, tcompile)
159
 
 
 
106
    _compile_logfile.write('%3.0fms %-40r\t@ %s:%d\n'
 
107
        % ((time.time()-tstart)*1000, args[0][:40], 
 
108
            frame_name, frame_lineno))
160
109
    return comp
161
110
 
162
 
 
163
 
def install():
164
 
    """Install the hooks for measuring import and regex compile time."""
165
 
    __builtins__['__import__'] = timed_import
166
 
    sre._compile = timed_compile
167
 
 
168
 
 
169
 
def uninstall():
170
 
    """Remove the import and regex compile timing hooks."""
171
 
    __builtins__['__import__'] = _real_import
172
 
    sre._compile = _real_compile
173
 
 
 
111
__builtins__.__import__ = _custom_import
 
112
sre._compile = _custom_compile