Review polish: fix stale exemplar context, dedupe rationales, close test gaps

- The exemplars docs described "the pinned opentelemetry-exporter-prometheus"
  and "Datasette's own Prometheus exporter" - context from demo/plugin work
  that is no longer part of this stack. Reworded to stand alone.
- Saturate a num_sql_threads=1 pool and assert the queue-depth gauge reads
  above zero - the headline alerting metric previously only had an absence
  test, and this also pins the private ThreadPoolExecutor._work_queue
  attribute it depends on.
- Pin error.type on the write path of db.client.operation.duration - the
  write wrappers time a different code path than the read one already tested.
- Isolate the non-threaded-mode gauge test from other live instances instead
  of comparing global observation counts, which a GC pass could shift.
- Halve the metrics banner, point conftest's meter note at it, compact the
  interrupted-counter call-site comment to a registry pointer, note why
  instrument and registry descriptions are separate strings, and stop
  calling the metric dimension a "later phase" now that metrics shipped.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_012U7coQfVu8nK2R4q2mCULA
This commit is contained in:
Alex Garcia 2026-09-02 11:31:12 -07:00
commit 721cc6d9f9
5 changed files with 104 additions and 42 deletions

View file

@ -925,13 +925,9 @@ class Database:
if not timeout_expected:
span.set_status(Status(StatusCode.ERROR, str(e)))
span.record_exception(e)
# A counter rather than only a span, because this is the
# one thing an operator wants a rate and an alert on, and
# spans under a 1% sampler cannot provide either. An
# expected timeout - a caller that opted into a shorter
# budget, like facet suggestion - is not counted, for the
# same reason it is not a span error: it fires routinely
# by design and would drown the signal this exists for.
# Expected timeouts (a caller that opted into a shorter
# budget, like facet suggestion) are not counted - see
# the M_QUERIES_INTERRUPTED registry entry for why.
record_query_interrupted(self.name)
raise
except Exception as e:

View file

