From fa0462015692200cb11db7f5a7540d04955dfd7e Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Tue, 1 Sep 2026 12:24:01 -0700 Subject: [PATCH] Register metrics and give histograms bucket boundaries suited to seconds Both histograms declared unit="s" but inherited OpenTelemetry's default boundaries, which are tuned for milliseconds - so every SQLite query landed in the single (0, 5] second bucket and every quantile query returned noise. The boundaries are the semantic conventions' recommended set for db.client.operation.duration plus 0.0001 and 0.0005 at the bottom, since SQLite is in-process and many real queries take tens of microseconds. (Adapted from 024f2029: that commit assumed the metrics were already in telemetry_registry.py, which on this lineage held spans only - so this commit also brings the MetricName registry machinery, the registry entries for all eight phase-3 metrics, the cog-generated Metric reference in internals.rst, and the datasette.operation attribute. The template and facet histograms it also touched belong to phase 5 and are not included.) Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01F2h9ANGZ7paWSpqs5DUAcG --- datasette/telemetry.py | 45 ++++++---- datasette/telemetry_registry.py | 138 +++++++++++++++++++++++++++++++ docs/internals.rst | 81 +++++++++++++++++- docs/telemetry_doc.py | 19 +++++ tests/test_telemetry_metrics.py | 64 ++++++++++++++ tests/test_telemetry_registry.py | 23 ++++++ 6 files changed, 352 insertions(+), 18 deletions(-) diff --git a/datasette/telemetry.py b/datasette/telemetry.py index b2d7a44a..f8272f19 100644 --- a/datasette/telemetry.py +++ b/datasette/telemetry.py @@ -35,6 +35,15 @@ from .telemetry_registry import ( ERROR_TYPE, HTTP_REQUEST_METHOD, HTTP_RESPONSE_STATUS_CODE, + M_CONNECTIONS_OPEN, + M_OPERATION_DURATION, + M_QUERIES_INTERRUPTED, + M_QUERIES_PENDING, + M_THREADS_LIMIT, + M_THREADS_QUEUE_DEPTH, + M_WRITE_QUEUE_DEPTH, + M_WRITE_QUEUE_WAIT, + OPERATION, SERVER_ADDRESS, URL_PATH, URL_SCHEME, @@ -388,27 +397,29 @@ def _duration_attributes(database_name, operation): return { DB_SYSTEM: "sqlite", DB_NAMESPACE: database_name, - "datasette.operation": operation, + OPERATION: operation, } sql_operation_duration = meter.create_histogram( - "db.client.operation.duration", - unit="s", + M_OPERATION_DURATION, + unit=M_OPERATION_DURATION.unit, description="Duration of a SQL operation issued by Datasette", + explicit_bucket_boundaries_advisory=M_OPERATION_DURATION.buckets, ) write_queue_wait = meter.create_histogram( - "datasette.write.queue_wait", - unit="s", + M_WRITE_QUEUE_WAIT, + unit=M_WRITE_QUEUE_WAIT.unit, description=( "Time a write spent queued behind the single write thread for its database" ), + explicit_bucket_boundaries_advisory=M_WRITE_QUEUE_WAIT.buckets, ) queries_interrupted = meter.create_counter( - "datasette.sql.queries.interrupted", - unit="{query}", + M_QUERIES_INTERRUPTED, + unit=M_QUERIES_INTERRUPTED.unit, description=( "Queries cancelled for exceeding sql_time_limit_ms. Not derivable from " "spans under sampling, and the signal that a time limit is too tight" @@ -568,36 +579,36 @@ def observe_open_connections(options=None): sql_thread_limit_gauge = meter.create_observable_gauge( - "datasette.sql.threads.limit", + M_THREADS_LIMIT, callbacks=[observe_sql_thread_limit], - unit="{thread}", + unit=M_THREADS_LIMIT.unit, description="Maximum concurrent read queries (the num_sql_threads setting)", ) sql_thread_queue_depth_gauge = meter.create_observable_gauge( - "datasette.sql.threads.queue_depth", + M_THREADS_QUEUE_DEPTH, callbacks=[observe_sql_thread_queue_depth], - unit="{query}", + unit=M_THREADS_QUEUE_DEPTH.unit, description="Read queries waiting for a free thread in the shared SQL pool", ) pending_queries_gauge = meter.create_observable_gauge( - "datasette.sql.queries.pending", + M_QUERIES_PENDING, callbacks=[observe_pending_queries], - unit="{query}", + unit=M_QUERIES_PENDING.unit, description="Read queries submitted to the pool and not yet complete", ) write_queue_depth_gauge = meter.create_observable_gauge( - "datasette.write.queue_depth", + M_WRITE_QUEUE_DEPTH, callbacks=[observe_write_queue_depth], - unit="{write}", + unit=M_WRITE_QUEUE_DEPTH.unit, description="Writes queued behind a database's single write thread", ) open_connections_gauge = meter.create_observable_gauge( - "datasette.connections.open", + M_CONNECTIONS_OPEN, callbacks=[observe_open_connections], - unit="{connection}", + unit=M_CONNECTIONS_OPEN.unit, description="Open SQLite file connections tracked for closing", ) diff --git a/datasette/telemetry_registry.py b/datasette/telemetry_registry.py index 4e750605..7ce8de7d 100644 --- a/datasette/telemetry_registry.py +++ b/datasette/telemetry_registry.py @@ -84,6 +84,33 @@ class SpanName(str): return f"SpanName({str(self)!r})" +class MetricName(str): + "A metric name, carrying its instrument kind, unit and attributes." + + __slots__ = ("attributes", "buckets", "description", "kind", "unit") + + def __new__(cls, name, kind, unit, description, attributes=(), buckets=None): + self = super().__new__(cls, name) + self.kind = kind + self.unit = unit + self.description = description + self.attributes = tuple(attributes) + # Explicit histogram bucket boundaries, for histograms only. Passed to + # create_histogram() as explicit_bucket_boundaries_advisory and + # published in the generated docs, since an operator writing a + # histogram_quantile() query needs to know them. + self.buckets = tuple(buckets) if buckets is not None else None + return self + + def __repr__(self): + return f"MetricName({str(self)!r})" + + +COUNTER = "Counter" +HISTOGRAM = "Histogram" +GAUGE = "Observable gauge" + + # --- Attributes ----------------------------------------------------------- # # Shared attributes are defined once and referenced by every span that sets @@ -152,6 +179,7 @@ ERROR_TYPE = Attribute( DB_SYSTEM = Attribute("db.system", "Always ``sqlite``.") DB_NAMESPACE = Attribute("db.namespace", "Name of the database being queried.") +OPERATION = Attribute("datasette.operation", "``read`` or ``write``.") DB_QUERY_TEXT = Attribute( "db.query.text", "The SQL, truncated to 2048 characters. Never the parameter values.", @@ -386,3 +414,113 @@ def attribute_allowed(span, emitted_key): if span is None: return False return emitted_key in span.attributes + + +# --- Metrics -------------------------------------------------------------- + +# Every duration histogram here is in seconds, and OpenTelemetry's default +# bucket boundaries are tuned for milliseconds - their first non-zero boundary +# is 5, so without explicit boundaries every SQLite query lands in the single +# (0, 5] second bucket and every quantile query returns noise. +# +# These are the OpenTelemetry semantic conventions' recommended boundaries for +# db.client.operation.duration, in seconds, plus 0.0001 and 0.0005 at the +# bottom. The deviation is deliberate: those boundaries assume a network +# database client, whereas SQLite is in-process and a large fraction of real +# queries run in 30-80us, which would otherwise all pile into the first +# bucket and be indistinguishable from each other. +# +# One shared list is used for every duration histogram rather than a tailored +# list each, so that dashboards stay comparable and a queue wait can be read +# against the query duration it delays. It already spans 100us to 10s, which +# covers both a fast in-process read and a write queued behind contention. +DURATION_BUCKETS = (0.0001, 0.0005, 0.001, 0.005, 0.01, 0.05, 0.1, 0.5, 1, 5, 10) + +M_OPERATION_DURATION = MetricName( + "db.client.operation.duration", + HISTOGRAM, + "s", + "Duration of a SQL operation. The standard OpenTelemetry semantic " + "convention metric, and the one that survives trace sampling.", + (DB_SYSTEM, DB_NAMESPACE, OPERATION, ERROR_TYPE), + buckets=DURATION_BUCKETS, +) + +M_WRITE_QUEUE_WAIT = MetricName( + "datasette.write.queue_wait", + HISTOGRAM, + "s", + "Time each write waited in its database's write queue. The metric " + "counterpart of the ``db.write.queue_wait`` span.", + (DB_NAMESPACE,), + buckets=DURATION_BUCKETS, +) + +M_QUERIES_INTERRUPTED = MetricName( + "datasette.sql.queries.interrupted", + COUNTER, + "{query}", + "Queries cancelled for exceeding :ref:`setting_sql_time_limit_ms`. Worth " + "alerting on: a rising rate means the limit is too tight or a table has " + "outgrown its queries. A caller that opted into a deliberately shorter " + "budget - facet suggestion, for example - is not counted, for the same " + "reason its timeout is not a span error.", + (DB_NAMESPACE,), +) + +M_THREADS_LIMIT = MetricName( + "datasette.sql.threads.limit", + GAUGE, + "{thread}", + "Maximum concurrent read queries - the :ref:`setting_num_sql_threads` " + "value. Not reported when ``num_sql_threads`` is ``0``, since then queries " + "run on the event loop and there is no pool.", +) + +M_THREADS_QUEUE_DEPTH = MetricName( + "datasette.sql.threads.queue_depth", + GAUGE, + "{query}", + "Read queries waiting for a free thread. **This is the saturation " + "signal** - sustained above zero means requests are queueing on " + "``num_sql_threads``.", +) + +M_QUERIES_PENDING = MetricName( + "datasette.sql.queries.pending", + GAUGE, + "{query}", + "Read queries submitted to the pool and not yet complete. Summed across " + "databases and compared against the thread limit, this is pool " + "utilisation.", + (DB_NAMESPACE,), +) + +M_WRITE_QUEUE_DEPTH = MetricName( + "datasette.write.queue_depth", + GAUGE, + "{write}", + "Writes queued behind a database's single write thread. Backpressure that " + "raising ``num_sql_threads`` cannot relieve. Not reported for a database " + "that has never been written to.", + (DB_NAMESPACE,), +) + +M_CONNECTIONS_OPEN = MetricName( + "datasette.connections.open", + GAUGE, + "{connection}", + "Open SQLite file connections currently tracked for closing.", + (DB_NAMESPACE,), +) + +METRICS = ( + M_OPERATION_DURATION, + M_WRITE_QUEUE_WAIT, + M_QUERIES_INTERRUPTED, + M_THREADS_LIMIT, + M_THREADS_QUEUE_DEPTH, + M_QUERIES_PENDING, + M_WRITE_QUEUE_DEPTH, + M_CONNECTIONS_OPEN, +) diff --git a/docs/internals.rst b/docs/internals.rst index 96404966..b4f82c4d 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -2354,7 +2354,7 @@ Spans do not appear immediately. The SDK's default ``BatchSpanProcessor`` flushe 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_LOGS_EXPORTER=none`` is worth doing unless your backend accepts logs too - ``opentelemetry-distro`` defaults every signal to OTLP, and a backend that does not take a signal will reject it noisily. Datasette emits no logs through OpenTelemetry; it does emit metrics (see :ref:`internals_telemetry_metrics`), so set ``OTEL_METRICS_EXPORTER=none`` only if your backend does not accept them. Span reference -------------- @@ -2439,6 +2439,85 @@ That is the route's compiled regular expression, not a prettified ``/{database}/ .. [[[end]]] +.. _internals_telemetry_metrics: + +Metric reference +---------------- + +Spans describe events; metrics describe levels and rates. "Am I saturating my :ref:`setting_num_sql_threads` threads right now?" cannot be answered by any span, because it is a level sampled at collection time - and it is usually the first thing worth knowing about a busy Datasette, since ``num_sql_threads`` defaults to ``3``. Metrics also survive trace sampling: an operator keeping 1% of traces still gets 100% of every histogram and counter below. + +As with spans, core emits these through the OpenTelemetry API only. Without a ``MeterProvider`` every instrument is a no-op, and the observable-gauge callbacks are never invoked at all, so an uninstrumented install pays nothing for them. + +Every duration histogram is in **seconds**, with explicit bucket boundaries chosen for an in-process database - OpenTelemetry's default boundaries are tuned for milliseconds and would file every SQLite query into a single bucket, making quantile queries meaningless. The boundaries are listed with each histogram because a ``histogram_quantile()`` query is only as good as the buckets underneath it. + +This reference is generated from ``datasette/telemetry_registry.py``, like the span reference above. + +.. [[[cog + from telemetry_doc import metrics + metrics(cog) +.. ]]] + +``db.client.operation.duration`` + Histogram, unit ``s``. Duration of a SQL operation. The standard OpenTelemetry semantic convention metric, and the one that survives trace sampling. + + Bucket boundaries: ``0.0001``, ``0.0005``, ``0.001``, ``0.005``, ``0.01``, ``0.05``, ``0.1``, ``0.5``, ``1``, ``5``, ``10``. + + Attributes: + + - ``db.system`` - Always ``sqlite``. + - ``db.namespace`` - Name of the database being queried. + - ``datasette.operation`` - ``read`` or ``write``. + - ``error.type`` - Set when the request failed: the exception class name if one escaped the application, otherwise the status code as a string for a 5xx response. A 4xx does **not** set this and does not set an error status - per semantic conventions a client error is not a server span's failure. + +``datasette.write.queue_wait`` + Histogram, unit ``s``. Time each write waited in its database's write queue. The metric counterpart of the ``db.write.queue_wait`` span. + + Bucket boundaries: ``0.0001``, ``0.0005``, ``0.001``, ``0.005``, ``0.01``, ``0.05``, ``0.1``, ``0.5``, ``1``, ``5``, ``10``. + + Attributes: + + - ``db.namespace`` - Name of the database being queried. + +``datasette.sql.queries.interrupted`` + Counter, unit ``{query}``. Queries cancelled for exceeding :ref:`setting_sql_time_limit_ms`. Worth alerting on: a rising rate means the limit is too tight or a table has outgrown its queries. A caller that opted into a deliberately shorter budget - facet suggestion, for example - is not counted, for the same reason its timeout is not a span error. + + Attributes: + + - ``db.namespace`` - Name of the database being queried. + +``datasette.sql.threads.limit`` + Observable gauge, unit ``{thread}``. Maximum concurrent read queries - the :ref:`setting_num_sql_threads` value. Not reported when ``num_sql_threads`` is ``0``, since then queries run on the event loop and there is no pool. + + No attributes. + +``datasette.sql.threads.queue_depth`` + Observable gauge, unit ``{query}``. Read queries waiting for a free thread. **This is the saturation signal** - sustained above zero means requests are queueing on ``num_sql_threads``. + + No attributes. + +``datasette.sql.queries.pending`` + Observable gauge, unit ``{query}``. Read queries submitted to the pool and not yet complete. Summed across databases and compared against the thread limit, this is pool utilisation. + + Attributes: + + - ``db.namespace`` - Name of the database being queried. + +``datasette.write.queue_depth`` + Observable gauge, unit ``{write}``. Writes queued behind a database's single write thread. Backpressure that raising ``num_sql_threads`` cannot relieve. Not reported for a database that has never been written to. + + Attributes: + + - ``db.namespace`` - Name of the database being queried. + +``datasette.connections.open`` + Observable gauge, unit ``{connection}``. Open SQLite file connections currently tracked for closing. + + Attributes: + + - ``db.namespace`` - Name of the database being queried. + +.. [[[end]]] + .. _internals_telemetry_requests: Requests and inbound trace context diff --git a/docs/telemetry_doc.py b/docs/telemetry_doc.py index 3551ef0e..500d11c7 100644 --- a/docs/telemetry_doc.py +++ b/docs/telemetry_doc.py @@ -35,3 +35,22 @@ def spans(cog): if span.kind != SpanKind.INTERNAL: cog.out(f" Kind: ``{span.kind.name}``.\n\n") _attribute_lines(cog, span.attributes) + + +def metrics(cog): + from datasette.telemetry_registry import METRICS + + cog.out("\n") + for metric in METRICS: + cog.out(f"``{metric}``\n") + cog.out(f" {metric.kind}, unit ``{metric.unit}``. {metric.description}\n\n") + if metric.buckets: + boundaries = ", ".join(f"``{boundary}``" for boundary in metric.buckets) + cog.out(f" Bucket boundaries: {boundaries}.\n\n") + if metric.attributes: + cog.out(" Attributes:\n\n") + for attribute in metric.attributes: + cog.out(f" - ``{attribute}`` - {attribute.description}\n") + cog.out("\n") + else: + cog.out(" No attributes.\n\n") diff --git a/tests/test_telemetry_metrics.py b/tests/test_telemetry_metrics.py index 6d1efd1f..1422fbcd 100644 --- a/tests/test_telemetry_metrics.py +++ b/tests/test_telemetry_metrics.py @@ -321,3 +321,67 @@ def test_registry_holds_instances_weakly(): gc.collect() assert ref() is None assert not any(isinstance(ds, FakeDatasette) for ds in telemetry._live_instances()) + + +HISTOGRAM_PROBES = [ + # (instrument attribute on telemetry, metric name, isolating attributes) + ( + "sql_operation_duration", + "db.client.operation.duration", + {"db.namespace": "bucket_probe_operation"}, + ), + ( + "write_queue_wait", + "datasette.write.queue_wait", + {"db.namespace": "bucket_probe_queue_wait"}, + ), +] + +# One value inside each of six distinct registry buckets. Under OpenTelemetry's +# default boundaries - [0, 5, 10, 25, ...], meant for milliseconds - the first +# five of these all land in (0, 5] and only 7.0 lands elsewhere, so the +# "occupies six buckets" assertion below fails if the advisory is ever dropped. +SPREAD = [0.00005, 0.0003, 0.002, 0.03, 0.8, 7.0] + + +@pytest.mark.parametrize( + "instrument_name,metric_name,attributes", + HISTOGRAM_PROBES, + ids=[metric for _, metric, _ in HISTOGRAM_PROBES], +) +def test_histograms_spread_values_across_buckets( + otel_metrics, instrument_name, metric_name, attributes +): + """ + The registry's boundaries reach the SDK, and a realistic spread of + seconds-scale durations occupies more than one bucket. + + Recording onto the instrument directly rather than driving a workload is + deliberate: real durations here are all tens of microseconds and would + share a bucket no matter what the boundaries were, which is exactly the + situation this test exists to detect. + + `explicit_bounds` is compared against the registry rather than against the + instrument's own configuration - the instrument is built *from* the + registry, so that comparison would be a value against itself. What is + checked here is that the advisory survived the trip through the SDK. + """ + from datasette.telemetry_registry import METRICS + + metric = next(m for m in METRICS if m == metric_name) + instrument = getattr(telemetry, instrument_name) + for value in SPREAD: + instrument.record(value, attributes) + + otel_metrics.collect() + point = otel_metrics.point(metric_name, attributes) + + assert ( + tuple(point.explicit_bounds) == metric.buckets + ), "the registry's boundaries did not reach the SDK" + assert point.count == len(SPREAD) + occupied = [count for count in point.bucket_counts if count] + assert len(occupied) == len(SPREAD), ( + f"expected each of {SPREAD} in its own bucket, got bucket counts " + f"{list(point.bucket_counts)} for bounds {list(point.explicit_bounds)}" + ) diff --git a/tests/test_telemetry_registry.py b/tests/test_telemetry_registry.py index 398f72aa..7e807c18 100644 --- a/tests/test_telemetry_registry.py +++ b/tests/test_telemetry_registry.py @@ -382,6 +382,29 @@ def test_registry_entries_are_usable_as_plain_strings(): assert f"{reg.DB_QUERY}.execute" == "db.query.execute" +def test_every_histogram_declares_bucket_boundaries(): + """ + Every histogram must carry explicit boundaries, and only histograms may. + + OpenTelemetry's default boundaries start at 5 and are meant for + milliseconds, so a seconds-valued histogram that inherits them records + everything into one bucket. This is a registry self-consistency check, not + a check that the boundaries reached the SDK - for that see + `test_histograms_spread_values_across_buckets` in test_telemetry_metrics.py. + """ + for metric in reg.METRICS: + if metric.kind == reg.HISTOGRAM: + assert metric.buckets, f"{metric} is a histogram with no boundaries" + assert list(metric.buckets) == sorted( + set(metric.buckets) + ), f"{metric} boundaries must be ascending and unique" + assert metric.buckets[0] > 0, f"{metric} has a non-positive boundary" + else: + assert ( + metric.buckets is None + ), f"{metric} is a {metric.kind} and cannot have bucket boundaries" + + def test_dynamic_span_lookup(): """ `dynamic=True` matching, which is how the request span resolves.