diff --git a/datasette/database.py b/datasette/database.py index 155a7444..207e80a6 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -402,14 +402,9 @@ class Database: if not write: # Immutable database - no writes can ever occur, so there is no # write queue to block; run against a fresh read-only connection. - # A fresh copy_context() is required per submit (not one shared - # copy reused across calls): concurrent execution of the same - # Context raises "RuntimeError: cannot enter context ... already - # entered". This propagates the caller's otel context (e.g. the - # enclosing db.query span) onto the worker thread. - # - # It also propagates every *other* ContextVar - see the note in - # execute_fn() for why that is safe. + # copy_context() carries the caller's otel context onto the worker + # thread - see the notes in execute_fn() for why it must be a + # fresh copy per submit and why carrying every ContextVar is safe. ctx = contextvars.copy_context() return await asyncio.get_running_loop().run_in_executor( self.ds.executor, ctx.run, _run @@ -526,12 +521,9 @@ class Database: task_id = uuid.uuid4() loop = asyncio.get_running_loop() reply_future = loop.create_future() - # Captured here, on the event loop, at enqueue time: the otel - # Context (carrying the enclosing db.query span, if any) and the - # timestamp used to build the db.write.queue_wait span once this - # task is dequeued on the write thread. `block` travels with the - # task too, because it decides whether that context is this task's - # parent or only a link target - see `_execute_writes`. + # The otel Context and enqueue timestamp are captured here, on the + # event loop, for the db.write.queue_wait span built at dequeue time. + # `block` travels too - it decides parent vs. link; see `_execute_writes`. self._write_queue.put( WriteTask( fn, diff --git a/datasette/telemetry.py b/datasette/telemetry.py index 3a205cee..3705d89f 100644 --- a/datasette/telemetry.py +++ b/datasette/telemetry.py @@ -9,10 +9,9 @@ harness). With no provider installed every span produced here is a `NonRecordingSpan`. That is not free - a table page emits ~58 spans - -but it is below what an end-to-end page benchmark can resolve: measured -across 15 runs of a 5,000-row table page, the median moved 9.80ms to -9.98ms while run-to-run spread was 1.4ms. Installing an SDK provider is -what costs something measurable. +but end-to-end page benchmarks put the overhead below their own +run-to-run variation. Installing an SDK provider is what costs +something measurable. """ import re diff --git a/datasette/telemetry_registry.py b/datasette/telemetry_registry.py index 2d0692a8..c2b9db32 100644 --- a/datasette/telemetry_registry.py +++ b/datasette/telemetry_registry.py @@ -47,18 +47,12 @@ class Attribute(str): class SpanName(str): "A span name, carrying its documentation and the attributes it may set." - __slots__ = ("attributes", "description", "kind", "prefix") + __slots__ = ("attributes", "description", "kind") - def __new__( - cls, name, description, attributes=(), prefix=False, kind=SpanKind.INTERNAL - ): + def __new__(cls, name, description, attributes=(), kind=SpanKind.INTERNAL): self = super().__new__(cls, name) self.description = description self.attributes = tuple(attributes) - # True for a span family whose emitted names carry a variable suffix, - # so the conformance test matches by prefix rather than equality. - # Nothing sets it yet. - self.prefix = prefix # SpanKind.INTERNAL by default - every span Datasette emits describes # its own internal work. db.query is the one exception: it is a real # database call, so semantic conventions (and trace UIs, which key @@ -85,10 +79,9 @@ DB_OPERATION_NAME = Attribute( "db.operation.name", "The statement's leading keyword - ``SELECT``, ``INSERT``, ``CREATE``, and " "so on - matched against a small fixed allowlist. Omitted rather than set " - "to an arbitrary value: the allowlist exists because this attribute is a " - "candidate dimension for a query-duration metric in a later phase, and " - "echoing an unrecognised first token from user-supplied SQL would be an " - "unbounded-cardinality hazard. Also omitted for " + "to an arbitrary value: the attribute must stay safe to use as a metric " + "dimension, and echoing an unrecognised first token from user-supplied " + "SQL would be an unbounded-cardinality hazard. Also omitted for " "``execute_write_script()``, which runs multiple statements - per " "semantic conventions, the operation name should not be extracted from " "query text that can contain more than one operation. Note that a " @@ -252,16 +245,11 @@ def span_for(emitted_name): """ Resolve an emitted span name to its registry entry, or None. - Handles span families whose emitted names carry a suffix that is not - knowable in advance - `prefix=True` entries. Phase 1 has none, but the - lookup is what the conformance test calls, so it lives here rather than - in the test. + The lookup is what the conformance test calls, so it lives here rather + than in the test. """ for span in SPANS: - if span.prefix: - if emitted_name.startswith(span): - return span - elif emitted_name == span: + if emitted_name == span: return span return None diff --git a/docs/changelog.rst b/docs/changelog.rst index 3d4363ef..b6b946c8 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -13,7 +13,7 @@ Unreleased - Datasette's database layer now emits `OpenTelemetry `__ spans: one per query, covering the full round trip including time spent waiting for a SQL worker thread, plus separate child spans for the execution itself and for time spent in the write queue. Datasette core depends on ``opentelemetry-api`` only and never installs an SDK provider, an exporter or a sampler, so there is no effect and no measurable overhead unless tracing is switched on externally - normally with the standard ``opentelemetry-instrument`` agent. See :ref:`internals_telemetry`. (:issue:`1730`) - :ref:`db.execute(sql, ..., table=None) ` has a new optional ``table=`` parameter, naming the table a query is about so it can be recorded on that query's OpenTelemetry span. It has no effect on query execution, and Datasette never derives it from the SQL. (:issue:`1730`) -Nothing is removed by this change: the ``?_trace=1`` query string parameter, the ``trace_debug`` setting and the :ref:`internals_tracer` module all continue to work as before. +Nothing is removed by the OpenTelemetry work: the ``?_trace=1`` query string parameter, the ``trace_debug`` setting and the :ref:`internals_tracer` module all continue to work as before. .. _v1_0_a39: diff --git a/docs/internals.rst b/docs/internals.rst index d7dd51ab..ecde8533 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -2359,11 +2359,11 @@ A few things catch people out the first time: .. warning:: ``OTEL_TRACES_EXPORTER=console datasette mydb.db`` produces **nothing**. That environment variable is read by the OpenTelemetry SDK's auto-configuration, which only runs when the ``opentelemetry-instrument`` agent wraps the process. Datasette core installs no provider, so a plain ``datasette`` process emits nothing at all, whatever ``OTEL_`` variables are set. -Spans do not appear immediately. The SDK's default ``BatchSpanProcessor`` flushes on a timer, every 5 seconds. Either wait, or stop the process - shutdown triggers a final flush - or set ``OTEL_BSP_SCHEDULE_DELAY=1000`` while you are experimenting. That last one is for demos, not for production. +- **Spans do not appear immediately.** The SDK's default ``BatchSpanProcessor`` flushes on a timer, every 5 seconds. Either wait, or stop the process - shutdown triggers a final flush - or set ``OTEL_BSP_SCHEDULE_DELAY=1000`` while you are experimenting. That last one is for demos, not for production. -Always set ``OTEL_SERVICE_NAME``. Without it the SDK's default resource reports a ``service.name`` of ``unknown_service``, and your traces will be filed under that instead of under a name you can search for. +- **Always set** ``OTEL_SERVICE_NAME``. Without it the SDK's default resource reports a ``service.name`` of ``unknown_service``, and your traces will be filed under that instead of under a name you can search for. -Setting ``OTEL_METRICS_EXPORTER=none`` and ``OTEL_LOGS_EXPORTER=none`` is worth doing unless your backend accepts those signals too - ``opentelemetry-distro`` defaults every signal to OTLP, and a traces-only backend will reject the other two noisily. Datasette itself emits no metrics and no logs through OpenTelemetry. +- **Setting** ``OTEL_METRICS_EXPORTER=none`` **and** ``OTEL_LOGS_EXPORTER=none`` is worth doing unless your backend accepts those signals too - ``opentelemetry-distro`` defaults every signal to OTLP, and a traces-only backend will reject the other two noisily. Datasette itself emits no metrics and no logs through OpenTelemetry. Span reference -------------- @@ -2389,7 +2389,7 @@ Spans are ``SpanKind.INTERNAL`` unless a kind is listed below. Only ``db.query`` - ``db.system`` - Always ``sqlite``. - ``db.namespace`` - Name of the database being queried. - ``db.query.text`` - The SQL, truncated to 2048 characters. Never the parameter values. - - ``db.operation.name`` *(optional)* - The statement's leading keyword - ``SELECT``, ``INSERT``, ``CREATE``, and so on - matched against a small fixed allowlist. Omitted rather than set to an arbitrary value: the allowlist exists because this attribute is a candidate dimension for a query-duration metric in a later phase, and echoing an unrecognised first token from user-supplied SQL would be an unbounded-cardinality hazard. Also omitted for ``execute_write_script()``, which runs multiple statements - per semantic conventions, the operation name should not be extracted from query text that can contain more than one operation. Note that a statement beginning with a CTE reports ``WITH``, not the operation inside it - a substantial share of Datasette's own reads take that form. Resolving it further would mean parsing. + - ``db.operation.name`` *(optional)* - The statement's leading keyword - ``SELECT``, ``INSERT``, ``CREATE``, and so on - matched against a small fixed allowlist. Omitted rather than set to an arbitrary value: the attribute must stay safe to use as a metric dimension, and echoing an unrecognised first token from user-supplied SQL would be an unbounded-cardinality hazard. Also omitted for ``execute_write_script()``, which runs multiple statements - per semantic conventions, the operation name should not be extracted from query text that can contain more than one operation. Note that a statement beginning with a CTE reports ``WITH``, not the operation inside it - a substantial share of Datasette's own reads take that form. Resolving it further would mean parsing. - ``db.collection.name`` *(optional)* - The primary table, set only where the view already knows it - the table and row pages. Omitted for arbitrary ``?sql=`` queries, where determining the table would mean parsing the query. - ``datasette.param_count`` *(optional)* - Number of bound parameters. Recorded instead of the values themselves. - ``datasette.param_sets`` *(optional)* - Number of parameter sets consumed by ``execute_write_many()``. Not a row count - ``executemany()`` returns no rows. The parameter values themselves are never recorded: that sequence can hold thousands of rows. diff --git a/docs/telemetry_doc.py b/docs/telemetry_doc.py index 3551ef0e..d0af5dbd 100644 --- a/docs/telemetry_doc.py +++ b/docs/telemetry_doc.py @@ -26,8 +26,7 @@ def spans(cog): cog.out("\n") for span in SPANS: - title = f"{span}*" if span.prefix else str(span) - cog.out(f"``{title}``\n") + cog.out(f"``{span}``\n") cog.out(f" {span.description}\n\n") # INTERNAL is the default and the overwhelming majority of spans - # printing it on every one would be noise. Only the exceptional case, diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index 0022883a..83e13b6e 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -147,6 +147,29 @@ async def test_db_query_span_basic_attributes(ds_client, otel_spans): assert span.status.status_code == StatusCode.UNSET +@pytest.mark.asyncio +async def test_truncated_result_sets_truncated_attribute(otel_spans): + """ + A result actually cut short by max_returned_rows records truncated=True. + + Every other test asserts the attribute is False, so a regression that + recorded the flag before the slice (or inverted it) would pass the rest + of the suite. + """ + ds = Datasette(memory=True, settings={"max_returned_rows": 5}) + db = ds.add_memory_database("t04_truncated") + results = await db.execute( + "select value from json_each('[1,2,3,4,5,6,7,8,9,10]')", truncate=True + ) + assert results.truncated + + spans = _spans_for_namespace(otel_spans, "t04_truncated") + assert spans + span = spans[-1] + assert span.attributes["datasette.truncated"] is True + assert span.attributes["datasette.rows_returned"] == 5 + + @pytest.mark.asyncio async def test_facetable_request_produces_db_query_spans(ds_client, otel_spans): response = await ds_client.get("/fixtures/facetable.json") diff --git a/tests/test_telemetry_registry.py b/tests/test_telemetry_registry.py index 335eb946..75a183b4 100644 --- a/tests/test_telemetry_registry.py +++ b/tests/test_telemetry_registry.py @@ -287,23 +287,3 @@ def test_span_and_attribute_lookup(): assert not reg.attribute_allowed(reg.DB_QUERY, "db.namespace.extra") assert not reg.attribute_allowed(reg.DB_QUERY, "datasette.isolated_connection") assert not reg.attribute_allowed(None, "db.namespace") - - -def test_prefix_span_lookup(): - """ - `prefix=True` matching, exercised directly. - - Phase 1 registers no prefix spans, so without this the branch in - `span_for()` would be untested code that the conformance tests silently - never reach. - """ - hook = reg.SpanName("datasette.hook.", "A hypothetical span family", prefix=True) - original = reg.SPANS - reg.SPANS = original + (hook,) - try: - assert reg.span_for("datasette.hook.render_cell") is hook - assert reg.span_for("datasette.hook.anything") is hook - assert reg.span_for("datasette.hookish") is None - assert reg.span_for("db.query") is reg.DB_QUERY - finally: - reg.SPANS = original