| # (c) 2005 Ian Bicking and contributors; written for Paste (http://pythonpaste.org) |
| # Licensed under the MIT license: http://www.opensource.org/licenses/mit-license.php |
| """ |
| Middleware that profiles the request and displays profiling |
| information at the bottom of each page. |
| """ |
| |
| |
| import sys |
| import os |
| import hotshot |
| import hotshot.stats |
| import threading |
| import cgi |
| import six |
| import time |
| from cStringIO import StringIO |
| from paste import response |
| |
| __all__ = ['ProfileMiddleware', 'profile_decorator'] |
| |
| class ProfileMiddleware(object): |
| |
| """ |
| Middleware that profiles all requests. |
| |
| All HTML pages will have profiling information appended to them. |
| The data is isolated to that single request, and does not include |
| data from previous requests. |
| |
| This uses the ``hotshot`` module, which affects performance of the |
| application. It also runs in a single-threaded mode, so it is |
| only usable in development environments. |
| """ |
| |
| style = ('clear: both; background-color: #ff9; color: #000; ' |
| 'border: 2px solid #000; padding: 5px;') |
| |
| def __init__(self, app, global_conf=None, |
| log_filename='profile.log.tmp', |
| limit=40): |
| self.app = app |
| self.lock = threading.Lock() |
| self.log_filename = log_filename |
| self.limit = limit |
| |
| def __call__(self, environ, start_response): |
| catch_response = [] |
| body = [] |
| def replace_start_response(status, headers, exc_info=None): |
| catch_response.extend([status, headers]) |
| start_response(status, headers, exc_info) |
| return body.append |
| def run_app(): |
| app_iter = self.app(environ, replace_start_response) |
| try: |
| body.extend(app_iter) |
| finally: |
| if hasattr(app_iter, 'close'): |
| app_iter.close() |
| self.lock.acquire() |
| try: |
| prof = hotshot.Profile(self.log_filename) |
| prof.addinfo('URL', environ.get('PATH_INFO', '')) |
| try: |
| prof.runcall(run_app) |
| finally: |
| prof.close() |
| body = ''.join(body) |
| headers = catch_response[1] |
| content_type = response.header_value(headers, 'content-type') |
| if content_type is None or not content_type.startswith('text/html'): |
| # We can't add info to non-HTML output |
| return [body] |
| stats = hotshot.stats.load(self.log_filename) |
| stats.strip_dirs() |
| stats.sort_stats('time', 'calls') |
| output = capture_output(stats.print_stats, self.limit) |
| output_callers = capture_output( |
| stats.print_callers, self.limit) |
| body += '<pre style="%s">%s\n%s</pre>' % ( |
| self.style, cgi.escape(output), cgi.escape(output_callers)) |
| return [body] |
| finally: |
| self.lock.release() |
| |
| def capture_output(func, *args, **kw): |
| # Not threadsafe! (that's okay when ProfileMiddleware uses it, |
| # though, since it synchronizes itself.) |
| out = StringIO() |
| old_stdout = sys.stdout |
| sys.stdout = out |
| try: |
| func(*args, **kw) |
| finally: |
| sys.stdout = old_stdout |
| return out.getvalue() |
| |
| def profile_decorator(**options): |
| |
| """ |
| Profile a single function call. |
| |
| Used around a function, like:: |
| |
| @profile_decorator(options...) |
| def ... |
| |
| All calls to the function will be profiled. The options are |
| all keywords, and are: |
| |
| log_file: |
| The filename to log to (or ``'stdout'`` or ``'stderr'``). |
| Default: stderr. |
| display_limit: |
| Only show the top N items, default: 20. |
| sort_stats: |
| A list of string-attributes to sort on. Default |
| ``('time', 'calls')``. |
| strip_dirs: |
| Strip directories/module names from files? Default True. |
| add_info: |
| If given, this info will be added to the report (for your |
| own tracking). Default: none. |
| log_filename: |
| The temporary filename to log profiling data to. Default; |
| ``./profile_data.log.tmp`` |
| no_profile: |
| If true, then don't actually profile anything. Useful for |
| conditional profiling. |
| """ |
| |
| if options.get('no_profile'): |
| def decorator(func): |
| return func |
| return decorator |
| def decorator(func): |
| def replacement(*args, **kw): |
| return DecoratedProfile(func, **options)(*args, **kw) |
| return replacement |
| return decorator |
| |
| class DecoratedProfile(object): |
| |
| lock = threading.Lock() |
| |
| def __init__(self, func, **options): |
| self.func = func |
| self.options = options |
| |
| def __call__(self, *args, **kw): |
| self.lock.acquire() |
| try: |
| return self.profile(self.func, *args, **kw) |
| finally: |
| self.lock.release() |
| |
| def profile(self, func, *args, **kw): |
| ops = self.options |
| prof_filename = ops.get('log_filename', 'profile_data.log.tmp') |
| prof = hotshot.Profile(prof_filename) |
| prof.addinfo('Function Call', |
| self.format_function(func, *args, **kw)) |
| if ops.get('add_info'): |
| prof.addinfo('Extra info', ops['add_info']) |
| exc_info = None |
| try: |
| start_time = time.time() |
| try: |
| result = prof.runcall(func, *args, **kw) |
| except: |
| exc_info = sys.exc_info() |
| end_time = time.time() |
| finally: |
| prof.close() |
| stats = hotshot.stats.load(prof_filename) |
| os.unlink(prof_filename) |
| if ops.get('strip_dirs', True): |
| stats.strip_dirs() |
| stats.sort_stats(*ops.get('sort_stats', ('time', 'calls'))) |
| display_limit = ops.get('display_limit', 20) |
| output = capture_output(stats.print_stats, display_limit) |
| output_callers = capture_output( |
| stats.print_callers, display_limit) |
| output_file = ops.get('log_file') |
| if output_file in (None, 'stderr'): |
| f = sys.stderr |
| elif output_file in ('-', 'stdout'): |
| f = sys.stdout |
| else: |
| f = open(output_file, 'a') |
| f.write('\n%s\n' % ('-'*60)) |
| f.write('Date: %s\n' % time.strftime('%c')) |
| f.write('Function call: %s\n' |
| % self.format_function(func, *args, **kw)) |
| f.write('Wall time: %0.2f seconds\n' |
| % (end_time - start_time)) |
| f.write(output) |
| f.write(output_callers) |
| if output_file not in (None, '-', 'stdout', 'stderr'): |
| f.close() |
| if exc_info: |
| # We captured an exception earlier, now we re-raise it |
| six.reraise(exc_info[0], exc_info[1], exc_info[2]) |
| return result |
| |
| def format_function(self, func, *args, **kw): |
| args = map(repr, args) |
| args.extend( |
| ['%s=%r' % (k, v) for k, v in kw.items()]) |
| return '%s(%s)' % (func.__name__, ', '.join(args)) |
| |
| |
| def make_profile_middleware( |
| app, global_conf, |
| log_filename='profile.log.tmp', |
| limit=40): |
| """ |
| Wrap the application in a component that will profile each |
| request. The profiling data is then appended to the output |
| of each page. |
| |
| Note that this serializes all requests (i.e., removing |
| concurrency). Therefore never use this in production. |
| """ |
| limit = int(limit) |
| return ProfileMiddleware( |
| app, log_filename=log_filename, limit=limit) |
