← 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 04:16:37 UTC
  • mto: This revision was merged to the branch mainline in revision 1794.
  • Revision ID: john@arbash-meinel.com-20060618041637-2e95a1469edd8c72
New --profile-imports output which puts parents before children.

Show diffs side-by-side

added added

removed removed

Lines of Context:
profile_imports.py
17
17
"""A custom importer and regex compiler which logs time spent."""
18
18
 
19
19
import os
 
20
import pprint
20
21
import sre
21
22
import sys
22
23
import time
25
26
import_logfile = sys.stderr
26
27
compile_logfile = sys.stderr
27
28
 
 
29
 
 
30
_parent_stack = []
 
31
_total_stack = {}
 
32
_info = {}
 
33
_cur_id = 0
 
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
    if  _parent_stack[-1] != this:
 
56
        # This should only happen if there is a bug
 
57
        # (used to happen if an import failed)
 
58
        if this not in _parent_stack:
 
59
            import_logfile.write('could not find %s in callstat: %s\n'
 
60
                                % (this, pprint.pformat(_parent_stack)))
 
61
        else:
 
62
            idx = _parent_stack.index(this)
 
63
            import_logfile.write('stripping off extra children: %s\n'
 
64
                                % (_parent_stack[idx:],))
 
65
            _parent_stack = _parent_stack[:idx]
 
66
    else:
 
67
        _parent_stack.pop()
 
68
    _info[this].append(cost)
 
69
 
 
70
 
 
71
def log_stack_info(out_file):
 
72
    # Find all of the roots with import = 0
 
73
    out_file.write('cum_time\tmod_time\tname\tscope\tframe\n')
 
74
    todo = [key for key,value in _info.iteritems() if value[0] == 0]
 
75
 
 
76
    while todo:
 
77
        cur = todo.pop()
 
78
        children = _total_stack[cur]
 
79
 
 
80
        info = _info[cur]
 
81
        # Compute the module time by removing the children times
 
82
        mod_time = info[-1]
 
83
        for child in children:
 
84
            c_info = _info[child]
 
85
            mod_time -= c_info[-1]
 
86
 
 
87
        scope_name = info[3]
 
88
        if scope_name is None:
 
89
            txt = '%-48s' % (cur[1],)
 
90
        else:
 
91
            txt = '%-24s\tfor %-24s' % (cur[1], scope_name)
 
92
        # indent, cum_time, mod_time, name,
 
93
        # scope_name, frame_name, frame_lineno
 
94
        out_file.write('%s%5.1f %5.1f %s\t@ %s:%d\n'
 
95
            % (info[0]*'+', info[-1]*1000., mod_time, txt, info[1], info[2]))
 
96
 
 
97
        todo.extend(reversed(children))
 
98
 
 
99
 
28
100
_real_import = __import__
29
101
 
30
102
def timed_import(name, globals, locals, fromlist):
31
103
    """Wrap around standard importer to log import time"""
 
104
 
32
105
    if import_logfile is None:
33
106
        return _real_import(name, globals, locals, fromlist)
34
107
 
46
119
        loc = scope_name.find('python2.4')
47
120
        if loc != -1:
48
121
            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
54
122
 
55
123
    # Figure out the frame that is doing the importing
56
124
    frame = sys._getframe(1)
65
133
        frame_name = frame.f_globals.get('__name__', '<unknown>')
66
134
    frame_lineno = frame.f_lineno
67
135
 
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')
 
136
    this = stack_add(name+extra, frame_name, frame_lineno, scope_name)
 
137
 
 
138
    tstart = time.time()
 
139
    try:
 
140
        # Do the import
 
141
        mod = _real_import(name, globals, locals, fromlist)
 
142
    finally:
 
143
        tload = time.time()-tstart
 
144
        stack_finish(this, tload)
 
145
 
88
146
    return mod
89
147
 
90
148
 
95
153
    if compile_logfile is None:
96
154
        return _real_compile(*args, **kwargs)
97
155
 
98
 
    # Measure the compile time
99
 
    tstart = time.time()
100
 
    comp = _real_compile(*args, **kwargs)
101
 
    
102
156
    # And who is requesting this?
103
157
    frame = sys._getframe(2)
104
158
    frame_name = frame.f_globals.get('__name__', '<unknown>')
105
159
    frame_lineno = frame.f_lineno
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
 
 
161
    this = stack_add(repr(args[0][:40]), frame_name, frame_lineno)
 
162
 
 
163
    tstart = time.time()
 
164
    try:
 
165
        # Measure the compile time
 
166
        comp = _real_compile(*args, **kwargs)
 
167
    finally:
 
168
        tcompile = time.time() - tstart
 
169
        stack_finish(this, tcompile)
 
170
 
109
171
    return comp