@ -109,11 +109,11 @@ def callback_name(fn) -> str:
# fixed allowlist - deliberately not a parse.
#
# This runs against arbitrary user-supplied SQL (the `?sql=` query string,
# canned queries, anything typed into the query editor), and the attribute is
# a candidate dimension on a query-duration metric in a later phase. A metric
# series is keyed by its attribute values, so echoing back an arbitrary first
# token would let one visitor's typo mint a new, permanent series. The
# allowlist bounds that at a fixed, small set regardless of what anyone sends.
# canned queries, anything typed into the query editor), and the attribute
# has to stay safe to use as a metric dimension. A metric series is keyed by
# its attribute values, so echoing back an arbitrary first token would let
# one visitor's typo mint a new, permanent series. The allowlist bounds that
# at a fixed, small set regardless of what anyone sends.
DB_OPERATION_ALLOWLIST = frozenset(
{
"SELECT",
@ -382,23 +382,12 @@ class TelemetryMiddleware:
# --- Metrics --------------------------------------------------------------
#
# Spans answer "what happened during this request". They cannot answer "am I
# saturating my 3 SQL threads right now", because that is a gauge: a level
# sampled at collection time, not an event with a duration. It is also the
# single most useful operational question about a Datasette deployment, since
# num_sql_threads defaults to 3 and every read query in the process competes
# for those threads.
#
# Two shapes are used here:
#
# Observable gauges - a callback the SDK invokes on its own collection
# cycle. Nothing is computed unless something is collecting, so the default
# no-provider install pays literally nothing for them.
#
# Synchronous histograms/counters - recorded inline on the query path. These
# survive trace sampling, which spans do not: an operator sampling 1% of
# traces still gets 100% of the latency distribution and the interrupted
# count.
# Two shapes. Observable gauges - a callback the SDK invokes on its own
# collection cycle, so a no-provider install never runs them - answer level
# questions no span can, like "am I saturating my SQL threads right now".
# Synchronous histograms/counters are recorded inline on the query path and
# survive trace sampling: 1% of traces still means 100% of the latency
# distribution. Why each metric exists is documented on its registry entry.
#
# Note a real difference from tracing: `_ProxyMeter` and its instruments
# forward to a provider installed *after* they were created, whereas
@ -415,6 +404,10 @@ def _duration_attributes(database_name, operation):
}
# Each instrument passes the SDK a short plain-text description; the registry
# entry for the same metric carries a longer RST one for the generated docs
# (it can use `:ref:` roles, which an exported description string cannot).
sql_operation_duration = meter.create_histogram(
M_OPERATION_DURATION,
unit=M_OPERATION_DURATION.unit,

View file

@ -2552,7 +2552,7 @@ Exemplars are kept per histogram bucket - the SDK's default reservoir for an exp
Correcting the bucket boundaries had a second effect beyond fixing the quantiles: it also multiplied the number of traces reachable from this metric, one to four for this workload.
Which export path you use matters here. The OTLP exporter carries exemplars through unchanged. The pinned ``opentelemetry-exporter-prometheus`` (``0.65b0``) does not: the string ``exemplar`` does not appear anywhere in its source, and an OpenMetrics scrape of the workload above through that exporter contained zero exemplar markers - even though ``prometheus-client`` (``0.26.0``), the library it depends on for OpenMetrics output, supports the syntax. If exemplars need to reach Prometheus, the path that works is an OTLP collector writing to Prometheus, not Datasette's own Prometheus exporter. On that path, the Prometheus server needs `--enable-feature=exemplar-storage <https://prometheus.io/docs/prometheus/latest/feature_flags/>`__, and the scrape itself must use the OpenMetrics exposition format - Prometheus's default text format has no syntax for exemplars at all. Grafana then needs the Prometheus data source's `exemplar configuration <https://grafana.com/docs/grafana/latest/datasources/prometheus/configure/>`__ (``exemplarTraceIdDestinations``) pointed at a tracing data source before it will draw an exemplar as a clickable point rather than an ordinary sample.
Which export path you use matters here. The OTLP exporter carries exemplars through unchanged. ``opentelemetry-exporter-prometheus`` (as of ``0.65b0``) does not: the string ``exemplar`` does not appear anywhere in its source, and an OpenMetrics scrape of the workload above through that exporter contained zero exemplar markers - even though ``prometheus-client`` (``0.26.0``), the library it depends on for OpenMetrics output, supports the syntax. If exemplars need to reach Prometheus, the path that works is an OTLP collector writing to Prometheus, not a plugin scraping through that exporter. On that path, the Prometheus server needs `--enable-feature=exemplar-storage <https://prometheus.io/docs/prometheus/latest/feature_flags/>`__, and the scrape itself must use the OpenMetrics exposition format - Prometheus's default text format has no syntax for exemplars at all. Grafana then needs the Prometheus data source's `exemplar configuration <https://grafana.com/docs/grafana/latest/datasources/prometheus/configure/>`__ (``exemplarTraceIdDestinations``) pointed at a tracing data source before it will draw an exemplar as a clickable point rather than an ordinary sample.
An exemplar can only exist for a trace that was sampled. The SDK's default exemplar filter only records one when the measurement happens inside a sampled span, and produces no exemplar at all rather than a link to a trace that was never kept. Verified: with the tracer provider's sampler set to ``ALWAYS_OFF``, the same four-query workload produced ``exemplars: 0`` on every data point. At 1% head sampling, 99% of measurements contribute no exemplar - but every exemplar you do get is guaranteed to resolve to a trace that exists.

View file

@ -123,12 +123,10 @@ def _otel_meter_provider():
Install a real OTel SDK MeterProvider + InMemoryMetricReader once per
process.
Unlike the tracer, ordering is not load-bearing here: `_ProxyMeter` and
the `_ProxyInstrument`s it hands out forward to a provider installed
*after* they were created, whereas `ProxyTracer` permanently caches the
first concrete tracer it resolves. This fixture is still session-scoped
and autouse for symmetry, and so that a single reader collects for the
whole run.
Unlike the tracer, ordering is not load-bearing here - see the metrics
banner in `datasette/telemetry.py` for the `_ProxyMeter`-vs-`ProxyTracer`
difference. This fixture is still session-scoped and autouse for
symmetry, and so that a single reader collects for the whole run.
DELTA temporality is chosen for counters and histograms so that each
collection reports only what happened since the previous one. With the

View file

@ -17,6 +17,8 @@ Two layers are tested separately and deliberately:
"""
import asyncio
import threading
import weakref
import pytest
@ -74,22 +76,71 @@ async def test_no_thread_gauges_in_non_threaded_mode():
num_sql_threads=0 means there is no pool at all, so the pool gauges must
skip the instance rather than report a bogus limit of 0.
The pool gauges carry no attributes, so the assertion is that adding this
instance produces no *additional* observations.
The pool gauges carry no attributes, so the live-instance registry is
narrowed to just this instance for the assertion - counting global
observations instead would let an unrelated instance being garbage
collected mid-test shift the baseline.
"""
before_limits = len(list(telemetry.observe_sql_thread_limit()))
before_depths = len(list(telemetry.observe_sql_thread_queue_depth()))
ds = Datasette(memory=True, settings={"num_sql_threads": 0})
try:
assert ds.executor is None
assert len(list(telemetry.observe_sql_thread_limit())) == before_limits
assert len(list(telemetry.observe_sql_thread_queue_depth())) == before_depths
original = telemetry._live_datasettes
telemetry._live_datasettes = weakref.WeakSet([ds])
try:
assert list(telemetry.observe_sql_thread_limit()) == []
assert list(telemetry.observe_sql_thread_queue_depth()) == []
finally:
telemetry._live_datasettes = original
# Per-database gauges are unaffected - they do not depend on the pool.
assert observations(telemetry.observe_pending_queries, ds)
finally:
ds.close()
@pytest.mark.asyncio
async def test_thread_queue_depth_gauge_reports_saturation():
"""
The headline alerting metric must actually read above zero when reads
queue behind num_sql_threads. This also pins the private
`ThreadPoolExecutor._work_queue` attribute the callback depends on: if a
stdlib rename ever removes it, this fails instead of the metric silently
vanishing (the callback tolerates its absence at collection time).
"""
ds = Datasette(memory=True, settings={"num_sql_threads": 1})
db = ds.add_memory_database("metrics_saturation_db")
entered = threading.Event()
release = threading.Event()
def blocker(conn):
entered.set()
assert release.wait(timeout=10)
return 1
try:
first = asyncio.ensure_future(db.execute_fn(blocker))
# Wait until the blocker owns the pool's only thread.
await asyncio.get_running_loop().run_in_executor(None, entered.wait, 10)
second = asyncio.ensure_future(db.execute_fn(lambda conn: 2))
# The second submission lands in the executor's queue on the next
# event-loop turn; poll briefly rather than assume the timing.
depths = []
for _ in range(500):
depths = [
value
for _, value in observations(telemetry.observe_sql_thread_queue_depth)
]
if any(value >= 1 for value in depths):
break
await asyncio.sleep(0.01)
assert any(value >= 1 for value in depths), depths
release.set()
assert await first == 1
assert await second == 2
finally:
release.set()
ds.close()
@pytest.mark.asyncio
async def test_pending_queries_gauge_tracks_in_flight_queries(metrics_ds):
db = metrics_ds.get_database("metrics_test_db")
@ -224,6 +275,30 @@ async def test_operation_duration_records_error_type(otel_metrics):
ds.close()
@pytest.mark.asyncio
async def test_operation_duration_records_write_error_type(otel_metrics):
"""
Same as the read-path error test, but the write wrappers time a different
code path - `execute_write_fn`, the write thread and its reply future -
so error propagation through them is pinned separately.
"""
ds = Datasette(memory=True)
ds.add_memory_database("duration_write_error_db")
try:
db = ds.get_database("duration_write_error_db")
with pytest.raises(sqlite3.OperationalError):
await db.execute_write("insert into nope values (1)")
otel_metrics.collect()
point = otel_metrics.point(
"db.client.operation.duration",
{"db.namespace": "duration_write_error_db", "datasette.operation": "write"},
)
assert point.count == 1
assert dict(point.attributes)["error.type"] == "OperationalError"
finally:
ds.close()
@pytest.mark.asyncio
async def test_write_queue_wait_histogram(otel_metrics):
ds = Datasette(memory=True)