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
20import re
21import sys
22import time
23
24
25_parent_stack = []
26_total_stack = {}
27_info = {}
28_cur_id = 0
29_timer = time.time
30if sys.platform == 'win32':
31    _timer = time.clock
32
33
34def 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,
45                         scope_name]
46
47    return this_stack
48
49
50def stack_finish(this, cost):
51    """Finish a given entry, and record its cost in time"""
52    global _parent_stack
53
54    assert _parent_stack[-1] == this, \
55        'import stack does not end with this %s: %s' % (this, _parent_stack)
56    _parent_stack.pop()
57    _info[this].append(cost)
58
59
60def log_stack_info(out_file, sorted=True, hide_fast=True):
61    # Find all of the roots with import = 0
62    out_file.write(
63        '%5s %5s %-40s @ %s:%s\n'
64        % ('cum', 'local', 'name', 'file', 'line'))
65    todo = [(value[-1], key) for key, value in _info.items() 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(
90            '%5.1f %5.1f %-40s @ %s:%d\n' % (
91                info[-1] * 1000., mod_time * 1000.,
92                ('+' * info[0] + cur[1]), 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
103def timed_import(name, globals=None, locals=None, fromlist=None, level=0):
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 has different default between Python 2 and 3, but codebase
109    if globals is None:
110        # can't determine the scope name afaics; we could peek up the stack to
111        # see where this is being called from, but it should be a rare case.
112        scope_name = None
113    else:
114        scope_name = globals.get('__name__', None)
115        if scope_name is None:
116            scope_name = globals.get('__file__', None)
117        if scope_name is None:
118            scope_name = globals.keys()
119        else:
120            # Trim out paths before breezy
121            loc = scope_name.find('breezy')
122            if loc != -1:
123                scope_name = scope_name[loc:]
124
125    # Figure out the frame that is doing the importing
126    frame = sys._getframe(1)
127    frame_name = frame.f_globals.get('__name__', '<unknown>')
128    extra = ''
129    if frame_name.endswith('demandload'):
130        # If this was demandloaded, we have 3 frames to ignore
131        extra = '(demandload) '
132        frame = sys._getframe(4)
133        frame_name = frame.f_globals.get('__name__', '<unknown>')
134    elif frame_name.endswith('lazy_import'):
135        # If this was lazily imported, we have 3 frames to ignore
136        extra = '[l] '
137        frame = sys._getframe(4)
138        frame_name = frame.f_globals.get('__name__', '<unknown>')
139    if fromlist:
140        extra += ' [%s]' % (', '.join(map(str, fromlist)),)
141    frame_lineno = frame.f_lineno
142
143    this = stack_add(extra + name, frame_name, frame_lineno, scope_name)
144
145    tstart = _timer()
146    try:
147        # Do the import
148        return _real_import(name, globals, locals, fromlist, level=level)
149    finally:
150        tload = _timer() - tstart
151        stack_finish(this, tload)
152
153
154def _repr_regexp(pattern, max_len=30):
155    """Present regexp pattern for logging, truncating if over max_len."""
156    if len(pattern) > max_len:
157        return repr(pattern[:max_len - 3]) + "..."
158    return repr(pattern)
159
160
161_real_compile = re._compile
162
163
164def 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_regexp(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
191def install():
192    """Install the hooks for measuring import and regex compile time."""
193    __builtins__['__import__'] = timed_import
194    re._compile = timed_compile
195
196
197def uninstall():
198    """Remove the import and regex compile timing hooks."""
199    __builtins__['__import__'] = _real_import
200    re._compile = _real_compile
201