diff --git a/src/sentry/api/base.py b/src/sentry/api/base.py index b036077256aad7..1ffba4b648b642 100644 --- a/src/sentry/api/base.py +++ b/src/sentry/api/base.py @@ -20,6 +20,7 @@ from sentry.models import ApiKey, AuditLogEntry from sentry.utils.cursors import Cursor from sentry.utils.http import absolute_uri, is_valid_origin +from sentry.utils.performance import SqlQueryCountMonitor from .authentication import ApiKeyAuthentication from .paginator import Paginator @@ -116,6 +117,8 @@ def dispatch(self, request, *args, **kwargs): self.request = request self.headers = self.default_response_headers # deprecate? + metric_name = '{}.{}'.format(type(self).__name__, request.method.lower()) + if settings.SENTRY_API_RESPONSE_DELAY: time.sleep(settings.SENTRY_API_RESPONSE_DELAY / 1000.0) @@ -141,7 +144,8 @@ def dispatch(self, request, *args, **kwargs): else: handler = self.http_method_not_allowed - response = handler(request, *args, **kwargs) + with SqlQueryCountMonitor(metric_name): + response = handler(request, *args, **kwargs) except Exception as exc: response = self.handle_exception(request, exc) diff --git a/src/sentry/tasks/base.py b/src/sentry/tasks/base.py index 02f16399235e09..33ee0abee59448 100644 --- a/src/sentry/tasks/base.py +++ b/src/sentry/tasks/base.py @@ -16,6 +16,7 @@ from sentry.celery import app from sentry.utils import metrics +from sentry.utils.performance import SqlQueryCountMonitor def get_rss_usage(): @@ -49,7 +50,8 @@ def _wrapped(*args, **kwargs): 'transaction_id': transaction_id, }) with metrics.timer(key, instance=instance), \ - track_memory_usage('jobs.memory_change', instance=instance): + track_memory_usage('jobs.memory_change', instance=instance), \ + SqlQueryCountMonitor(name): try: result = func(*args, **kwargs) finally: diff --git a/src/sentry/utils/performance/__init__.py b/src/sentry/utils/performance/__init__.py new file mode 100644 index 00000000000000..b9a9714e455936 --- /dev/null +++ b/src/sentry/utils/performance/__init__.py @@ -0,0 +1,3 @@ +from __future__ import absolute_import + +from .sqlquerycount import SqlQueryCountMonitor # NOQA diff --git a/src/sentry/utils/performance/sqlquerycount.py b/src/sentry/utils/performance/sqlquerycount.py new file mode 100644 index 00000000000000..dfe2fd2fd08edd --- /dev/null +++ b/src/sentry/utils/performance/sqlquerycount.py @@ -0,0 +1,123 @@ +from __future__ import absolute_import + +import logging +import threading + +from collections import defaultdict + +from sentry.debug.utils.patch_context import PatchContext + +DEFAULT_MAX_QUERIES = 25 +DEFAULT_MAX_DUPES = 3 + + +class State(threading.local): + def __init__(self): + self.count = 0 + self.query_hashes = defaultdict(int) + + def record_query(self, sql): + self.count += 1 + self.query_hashes[hash(sql)] += 1 + + def count_dupes(self): + return sum(1 for n in self.query_hashes.itervalues() if n > 1) + + +class CursorWrapper(object): + def __init__(self, cursor, connection, state): + self.cursor = cursor + self.connection = connection + self._state = state + + def execute(self, sql, params=()): + try: + return self.cursor.execute(sql, params) + finally: + self._state.record_query(sql) + + def executemany(self, sql, paramlist): + try: + return self.cursor.executemany(sql, paramlist) + finally: + self._state.record_query(sql) + + 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) + + +def get_cursor_wrapper(state): + def cursor(func, self, *args, **kwargs): + result = func(self, *args, **kwargs) + + return CursorWrapper(result, self, state) + return cursor + + +class SqlQueryCountMonitor(object): + def __init__(self, context, max_queries=DEFAULT_MAX_QUERIES, + max_dupes=DEFAULT_MAX_DUPES, logger=None, **kwargs): + self.context = context + self.max_queries = max_queries + self.max_dupes = max_dupes + self.logger = logger or logging.getLogger(__name__) + + self.state = State() + + self._cursor = get_cursor_wrapper(self.state) + self._patcher = PatchContext('django.db.backends.BaseDatabaseWrapper.cursor', self._cursor) + + def __enter__(self): + self.start() + return self + + def __exit__(self, *args, **kwargs): + self.stop() + + def start(self): + self._patcher.patch() + + def stop(self): + self._patcher.unpatch() + + num_dupes = self.state.count_dupes() + + if self.state.count > self.max_queries: + self.log_max_queries(num_dupes) + + if num_dupes > self.max_dupes: + self.log_max_dupes(num_dupes) + + def log_max_dupes(self, num_dupes): + state = self.state + + context = { + 'stack': True, + 'data': { + 'query_count': state.count, + 'num_dupes': num_dupes, + } + } + + self.logger.warning('%d duplicate queries executed in %s', + num_dupes, self.context, extra=context) + + def log_max_queries(self, num_dupes): + state = self.state + + context = { + 'stack': True, + 'data': { + 'query_count': state.count, + 'num_dupes': num_dupes, + } + } + + self.logger.warning('%d queries executed in %s', + state.count, self.context, extra=context)