Finished implementation of ?_trace=1 debug tool

I redesigned the JSON output and added a handy "traceback" key showing
three relevant lines of the current traceback for each logged query.

Closes #435

datasette/app.py

@@ -723,7 +723,7 @@ class Datasette:
             else:
                 return Results(rows, False, cursor.description)
 
-        with trace("sql", (db_name, sql.strip(), params)):
+        with trace("sql", database=db_name, sql=sql.strip(), params=params):
             results = await self.execute_against_connection_in_thread(
                 db_name, sql_operation_in_thread
             )
@@ -857,22 +857,21 @@ class Datasette:
         async def add_traces_to_response(request, response):
             if request.get("traces") is None:
                 return
-            traces = {
+            traces = request["traces"]
-                "duration": time.time() - request["trace_start"],
+            trace_info = {
-                "queries": request["traces"],
+                "request_duration_ms": 1000 * (time.time() - request["trace_start"]),
+                "sum_trace_duration_ms": sum(t["duration_ms"] for t in traces),
+                "num_traces": len(traces),
+                "traces": traces,
             }
             if "text/html" in response.content_type and b"</body>" in response.body:
-                extra = json.dumps(traces, indent=2)
+                extra = json.dumps(trace_info, indent=2)
                 extra_html = "<pre>{}</pre></body>".format(extra).encode("utf8")
                 response.body = response.body.replace(b"</body>", extra_html)
             elif "json" in response.content_type and response.body.startswith(b"{"):
                 data = json.loads(response.body.decode("utf8"))
-                if "_traces" not in data:
+                if "_trace" not in data:
-                    data["_traces"] = {
+                    data["_trace"] = trace_info
-                        "num_traces": len(traces["queries"]),
-                        "traces": traces,
-                        "duration_sum_ms": sum(t[-1] for t in traces["queries"]),
-                    }
                     response.body = json.dumps(data).encode("utf8")
 
         @app.exception(Exception)

datasette/tracer.py

@@ -1,9 +1,12 @@
 import asyncio
 from contextlib import contextmanager
 import time
+import traceback
 
 tracers = {}
 
+TRACE_RESERVED_KEYS = {"type", "start", "end", "duration_ms", "traceback"}
+
 
 def get_task_id():
     try:
@@ -14,7 +17,10 @@ def get_task_id():
 
 
 @contextmanager
-def trace(type, action):
+def trace(type, **kwargs):
+    assert not TRACE_RESERVED_KEYS.intersection(
+        kwargs.keys()
+    ), ".trace() keyword parameters cannot include {}".format(TRACE_RESERVED_KEYS)
     task_id = get_task_id()
     if task_id is None:
         yield
@@ -23,10 +29,18 @@ def trace(type, action):
     if tracer is None:
         yield
         return
-    begin = time.time()
+    start = time.time()
     yield
     end = time.time()
-    tracer.append((type, action, begin, end, 1000 * (end - begin)))
+    trace = {
+        "type": type,
+        "start": start,
+        "end": end,
+        "duration_ms": (end - start) * 1000,
+        "traceback": traceback.format_list(traceback.extract_stack(limit=6)[:-3]),
+    }
+    trace.update(kwargs)
+    tracer.append(trace)
 
 
 @contextmanager

tests/test_api.py

@@ -1469,12 +1469,22 @@ def test_infinity_returned_as_invalid_json_if_requested(app_client):
 def test_trace(app_client):
     response = app_client.get("/fixtures/simple_primary_key.json?_trace=1")
     data = response.json
-    assert "_traces" in data
+    assert "_trace" in data
-    traces = data["_traces"]
+    trace_info = data["_trace"]
-    assert isinstance(traces["duration_sum_ms"], float)
+    assert isinstance(trace_info["request_duration_ms"], float)
-    assert isinstance(traces["num_traces"], int)
+    assert isinstance(trace_info["sum_trace_duration_ms"], float)
-    assert isinstance(traces["traces"], dict)
+    assert isinstance(trace_info["num_traces"], int)
-    assert len(traces["traces"]["queries"]) == traces["num_traces"]
+    assert isinstance(trace_info["traces"], list)
+    assert len(trace_info["traces"]) == trace_info["num_traces"]
+    for trace in trace_info["traces"]:
+        assert isinstance(trace["type"], str)
+        assert isinstance(trace["start"], float)
+        assert isinstance(trace["end"], float)
+        assert trace["duration_ms"] == (trace["end"] - trace["start"]) * 1000
+        assert isinstance(trace["traceback"], list)
+        assert isinstance(trace["database"], str)
+        assert isinstance(trace["sql"], str)
+        assert isinstance(trace["params"], (list, dict))
 
 
 @pytest.mark.parametrize(