From 3f578cf684b7e3b9a20d9c777950c28c44db074a Mon Sep 17 00:00:00 2001 From: David Cramer Date: Thu, 31 Mar 2011 11:42:23 -0700 Subject: Add utilities to inject and monitor functions. Change DB tracking to use new injection method on BaseDatabaseWrapper.cursor --- debug_toolbar/utils/tracking/__init__.py | 90 ++++++++++++++++++++++++++++++++ debug_toolbar/utils/tracking/db.py | 85 ++++++++++++++++++++++++++++++ 2 files changed, 175 insertions(+) create mode 100644 debug_toolbar/utils/tracking/__init__.py create mode 100644 debug_toolbar/utils/tracking/db.py (limited to 'debug_toolbar/utils/tracking') diff --git a/debug_toolbar/utils/tracking/__init__.py b/debug_toolbar/utils/tracking/__init__.py new file mode 100644 index 0000000..db8ff18 --- /dev/null +++ b/debug_toolbar/utils/tracking/__init__.py @@ -0,0 +1,90 @@ +import logging +import time +import types + +def post_dispatch(func): + def wrapped(callback): + register_hook(func, 'after', callback) + return callback + return wrapped + +def pre_dispatch(func): + def wrapped(callback): + register_hook(func, 'before', callback) + return callback + return wrapped + +def replace_call(func): + def inner(callback): + def wrapped(*args, **kwargs): + return callback(func, *args, **kwargs) + + actual = getattr(func, '__wrapped__', func) + wrapped.__wrapped__ = actual + wrapped.__doc__ = getattr(actual, '__doc__', None) + wrapped.__name__ = actual.__name__ + + _replace_function(func, wrapped) + return wrapped + return inner + +def fire_hook(hook, sender, **kwargs): + try: + for callback in callbacks[hook].get(id(sender), []): + callback(sender=sender, **kwargs) + except Exception, e: + # Log the exception, dont mess w/ the underlying function + logging.exception(e) + +def _replace_function(func, wrapped): + if isinstance(func, types.FunctionType): + if func.__module__ == '__builtin__': + # oh shit + __builtins__[func] = wrapped + else: + module = __import__(func.__module__, {}, {}, [func.__module__], 0) + setattr(module, func.__name__, wrapped) + elif getattr(func, 'im_self', None): + # TODO: classmethods + raise NotImplementedError + elif hasattr(func, 'im_class'): + # for unbound methods + setattr(func.im_class, func.__name__, wrapped) + else: + raise NotImplementedError + +callbacks = { + 'before': {}, + 'after': {}, +} + +def register_hook(func, hook, callback): + """ + def myhook(sender, args, kwargs): + print func, "executed + print "args:", args + print "kwargs:", kwargs + register_hook(BaseDatabaseWrapper.cursor, 'before', myhook) + """ + + assert hook in ('before', 'after') + + def wrapped(*args, **kwargs): + start = time.time() + fire_hook('before', sender=wrapped.__wrapped__, args=args, kwargs=kwargs, + start=start) + result = wrapped.__wrapped__(*args, **kwargs) + stop = time.time() + fire_hook('after', sender=wrapped.__wrapped__, args=args, kwargs=kwargs, + result=result, start=start, stop=stop) + actual = getattr(func, '__wrapped__', func) + wrapped.__wrapped__ = actual + wrapped.__doc__ = getattr(actual, '__doc__', None) + wrapped.__name__ = actual.__name__ + + id_ = id(actual) + if id_ not in callbacks[hook]: + callbacks[hook][id_] = [] + callbacks[hook][id_].append(callback) + + _replace_function(func, wrapped) \ No newline at end of file diff --git a/debug_toolbar/utils/tracking/db.py b/debug_toolbar/utils/tracking/db.py new file mode 100644 index 0000000..4c9ee53 --- /dev/null +++ b/debug_toolbar/utils/tracking/db.py @@ -0,0 +1,85 @@ +import sys +import traceback + +from datetime import datetime + +from django.conf import settings +from django.template import Node +from django.utils import simplejson +from django.utils.encoding import force_unicode +from django.utils.hashcompat import sha_constructor + +from debug_toolbar.utils import ms_from_timedelta, tidy_stacktrace, get_template_info + +# TODO:This should be set in the toolbar loader as a default and panels should +# get a copy of the toolbar object with access to its config dictionary +SQL_WARNING_THRESHOLD = getattr(settings, 'DEBUG_TOOLBAR_CONFIG', {}) \ + .get('SQL_WARNING_THRESHOLD', 500) + +class CursorWrapper(object): + """ + Wraps a cursor and logs queries. + """ + + def __init__(self, cursor, db, logger): + self.cursor = cursor + # Instance of a BaseDatabaseWrapper subclass + self.db = db + # logger must implement a ``record`` method + self.logger = logger + + def execute(self, sql, params=()): + start = datetime.now() + try: + return self.cursor.execute(sql, params) + finally: + stop = datetime.now() + duration = ms_from_timedelta(stop - start) + stacktrace = tidy_stacktrace(traceback.extract_stack()) + _params = '' + try: + _params = simplejson.dumps([force_unicode(x, strings_only=True) for x in params]) + except TypeError: + pass # object not JSON serializable + + template_info = None + cur_frame = sys._getframe().f_back + try: + while cur_frame is not None: + if cur_frame.f_code.co_name == 'render': + node = cur_frame.f_locals['self'] + if isinstance(node, Node): + template_info = get_template_info(node.source) + break + cur_frame = cur_frame.f_back + except: + pass + del cur_frame + + # We keep `sql` to maintain backwards compatibility + self.logger.record(**{ + 'alias': getattr(self, 'alias', 'default'), + 'sql': self.db.ops.last_executed_query(self.cursor, sql, params), + 'duration': duration, + 'raw_sql': sql, + 'params': _params, + 'hash': sha_constructor(settings.SECRET_KEY + sql + _params).hexdigest(), + 'stacktrace': stacktrace, + 'start_time': start, + 'stop_time': stop, + 'is_slow': (duration > SQL_WARNING_THRESHOLD), + 'is_select': sql.lower().strip().startswith('select'), + 'template_info': template_info, + }) + + def executemany(self, sql, param_list): + return self.cursor.executemany(sql, param_list) + + def __getattr__(self, attr): + if attr in self.__dict__: + return self.__dict__[attr] + else: + return getattr(self.cursor, attr) + + def __iter__(self): + return iter(self.cursor) \ No newline at end of file -- cgit v1.2.3 From 72271115974463f30a2f9f8755e42acc69e204c3 Mon Sep 17 00:00:00 2001 From: David Cramer Date: Tue, 5 Apr 2011 14:02:47 -0700 Subject: Add support for engine-per-query as well as pulling out psycopg2's isolation level and transaction status --- debug_toolbar/utils/tracking/db.py | 24 +++++++++++++++++++----- 1 file changed, 19 insertions(+), 5 deletions(-) (limited to 'debug_toolbar/utils/tracking') diff --git a/debug_toolbar/utils/tracking/db.py b/debug_toolbar/utils/tracking/db.py index 4c9ee53..de84785 100644 --- a/debug_toolbar/utils/tracking/db.py +++ b/debug_toolbar/utils/tracking/db.py @@ -10,7 +10,7 @@ from django.utils.encoding import force_unicode from django.utils.hashcompat import sha_constructor from debug_toolbar.utils import ms_from_timedelta, tidy_stacktrace, get_template_info - +from debug_toolbar.utils.compat.db import connections # TODO:This should be set in the toolbar loader as a default and panels should # get a copy of the toolbar object with access to its config dictionary SQL_WARNING_THRESHOLD = getattr(settings, 'DEBUG_TOOLBAR_CONFIG', {}) \ @@ -29,6 +29,9 @@ class CursorWrapper(object): self.logger = logger def execute(self, sql, params=()): + alias = getattr(self, 'alias', 'default') + # HACK: avoid imports + engine = connections[alias].connection.__class__.__module__.split('.', 1)[0] start = datetime.now() try: return self.cursor.execute(sql, params) @@ -56,9 +59,9 @@ class CursorWrapper(object): pass del cur_frame - # We keep `sql` to maintain backwards compatibility - self.logger.record(**{ - 'alias': getattr(self, 'alias', 'default'), + params = { + 'engine': engine, + 'alias': alias, 'sql': self.db.ops.last_executed_query(self.cursor, sql, params), 'duration': duration, 'raw_sql': sql, @@ -70,7 +73,18 @@ class CursorWrapper(object): 'is_slow': (duration > SQL_WARNING_THRESHOLD), 'is_select': sql.lower().strip().startswith('select'), 'template_info': template_info, - }) + } + + if engine == 'psycopg2': + conn = connections[alias].connection + params.update({ + 'trans_status': conn.get_transaction_status(), + 'iso_level': conn.isolation_level, + 'encoding': conn.encoding, + }) + + # We keep `sql` to maintain backwards compatibility + self.logger.record(**params) def executemany(self, sql, param_list): return self.cursor.executemany(sql, param_list) -- cgit v1.2.3 From a9b466b6672c72f498e3f011524d48726937d1d5 Mon Sep 17 00:00:00 2001 From: David Cramer Date: Wed, 6 Apr 2011 16:07:46 -0700 Subject: SQL panel now guesses at Psycopg2 transactions (when autocommit swaps to in trans and vice versa) --- debug_toolbar/utils/tracking/db.py | 18 +++++++++++++++--- 1 file changed, 15 insertions(+), 3 deletions(-) (limited to 'debug_toolbar/utils/tracking') diff --git a/debug_toolbar/utils/tracking/db.py b/debug_toolbar/utils/tracking/db.py index de84785..234247a 100644 --- a/debug_toolbar/utils/tracking/db.py +++ b/debug_toolbar/utils/tracking/db.py @@ -30,9 +30,16 @@ class CursorWrapper(object): def execute(self, sql, params=()): alias = getattr(self, 'alias', 'default') + conn = connections[alias].connection # HACK: avoid imports - engine = connections[alias].connection.__class__.__module__.split('.', 1)[0] + if conn: + engine = conn.__class__.__module__.split('.', 1)[0] + else: + engine = 'unknown' + start = datetime.now() + if engine == 'psycopg2': + trans_status = self.logger.get_transaction_status(alias) try: return self.cursor.execute(sql, params) finally: @@ -76,12 +83,17 @@ class CursorWrapper(object): } if engine == 'psycopg2': - conn = connections[alias].connection + import psycopg2.extensions + cur_trans_status = self.logger.get_transaction_status(alias, True) params.update({ - 'trans_status': conn.get_transaction_status(), + 'starts_trans': cur_trans_status > trans_status, + 'ends_trans': cur_trans_status < trans_status, + 'in_trans': cur_trans_status == psycopg2.extensions.TRANSACTION_STATUS_INTRANS, + 'trans_status': cur_trans_status, 'iso_level': conn.isolation_level, 'encoding': conn.encoding, }) + # We keep `sql` to maintain backwards compatibility self.logger.record(**params) -- cgit v1.2.3 From 0556fd7b48c709b5ff803eff01e0dd7eb07ba3fc Mon Sep 17 00:00:00 2001 From: David Cramer Date: Wed, 6 Apr 2011 16:29:33 -0700 Subject: Generate fake transaction ids so we can match up transaction end state correctly --- debug_toolbar/utils/tracking/db.py | 26 ++++++++++---------------- 1 file changed, 10 insertions(+), 16 deletions(-) (limited to 'debug_toolbar/utils/tracking') diff --git a/debug_toolbar/utils/tracking/db.py b/debug_toolbar/utils/tracking/db.py index 234247a..87f4550 100644 --- a/debug_toolbar/utils/tracking/db.py +++ b/debug_toolbar/utils/tracking/db.py @@ -29,17 +29,7 @@ class CursorWrapper(object): self.logger = logger def execute(self, sql, params=()): - alias = getattr(self, 'alias', 'default') - conn = connections[alias].connection - # HACK: avoid imports - if conn: - engine = conn.__class__.__module__.split('.', 1)[0] - else: - engine = 'unknown' - start = datetime.now() - if engine == 'psycopg2': - trans_status = self.logger.get_transaction_status(alias) try: return self.cursor.execute(sql, params) finally: @@ -66,6 +56,14 @@ class CursorWrapper(object): pass del cur_frame + alias = getattr(self, 'alias', 'default') + conn = connections[alias].connection + # HACK: avoid imports + if conn: + engine = conn.__class__.__module__.split('.', 1)[0] + else: + engine = 'unknown' + params = { 'engine': engine, 'alias': alias, @@ -83,13 +81,9 @@ class CursorWrapper(object): } if engine == 'psycopg2': - import psycopg2.extensions - cur_trans_status = self.logger.get_transaction_status(alias, True) params.update({ - 'starts_trans': cur_trans_status > trans_status, - 'ends_trans': cur_trans_status < trans_status, - 'in_trans': cur_trans_status == psycopg2.extensions.TRANSACTION_STATUS_INTRANS, - 'trans_status': cur_trans_status, + 'trans_id': self.logger.get_transaction_id(alias), + 'trans_status': conn.get_transaction_status(), 'iso_level': conn.isolation_level, 'encoding': conn.encoding, }) -- cgit v1.2.3