Add EXPLAIN output to sql sentry breadcrumbs

talisker/postgresql.py

@@ -103,28 +103,40 @@ def cursor(self, *args, **kwargs):
         kwargs.setdefault('cursor_factory', TaliskerCursor)
         return super().cursor(*args, **kwargs)
 
-    def _format_query(self, query):
+    def _format_query(self, query, vars):
         if callable(query):
             query = query()
         query = prettify_sql(query)
-        query = FILTERED if query is None else query
+        if query is None or vars is None:
+            return FILTERED
         return query
 
-    def _record(self, msg, query, duration, extra={}):
+    def _record(self, msg, query, vars, duration, extra={}):
         talisker.Context.track('sql', duration)
 
         qdata = collections.OrderedDict()
         qdata['duration_ms'] = duration
         qdata['connection'] = self.safe_dsn
         qdata.update(extra)
 
+        # grab a reference here, where super() works
+        base_connection = super()
+
         if self.query_threshold >= 0 and duration > self.query_threshold:
-            formatted = self._format_query(query)
+            formatted = self._format_query(query, vars)
             self.logger.info(
                 'slow ' + msg, extra=dict(qdata, trailer=formatted))
 
         def processor(data):
-            qdata['query'] = self._format_query(query)
+            qdata['query'] = self._format_query(query, vars)
+            try:
+                cursor = base_connection.cursor()
+                cursor.execute('EXPLAIN ' + query, vars)
+                plan = '\n'.join(l[0] for l in cursor.fetchall())
+                qdata['plan'] = plan
+            except Exception as e:
+                qdata['plan'] = 'could not explain query: ' + str(e)
+
             data['data'].update(qdata)
 
         breadcrumb = dict(
@@ -141,7 +153,7 @@ def apply_timeout(self):
             return None
 
         ms = int(ctx_timeout * 1000)
-        super(TaliskerCursor, self).execute(
+        super().execute(
             'SET LOCAL statement_timeout TO %s', (ms,)
         )
         return ms
@@ -153,7 +165,7 @@ def execute(self, query, vars=None):
             extra['timeout'] = timeout
         timestamp = time.time()
         try:
-            return super(TaliskerCursor, self).execute(query, vars)
+            return super().execute(query, vars)
         except psycopg2.OperationalError as exc:
             extra['pgcode'] = exc.pgcode
             extra['pgerror'] = exc.pgerror
@@ -162,9 +174,7 @@ def execute(self, query, vars=None):
             raise
         finally:
             duration = get_rounded_ms(timestamp)
-            if vars is None:
-                query = None
-            self.connection._record('query', query, duration, extra)
+            self.connection._record('query', query, vars, duration, extra)
 
     def callproc(self, procname, vars=None):
         extra = collections.OrderedDict()
@@ -173,7 +183,7 @@ def callproc(self, procname, vars=None):
             extra['timeout'] = timeout
         timestamp = time.time()
         try:
-            return super(TaliskerCursor, self).callproc(procname, vars)
+            return super().callproc(procname, vars)
         except psycopg2.OperationalError as exc:
             extra['pgcode'] = exc.pgcode
             extra['pgerror'] = exc.pgerror
@@ -184,4 +194,9 @@ def callproc(self, procname, vars=None):
             duration = get_rounded_ms(timestamp)
             # no query parameters, cannot safely record
             self.connection._record(
-                'stored proc: {}'.format(procname), None, duration, extra)
+                'stored proc: {}'.format(procname),
+                None,
+                vars,
+                duration,
+                extra,
+            )

talisker/sentry.py

@@ -262,6 +262,7 @@ def __init__(self, dsn):
 
         def start(self):
             self.client = get_client()
+            new_context()
             self.orig_remote = self.client.remote
             self.client.set_dsn(self.dsn, DummySentryTransport)
             self.transport = self.client.remote.get_transport()
@@ -432,7 +433,7 @@ def add_talisker_context(data):
 def sql_summary(sql_crumbs, start_time):
 
     def duration(crumb):
-        return float(crumb['data'].get('duration', 0))
+        return float(crumb['data'].get('duration_ms', 0))
 
     sql_crumbs.sort(key=duration, reverse=True)
     sql_time = sum(duration(c) for c in sql_crumbs)
@@ -445,13 +446,14 @@ def duration(crumb):
         sql_summary['non_sql_time'] = request_time - sql_time
         sql_summary['total_time'] = request_time
 
-    sql_summary['slowest queries'] = [
-        OrderedDict([
-            ('duration', c['data']['duration']),
+    slowest = []
+    for c in sql_crumbs[:5]:
+        slow = OrderedDict([
+            ('duration_ms', c['data']['duration_ms']),
             ('query', c['data']['query'])]
         )
-        for c in sql_crumbs[:5]
-    ]
+        slowest.append(slow)
+    sql_summary['slowest queries'] = slowest
 
     return sql_summary
 

tests/flask_app.py

@@ -72,7 +72,7 @@ def logging():
 
 @app.route('/error/')
 def error():
-    conn.execute(select([users]))
+    conn.execute(select([users]).where(users.c.id == 1))
     talisker.requests.get_session().post(
         'http://httpbin.org/post', json={'foo': 'bar'})
     logger.info('halp', extra={'foo': 'bar'})

tests/test_postgresql.py

@@ -58,9 +58,9 @@ def cursor(conn):
 
 
 def test_connection_record_slow(conn, context, get_breadcrumbs):
-    query = 'select * from table'
+    query = 'select * from table where id=%s'
     conn._threshold = 0
-    conn._record('msg', query, 10000)
+    conn._record('msg', query, (1,), 10000)
     records = context.logs.filter(name='talisker.slowqueries')
     assert records[0].extra['duration_ms'] == 10000.0
     assert records[0]._trailer == prettify_sql(query)
@@ -69,14 +69,14 @@ def test_connection_record_slow(conn, context, get_breadcrumbs):
 @pytest.mark.skipif(not talisker.sentry.enabled, reason='need raven installed')
 def test_connection_record_fast(conn, context):
     query = 'select * from table'
-    conn._record('msg', query, 0)
+    conn._record('msg', query, None, 0)
     context.assert_not_log(name='talisker.slowqueries')
 
 
 @pytest.mark.skipif(not talisker.sentry.enabled, reason='need raven installed')
 def test_connection_record_breadcrumb(conn, get_breadcrumbs):
     query = 'select * from table'
-    conn._record('msg', query, 1000)
+    conn._record('msg', query, None, 1000)
     breadcrumb = get_breadcrumbs()[0]
     assert breadcrumb['message'] == 'msg'
     assert breadcrumb['category'] == 'sql'

tests/test_sentry.py

@@ -44,6 +44,8 @@
 
 from talisker import testing
 
+from tests.conftest import require_module
+
 DATESTRING = '2016-01-02 03:04:05.1234'
 
 
@@ -272,13 +274,13 @@ def test_add_talisker_context():
 @freeze_time(DATESTRING)
 def test_sql_summary_crumb():
     crumbs = [
-        {'category': 'sql', 'data': {'duration': 10.0, 'query': '1'}},
-        {'category': 'sql', 'data': {'duration': 15.0, 'query': '2'}},
-        {'category': 'sql', 'data': {'duration': 13.0, 'query': '3'}},
-        {'category': 'sql', 'data': {'duration': 5.0, 'query': '4'}},
-        {'category': 'sql', 'data': {'duration': 11.0, 'query': '5'}},
-        {'category': 'sql', 'data': {'duration': 7.0, 'query': '6'}},
-        {'category': 'sql', 'data': {'duration': 4.0, 'query': '7'}},
+        {'category': 'sql', 'data': {'duration_ms': 10.0, 'query': '1'}},
+        {'category': 'sql', 'data': {'duration_ms': 15.0, 'query': '2'}},
+        {'category': 'sql', 'data': {'duration_ms': 13.0, 'query': '3'}},
+        {'category': 'sql', 'data': {'duration_ms': 5.0, 'query': '4'}},
+        {'category': 'sql', 'data': {'duration_ms': 11.0, 'query': '5'}},
+        {'category': 'sql', 'data': {'duration_ms': 7.0, 'query': '6'}},
+        {'category': 'sql', 'data': {'duration_ms': 4.0, 'query': '7'}},
     ]
 
     start_time = time.time() - 0.5  # 500ms
@@ -289,15 +291,51 @@ def test_sql_summary_crumb():
         'total_time': 500.0,
         'non_sql_time': 435.0,
         'slowest queries': [
-            {'duration': 15.0, 'query': '2'},
-            {'duration': 13.0, 'query': '3'},
-            {'duration': 11.0, 'query': '5'},
-            {'duration': 10.0, 'query': '1'},
-            {'duration': 7.0, 'query': '6'},
+            {'duration_ms': 15.0, 'query': '2'},
+            {'duration_ms': 13.0, 'query': '3'},
+            {'duration_ms': 11.0, 'query': '5'},
+            {'duration_ms': 10.0, 'query': '1'},
+            {'duration_ms': 7.0, 'query': '6'},
         ],
     }
 
 
+@require_module('psycopg2')
+def test_sql_crumbs_functional(request, postgresql, context):
+    import psycopg2
+    from talisker.postgresql import TaliskerConnection
+
+    table = request.function.__name__
+
+    with psycopg2.connect(postgresql.dsn) as ddl:
+        with ddl.cursor() as cur:
+            cur.execute("""
+                CREATE TABLE IF NOT EXISTS {} (
+                id   INTEGER PRIMARY KEY,
+                value TEXT
+                );
+            """.format(table))
+            cur.execute("INSERT INTO {} VALUES (1, 'foo')".format(table))
+
+    cur = TaliskerConnection(postgresql.dsn).cursor()
+
+    q = 'SELECT * FROM {} WHERE id = %s'.format(table)
+    cur.execute(q, (1,))
+    cur.fetchall()
+    talisker.sentry.get_client().captureMessage(table)
+    msg = context.sentry[0]
+    sql_crumbs = [
+        c for c in msg['breadcrumbs']['values'] if c['category'] == 'sql'
+    ]
+    data = sql_crumbs[0]['data']
+    assert data['query'] == talisker.postgresql.prettify_sql(q)
+    assert data['plan'].startswith(
+        'Index Scan using {0}_pkey on {0}'.format(table)
+    )
+    assert 'duration_ms' in data
+    assert 'connection' in data
+
+
 def test_proxy_mixin():
     client = talisker.sentry.get_client()
     lh = talisker.sentry.get_log_handler()