diff --git a/README.md b/README.md index dc1340480..3278a79dd 100644 --- a/README.md +++ b/README.md @@ -10,6 +10,9 @@ applications: * Logging handler for CEE/UDP logs * An optional (enabled by setting the LOG_VIEW_SECRET env var) view (/logging/level) to change runtime the log levels +* SQL profiler to debug DB performance problems, disabled by default. You must enable it by setting the + SQL_PROFILER_SECRET env var and using the view (/sql_profiler) to switch it ON and OFF. Warning, + it will slow down everything. * Error handlers to send JSON messages to the client in case of error * A cornice service drop in replacement for setting up CORS diff --git a/acceptance_tests/tests/docker-compose.yml b/acceptance_tests/tests/docker-compose.yml index 14f804c85..d10d3cda5 100644 --- a/acceptance_tests/tests/docker-compose.yml +++ b/acceptance_tests/tests/docker-compose.yml @@ -9,6 +9,7 @@ services: STATSD_ADDRESS: 127.0.0.1:8125 STATSD_PREFIX: acceptance LOG_VIEW_SECRET: changeme + SQL_PROFILER_SECRET: changeme SQL_LOG_LEVEL: DEBUG OTHER_LOG_LEVEL: DEBUG DEVELOPMENT: 1 diff --git a/acceptance_tests/tests/tests/test_sql_profiler.py b/acceptance_tests/tests/tests/test_sql_profiler.py new file mode 100644 index 000000000..19107fb83 --- /dev/null +++ b/acceptance_tests/tests/tests/test_sql_profiler.py @@ -0,0 +1,21 @@ +def _switch(app_connection, enable=None): + params = {'secret': 'changeme'} + if enable is not None: + params['enable'] = "1" if enable else "0" + answer = app_connection.get_json("sql_profiler", params=params) + assert answer['status'] == 200 + return answer['enabled'] + + +def test_ok(app_connection, slave_db_connection): + assert _switch(app_connection) is False + assert _switch(app_connection, enable=True) is True + try: + assert _switch(app_connection) is True + app_connection.get_json("hello") + finally: + _switch(app_connection, enable=False) + + +def test_no_secret(app_connection): + app_connection.get_json("sql_profiler", params={'enable': '1'}, expected_status=403) diff --git a/c2cwsgiutils/pyramid.py b/c2cwsgiutils/pyramid.py index 247c3538b..7f5c260fb 100644 --- a/c2cwsgiutils/pyramid.py +++ b/c2cwsgiutils/pyramid.py @@ -1,7 +1,7 @@ import cornice import pyramid_tm -from c2cwsgiutils import stats, pyramid_logging +from c2cwsgiutils import stats, pyramid_logging, sql_profiler def includeme(config): @@ -14,5 +14,6 @@ def includeme(config): config.include(cornice.includeme) stats.init(config) pyramid_logging.install_subscriber(config) + sql_profiler.init(config) config.scan("c2cwsgiutils.services") config.scan("c2cwsgiutils.errors") diff --git a/c2cwsgiutils/sql_profiler.py b/c2cwsgiutils/sql_profiler.py new file mode 100644 index 000000000..027c0fd20 --- /dev/null +++ b/c2cwsgiutils/sql_profiler.py @@ -0,0 +1,69 @@ +""" +A view (URL=/sql_provider) allowing to enabled/disable a SQL spy that runs an "EXPLAIN ANALYZE" on +every SELECT query going through SQLAlchemy. +""" +import logging +import os +from pyramid.httpexceptions import HTTPForbidden +import re +import sqlalchemy.event +import sqlalchemy.engine + +ENV_KEY = 'SQL_PROFILER_SECRET' +LOG = logging.getLogger(__name__) +enabled = False + + +def _sql_profiler_view(request): + global enabled + if request.params.get('secret') != os.environ[ENV_KEY]: + raise HTTPForbidden('Missing or invalid secret parameter') + if 'enable' in request.params: + if request.params['enable'] == '1': + if not enabled: + LOG.warning("Enabling the SQL profiler") + sqlalchemy.event.listen(sqlalchemy.engine.Engine, "before_cursor_execute", + _before_cursor_execute) + enabled = True + return {'status': 200, 'enabled': True} + else: + if enabled: + LOG.warning("Disabling the SQL profiler") + sqlalchemy.event.remove(sqlalchemy.engine.Engine, "before_cursor_execute", + _before_cursor_execute) + enabled = False + return {'status': 200, 'enabled': False} + else: + return {'status': 200, 'enabled': enabled} + + +def _beautify_sql(statement): + statement = re.sub(r'SELECT [^\n]*\n', 'SELECT ...\n', statement) + statement = re.sub(r' ((?:LEFT )?(?:OUTER )?JOIN )', r'\n\1', statement) + statement = re.sub(r' ON ', r'\n ON ', statement) + statement = re.sub(r' GROUP BY ', r'\nGROUP BY ', statement) + statement = re.sub(r' ORDER BY ', r'\nORDER BY ', statement) + return statement + + +def _indent(statement, indent=' '): + return indent + ("\n" + indent).join(statement.split('\n')) + + +def _before_cursor_execute(conn, _cursor, statement, parameters, _context, _executemany): + if statement.startswith("SELECT ") and LOG.isEnabledFor(logging.INFO): + output = "statement:\n%s\nparameters: %s\nplan:\n " % (_indent(_beautify_sql(statement)), + repr(parameters)) + output += '\n '.join([row[0] for row in conn.engine.execute("EXPLAIN ANALYZE " + statement, + parameters)]) + LOG.info(output) + + +def init(config): + """ + Install a pyramid event handler that adds the request information + """ + if 'SQL_PROFILER_SECRET' in os.environ: + config.add_route("sql_profiler", r"/sql_profiler", request_method="GET") + config.add_view(_sql_profiler_view, route_name="sql_profiler", renderer="json", http_cache=0) + LOG.info("Enabled the /sql_profiler API") diff --git a/setup.py b/setup.py index 6359f5202..a12761884 100644 --- a/setup.py +++ b/setup.py @@ -2,7 +2,7 @@ from setuptools import setup, find_packages -VERSION = '0.6.0' +VERSION = '0.7.0' HERE = os.path.abspath(os.path.dirname(__file__)) INSTALL_REQUIRES = open(os.path.join(HERE, 'rel_requirements.txt')).read().splitlines()