diff --git a/datasette/app.py b/datasette/app.py index 2f0bf47a..f6ee38f1 100644 --- a/datasette/app.py +++ b/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 = { - "duration": time.time() - request["trace_start"], - "queries": request["traces"], + traces = request["traces"] + trace_info = { + "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"" in response.body: - extra = json.dumps(traces, indent=2) + extra = json.dumps(trace_info, indent=2) extra_html = "
{}
".format(extra).encode("utf8") response.body = response.body.replace(b"", 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: - data["_traces"] = { - "num_traces": len(traces["queries"]), - "traces": traces, - "duration_sum_ms": sum(t[-1] for t in traces["queries"]), - } + if "_trace" not in data: + data["_trace"] = trace_info response.body = json.dumps(data).encode("utf8") @app.exception(Exception) diff --git a/datasette/tracer.py b/datasette/tracer.py index 9ab0ab43..c6fe0a00 100644 --- a/datasette/tracer.py +++ b/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 diff --git a/tests/test_api.py b/tests/test_api.py index a13e53e5..a5e2163d 100644 --- a/tests/test_api.py +++ b/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 - traces = data["_traces"] - assert isinstance(traces["duration_sum_ms"], float) - assert isinstance(traces["num_traces"], int) - assert isinstance(traces["traces"], dict) - assert len(traces["traces"]["queries"]) == traces["num_traces"] + assert "_trace" in data + trace_info = data["_trace"] + assert isinstance(trace_info["request_duration_ms"], float) + assert isinstance(trace_info["sum_trace_duration_ms"], float) + assert isinstance(trace_info["num_traces"], int) + 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(