| 1 | # (c) 2005 Ian Bicking and contributors; written for Paste (http://pythonpaste.org) |
|---|
| 2 | # Licensed under the MIT license: http://www.opensource.org/licenses/mit-license.php |
|---|
| 3 | """ |
|---|
| 4 | Middleware that profiles the request and displays profiling |
|---|
| 5 | information at the bottom of each page. |
|---|
| 6 | """ |
|---|
| 7 | |
|---|
| 8 | |
|---|
| 9 | import sys |
|---|
| 10 | import os |
|---|
| 11 | import hotshot |
|---|
| 12 | import hotshot.stats |
|---|
| 13 | import threading |
|---|
| 14 | import cgi |
|---|
| 15 | import time |
|---|
| 16 | from cStringIO import StringIO |
|---|
| 17 | from paste import response |
|---|
| 18 | |
|---|
| 19 | __all__ = ['ProfileMiddleware', 'profile_decorator'] |
|---|
| 20 | |
|---|
| 21 | class ProfileMiddleware(object): |
|---|
| 22 | |
|---|
| 23 | """ |
|---|
| 24 | Middleware that profiles all requests. |
|---|
| 25 | |
|---|
| 26 | All HTML pages will have profiling information appended to them. |
|---|
| 27 | The data is isolated to that single request, and does not include |
|---|
| 28 | data from previous requests. |
|---|
| 29 | |
|---|
| 30 | This uses the ``hotshot`` module, which affects performance of the |
|---|
| 31 | application. It also runs in a single-threaded mode, so it is |
|---|
| 32 | only usable in development environments. |
|---|
| 33 | """ |
|---|
| 34 | |
|---|
| 35 | style = ('background-color: #ff9; color: #000; ' |
|---|
| 36 | 'border: 2px solid #000; padding: 5px;') |
|---|
| 37 | |
|---|
| 38 | def __init__(self, app, global_conf=None, |
|---|
| 39 | log_filename='profile.log.tmp', |
|---|
| 40 | limit=40): |
|---|
| 41 | self.app = app |
|---|
| 42 | self.lock = threading.Lock() |
|---|
| 43 | self.log_filename = log_filename |
|---|
| 44 | self.limit = limit |
|---|
| 45 | |
|---|
| 46 | def __call__(self, environ, start_response): |
|---|
| 47 | catch_response = [] |
|---|
| 48 | body = [] |
|---|
| 49 | def replace_start_response(status, headers, exc_info=None): |
|---|
| 50 | catch_response.extend([status, headers]) |
|---|
| 51 | start_response(status, headers, exc_info) |
|---|
| 52 | return body.append |
|---|
| 53 | def run_app(): |
|---|
| 54 | app_iter = self.app(environ, replace_start_response) |
|---|
| 55 | try: |
|---|
| 56 | body.extend(app_iter) |
|---|
| 57 | finally: |
|---|
| 58 | if hasattr(app_iter, 'close'): |
|---|
| 59 | app_iter.close() |
|---|
| 60 | self.lock.acquire() |
|---|
| 61 | try: |
|---|
| 62 | prof = hotshot.Profile(self.log_filename) |
|---|
| 63 | prof.addinfo('URL', environ.get('PATH_INFO', '')) |
|---|
| 64 | try: |
|---|
| 65 | prof.runcall(run_app) |
|---|
| 66 | finally: |
|---|
| 67 | prof.close() |
|---|
| 68 | body = ''.join(body) |
|---|
| 69 | headers = catch_response[1] |
|---|
| 70 | content_type = response.header_value(headers, 'content-type') |
|---|
| 71 | if not content_type.startswith('text/html'): |
|---|
| 72 | # We can't add info to non-HTML output |
|---|
| 73 | return [body] |
|---|
| 74 | stats = hotshot.stats.load(self.log_filename) |
|---|
| 75 | stats.strip_dirs() |
|---|
| 76 | stats.sort_stats('time', 'calls') |
|---|
| 77 | output = capture_output(stats.print_stats, self.limit) |
|---|
| 78 | output_callers = capture_output( |
|---|
| 79 | stats.print_callers, self.limit) |
|---|
| 80 | body += '<pre style="%s">%s\n%s</pre>' % ( |
|---|
| 81 | self.style, cgi.escape(output), cgi.escape(output_callers)) |
|---|
| 82 | return [body] |
|---|
| 83 | finally: |
|---|
| 84 | self.lock.release() |
|---|
| 85 | |
|---|
| 86 | def capture_output(func, *args, **kw): |
|---|
| 87 | # Not threadsafe! (that's okay when ProfileMiddleware uses it, |
|---|
| 88 | # though, since it synchronizes itself.) |
|---|
| 89 | out = StringIO() |
|---|
| 90 | old_stdout = sys.stdout |
|---|
| 91 | sys.stdout = out |
|---|
| 92 | try: |
|---|
| 93 | func(*args, **kw) |
|---|
| 94 | finally: |
|---|
| 95 | sys.stdout = old_stdout |
|---|
| 96 | return out.getvalue() |
|---|
| 97 | |
|---|
| 98 | def profile_decorator(**options): |
|---|
| 99 | |
|---|
| 100 | """ |
|---|
| 101 | Profile a single function call. |
|---|
| 102 | |
|---|
| 103 | Used around a function, like:: |
|---|
| 104 | |
|---|
| 105 | @profile_decorator(options...) |
|---|
| 106 | def ... |
|---|
| 107 | |
|---|
| 108 | All calls to the function will be profiled. The options are |
|---|
| 109 | all keywords, and are: |
|---|
| 110 | |
|---|
| 111 | log_file: |
|---|
| 112 | The filename to log to (or ``'stdout'`` or ``'stderr'``). |
|---|
| 113 | Default: stderr. |
|---|
| 114 | display_limit: |
|---|
| 115 | Only show the top N items, default: 20. |
|---|
| 116 | sort_stats: |
|---|
| 117 | A list of string-attributes to sort on. Default |
|---|
| 118 | ``('time', 'calls')``. |
|---|
| 119 | strip_dirs: |
|---|
| 120 | Strip directories/module names from files? Default True. |
|---|
| 121 | add_info: |
|---|
| 122 | If given, this info will be added to the report (for your |
|---|
| 123 | own tracking). Default: none. |
|---|
| 124 | log_filename: |
|---|
| 125 | The temporary filename to log profiling data to. Default; |
|---|
| 126 | ``./profile_data.log.tmp`` |
|---|
| 127 | no_profile: |
|---|
| 128 | If true, then don't actually profile anything. Useful for |
|---|
| 129 | conditional profiling. |
|---|
| 130 | """ |
|---|
| 131 | |
|---|
| 132 | if options.get('no_profile'): |
|---|
| 133 | def decorator(func): |
|---|
| 134 | return func |
|---|
| 135 | return decorator |
|---|
| 136 | def decorator(func): |
|---|
| 137 | def replacement(*args, **kw): |
|---|
| 138 | return DecoratedProfile(func, **options)(*args, **kw) |
|---|
| 139 | return replacement |
|---|
| 140 | return decorator |
|---|
| 141 | |
|---|
| 142 | class DecoratedProfile(object): |
|---|
| 143 | |
|---|
| 144 | lock = threading.Lock() |
|---|
| 145 | |
|---|
| 146 | def __init__(self, func, **options): |
|---|
| 147 | self.func = func |
|---|
| 148 | self.options = options |
|---|
| 149 | |
|---|
| 150 | def __call__(self, *args, **kw): |
|---|
| 151 | self.lock.acquire() |
|---|
| 152 | try: |
|---|
| 153 | return self.profile(self.func, *args, **kw) |
|---|
| 154 | finally: |
|---|
| 155 | self.lock.release() |
|---|
| 156 | |
|---|
| 157 | def profile(self, func, *args, **kw): |
|---|
| 158 | ops = self.options |
|---|
| 159 | prof_filename = ops.get('log_filename', 'profile_data.log.tmp') |
|---|
| 160 | prof = hotshot.Profile(prof_filename) |
|---|
| 161 | prof.addinfo('Function Call', |
|---|
| 162 | self.format_function(func, *args, **kw)) |
|---|
| 163 | if ops.get('add_info'): |
|---|
| 164 | prof.addinfo('Extra info', ops['add_info']) |
|---|
| 165 | exc_info = None |
|---|
| 166 | try: |
|---|
| 167 | start_time = time.time() |
|---|
| 168 | try: |
|---|
| 169 | result = prof.runcall(func, *args, **kw) |
|---|
| 170 | except: |
|---|
| 171 | exc_info = sys.exc_info() |
|---|
| 172 | end_time = time.time() |
|---|
| 173 | finally: |
|---|
| 174 | prof.close() |
|---|
| 175 | stats = hotshot.stats.load(prof_filename) |
|---|
| 176 | os.unlink(prof_filename) |
|---|
| 177 | if ops.get('strip_dirs', True): |
|---|
| 178 | stats.strip_dirs() |
|---|
| 179 | stats.sort_stats(*ops.get('sort_stats', ('time', 'calls'))) |
|---|
| 180 | display_limit = ops.get('display_limit', 20) |
|---|
| 181 | output = capture_output(stats.print_stats, display_limit) |
|---|
| 182 | output_callers = capture_output( |
|---|
| 183 | stats.print_callers, display_limit) |
|---|
| 184 | output_file = ops.get('log_file') |
|---|
| 185 | if output_file in (None, 'stderr'): |
|---|
| 186 | f = sys.stderr |
|---|
| 187 | elif output_file in ('-', 'stdout'): |
|---|
| 188 | f = sys.stdout |
|---|
| 189 | else: |
|---|
| 190 | f = open(output_file, 'a') |
|---|
| 191 | f.write('\n%s\n' % ('-'*60)) |
|---|
| 192 | f.write('Date: %s\n' % time.strftime('%c')) |
|---|
| 193 | f.write('Function call: %s\n' |
|---|
| 194 | % self.format_function(func, *args, **kw)) |
|---|
| 195 | f.write('Wall time: %0.2f seconds\n' |
|---|
| 196 | % (end_time - start_time)) |
|---|
| 197 | f.write(output) |
|---|
| 198 | f.write(output_callers) |
|---|
| 199 | if output_file not in (None, '-', 'stdout', 'stderr'): |
|---|
| 200 | f.close() |
|---|
| 201 | if exc_info: |
|---|
| 202 | # We captured an exception earlier, now we re-raise it |
|---|
| 203 | raise exc_info[0], exc_info[1], exc_info[2] |
|---|
| 204 | return result |
|---|
| 205 | |
|---|
| 206 | def format_function(self, func, *args, **kw): |
|---|
| 207 | args = map(repr, args) |
|---|
| 208 | args.extend( |
|---|
| 209 | ['%s=%r' % (k, v) for k, v in kw.items()]) |
|---|
| 210 | return '%s(%s)' % (func.__name__, ', '.join(args)) |
|---|
| 211 | |
|---|
| 212 | |
|---|
| 213 | def make_profile_middleware( |
|---|
| 214 | app, global_conf, |
|---|
| 215 | log_filename='profile.log.tmp', |
|---|
| 216 | limit=40): |
|---|
| 217 | """ |
|---|
| 218 | Wrap the application in a component that will profile each |
|---|
| 219 | request. The profiling data is then appended to the output |
|---|
| 220 | of each page. |
|---|
| 221 | |
|---|
| 222 | Note that this serializes all requests (i.e., removing |
|---|
| 223 | concurrency). Therefore never use this in production. |
|---|
| 224 | """ |
|---|
| 225 | limit = int(limit) |
|---|
| 226 | return ProfileMiddleware( |
|---|
| 227 | app, log_filename=log_filename, limit=limit) |
|---|