Add /sql_profiler to enable SQL profiling

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.

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
 

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

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)

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")

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")

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()