Added ?_trace=1 option to trace SQL

Currently just dumps all SQL statements out on the console.

datasette/app.py

@@ -2,6 +2,7 @@ import asyncio
 import click
 import collections
 import hashlib
+import json
 import os
 import sys
 import threading
@@ -38,6 +39,7 @@ from .utils import (
     to_css_class
 )
 from .inspect import inspect_hash, inspect_views, inspect_tables
+from .tracer import capture_traces, trace
 from .plugins import pm, DEFAULT_PLUGINS
 from .version import __version__
 
@@ -622,12 +624,25 @@ class Datasette:
             else:
                 return Results(rows, False, cursor.description)
 
-        return await self.execute_against_connection_in_thread(
-            db_name, sql_operation_in_thread
-        )
+        with trace("sql", (db_name, sql, params)):
+            results = await self.execute_against_connection_in_thread(
+                db_name, sql_operation_in_thread
+            )
+        return results
 
     def app(self):
-        app = Sanic(__name__)
+
+        class TracingSanic(Sanic):
+            async def handle_request(self, request, write_callback, stream_callback):
+                if request.args.get("_trace"):
+                    request["traces"] = []
+                    with capture_traces(request["traces"]):
+                        res = await super().handle_request(request, write_callback, stream_callback)
+                else:
+                    res = await super().handle_request(request, write_callback, stream_callback)
+                return res
+
+        app = TracingSanic(__name__)
         default_templates = str(app_root / "datasette" / "templates")
         template_paths = []
         if self.template_dir:
@@ -702,6 +717,7 @@ class Datasette:
             r"/<db_name:[^/]+>/<table:[^/]+?>/<pk_path:[^/]+?><as_format:(\.jsono?)?$>",
         )
         self.register_custom_units()
+
         # On 404 with a trailing slash redirect to path without that slash:
         # pylint: disable=unused-variable
         @app.middleware("response")
@@ -712,6 +728,12 @@ class Datasette:
                     path = "{}?{}".format(path, request.query_string)
                 return response.redirect(path)
 
+        @app.middleware("response")
+        async def print_traces(request, response):
+            if request.get("traces") is not None:
+                print(json.dumps(request["traces"], indent=2))
+                print("Num traces: {}".format(len(request["traces"])))
+
         @app.exception(Exception)
         def on_exception(request, exception):
             title = None

datasette/tracer.py

@@ -0,0 +1,41 @@
+import asyncio
+from contextlib import contextmanager
+import time
+
+tracers = {}
+
+
+def get_task_id():
+    try:
+        loop = asyncio.get_event_loop()
+    except RuntimeError:
+        return None
+    return id(asyncio.Task.current_task(loop=loop))
+
+
+@contextmanager
+def trace(type, action):
+    task_id = get_task_id()
+    if task_id is None:
+        yield
+        return
+    tracer = tracers.get(task_id)
+    if tracer is None:
+        yield
+        return
+    begin = time.time()
+    yield
+    end = time.time()
+    tracer.append((type, action, begin, end, 1000 * (end - begin)))
+
+
+@contextmanager
+def capture_traces(tracer):
+    # tracer is a list
+    task_id = get_task_id()
+    if task_id is None:
+        yield
+        return
+    tracers[task_id] = tracer
+    yield
+    del tracers[task_id]

pytest.ini

@@ -6,3 +6,5 @@ filterwarnings=
     ignore:Using or importing the ABCs::bs4.element
     # Sanic verify_ssl=True
     ignore:verify_ssl is deprecated::sanic
+    # Python 3.7 PendingDeprecationWarning: Task.current_task()
+    ignore:.*current_task.*:PendingDeprecationWarning