OpenTelemetry tracing for the database layer

[asg017]

This is the first PR for the #1730 OTel feature. It adds the appropriate lightweight OTel API for recording spans, and hooks it up to just raw SQL queries for now. This allows one to observe what SQL queries take up the most time for a Datasette application, but it's missing other important spans/traces (ex HTTP requests, facets, plugin hooks, startup times, etc). Those will come in future PRs.

🤖 Claude-generated PR description

Adds OpenTelemetry spans to Datasette's database layer.

This addresses #1730 — "SQL tracing should much more closely track the SQL query execution" —
by splitting the measurement in two: db.query covers the full round trip a caller experiences, and
db.query.execute covers only the work inside the SQL worker thread. The gap between them is
exactly the thread-pool wait that the current tracer folds invisibly into one number, which is what
that issue is about.

I've said "addresses" rather than "closes" deliberately: this adds a second, correct measurement
alongside the existing tracer rather than fixing the existing one. If you'd rather #1730 stay open
until the old tracer is dealt with, that seems right to me — it would close with the third PR in
this series.

Nothing is removed. ?_trace=1 and trace_debug still work exactly as before. The cost of that,
stated up front: for one release cycle the db.execute() path carries both instrumentations. I
think that's worth it to keep the removal a separate decision, but it is a real if small cost.

 datasette/app.py                 |  116 +++--
 datasette/database.py            |  484 +++++++++++++++---
 datasette/telemetry.py           |  117 +++++
 datasette/telemetry_registry.py  |  273 ++++++++++
 datasette/views/row.py           |    9 +-
 datasette/views/table.py         |   16 +-
 docs/changelog.rst               |   10 +
 docs/internals.rst               |  130 +++++
 docs/telemetry_doc.py            |   37 ++
 pyproject.toml                   |    2 +
 tests/conftest.py                |   62 +++
 tests/test_internals_database.py |  109 ++++
 tests/test_telemetry.py          | 1015 ++++++++++++++++++++++++++++++++++++++
 tests/test_telemetry_registry.py |  309 ++++++++++++
 14 files changed, 2552 insertions(+), 137 deletions(-)

About 1,500 of those lines are tests and another 440 are the span registry plus the docs
generated from it. The instrumentation itself is a few hundred lines across database.py and
app.py.

The design, in one paragraph

Datasette core depends on opentelemetry-api only and is a pure telemetry producer: it never
creates a TracerProvider, configures an exporter, or sets a sampler. Turning telemetry on is
entirely the job of whoever runs Datasette, normally via opentelemetry-instrument. With no
provider installed, every span is a NonRecordingSpan — see the benchmark below for what that
actually costs, measured rather than asserted.

That constraint is load-bearing rather than stylistic, and there's a test enforcing it
(test_datasette_package_never_imports_the_sdk). An earlier draft of this work had core own a
provider so it could render traces into a page, and that single requirement produced three problems
I found in self-review: a cross-request span leak that could expose another user's SQL text, a test
suite that permanently poisoned the process-global provider with no possible teardown (the SDK has
no remove_span_processor, and once a real provider exists ProxyTracer caches the concrete
tracer it resolved and ignores any later one), and a sampling environment variable that silently
blanked output. Not owning a provider dissolves all three.

To be precise about that caching, since a stronger version of the claim is easy to reach for and
is wrong: ProxyTracer does not cache the no-op tracer. Checked against opentelemetry-api
1.44, ProxyTracer._tracer returns self._noop_tracer without assigning _real_tracer when no
provider is set. So spans emitted before a provider exists are simply not recorded; they do not
poison the tracer for the rest of the process.

Spans

Span	Kind	What
db.query	CLIENT	A SQL operation, covering the full round trip including queue time
db.query.execute	INTERNAL	The read executing inside a worker thread
db.write.queue_wait	INTERNAL	Time a write spent in its database's write queue
db.write.execute	INTERNAL	The write executing on the write thread
datasette.startup	INTERNAL	invoke_startup(), once per process

Attributes follow OTel semantic conventions where they exist (db.system, db.namespace,
db.query.text, db.operation.name, db.collection.name) and a datasette.* prefix otherwise.
The instrumentation scope declares schema URL https://opentelemetry.io/schemas/1.29.0 — not the
latest, deliberately: 1.29.0 is the highest version at which every name emitted is the current
spelling. db.system and code.function were renamed in 1.30.0, so declaring anything later would
be a false machine-readable claim and would stop consumers translating those names forward.

Only db.query is CLIENT. Its children stay INTERNAL because they are Datasette's decomposition of
one logical query, not three database calls, and db.write.queue_wait touches no database at all.

SQL text is truncated to 2048 characters — on a public instance it is attacker-controlled and
unbounded. Parameter values are not recorded at all in this PR, only a count. No actor
identifiers are recorded.

db.operation.name is the statement's leading keyword matched against a fixed 13-word allowlist,
never a parse. Anything unrecognised gets no attribute rather than a wrong one. A statement starting
with a CTE therefore reports WITH rather than the operation inside it, which is a real limitation
and a substantial share of Datasette's own reads take that form. The allowlist is deliberate: the
same attribute goes on a metric in a later phase, and echoing back an arbitrary first token from
attacker-controlled SQL would let a visitor's typo mint a permanent metric series.

Things worth reviewing carefully

A new public API argument. db.execute() gains a table= keyword argument, used to set
db.collection.name. Table names are never derived from the SQL — deriving them would be a parse,
and on an instance where anyone can create a table the dimension has no ceiling. If you'd rather not
add public API for a telemetry reason, I can drop db.collection.name and keep db.operation.name,
which needs nothing new.

copy_context() propagates more than OpenTelemetry. Context is carried across five thread
boundaries with contextvars.copy_context(), which copies every ContextVar, not just OTel's.
Datasette has others — _skip_permission_checks and _permission_check_cache
(datasette/permissions.py), _in_datasette_client (app.py). Those values now flow into SQL
worker threads where they previously did not. I believe this is benign and possibly a latent fix,
but it is a behaviour change outside telemetry and I'd rather flag it than have it found in review.
If you'd prefer, I can propagate only the OTel context.

A fresh copy_context() per submit is required. Reusing one raises RuntimeError: cannot enter context ... already entered under concurrency.

Attach/detach discipline on the write thread. It is long-lived and shared, so a leaked context
token poisons it for every subsequent write. A wrong-token detach only logs — it does not raise
— so this cannot be validated by "does it throw". test_write_thread_context_is_detached_between_tasks
asserts it directly by carrying a plain context value through several writes and checking the
observed sequence.

block=False writes are linked, not parented. Measured: a block=False write's spans end ~50ms
after the enqueueing request's span has already closed, because parenting asserts containment and
the request causes the write without containing it. Those spans are roots carrying an OTel link back
to the enqueueing span. The accepted cost is that a linked span doesn't appear in the request's
waterfall in most trace UIs — for a fire-and-forget write whose latency the request never pays,
being absent beats being drawn wrongly.

Expected SQL errors are not marked as errors. ArrayFacet.suggest() probes every column with
json_type() specifically to find out which ones raise; Datasette passes log_sql_errors=False to
say "failure is the expected answer here". Those spans leave status UNSET and set
datasette.sql_error_suppressed, so they stay discoverable without reading as failures. Without
this, a plain table page produced 4 error spans out of 225 and any alerting keyed on span status
would fire constantly.

The same reasoning applies to timeouts. A caller that passes a custom_time_limit shorter than
the instance-wide sql_time_limit_ms is saying "this may not finish, and that is an answer I can
use" — table_counts() stores None, facet suggestion moves to the next column, autocomplete
falls back to a prefix query. Those spans set datasette.interrupted but leave status UNSET.
Without it the homepage alone emitted one red span per table on every hit, since it counts every
table under a 10ms budget.

A test ordering hack in tests/conftest.py, which you may reasonably want to argue with.
test_datasette_package_never_imports_the_sdk shells out to a fresh interpreter to prove
import datasette does not pull in the SDK. Run late in a serial suite on macOS it segfaults —
SIGSEGV/SIGBUS inside subprocess's _execute_child — so it is moved to the front with the
existing move_to_front() helper that test_cli, test_black and seven others already use.

This is not caused by anything in this PR. I reproduced it on unmodified main at e889403 with
a bare subprocess call placed at the same point in the run: by then the pytest process holds
enough threads that the fork half of fork+exec crashes CPython 3.13.1 on macOS. Linux CI will
never hit it, because CPython uses posix_spawn there. I have gone with the existing local
convention rather than adding a new mechanism, but if you would rather the test did not get
special ordering treatment, it can be marked serial instead.

Dependency

Adds opentelemetry-api to runtime dependencies. At 1.44 it brings only typing-extensions, and it
supports Python 3.10–3.14 — exactly this repo's CI matrix. No SDK, no exporter, no collector; those
are the operator's business.

Real output

All of the following was captured on this branch by installing an SDK TracerProvider with a
SimpleSpanProcessor and an InMemorySpanExporter, then making real requests. Times are
milliseconds.

invoke_startup(), one trace per process. Every span startup creates nests under it, so a
trace UI shows one startup trace rather than a wall of unrelated single-span ones:

                                                        start      dur
datasette.startup                                        0.00     7.48  |████████████████████████████████████████████|
  db.write.queue_wait                                    0.15     0.55  |███                                         |
  db.write.execute                                       0.72     4.88  |    ████████████████████████████            |
  db.query                                               5.69     0.39  |                                 ██         |
    db.query.execute                                     5.84     0.19  |                                  █         |
  db.query                                               6.11     0.11  |                                   █        |
    db.query.execute                                     6.13     0.02  |                                    █       |
  db.query                                               6.24     0.09  |                                    █       |
    db.query.execute                                     6.28     0.02  |                                    █       |
  ... six more db.query / db.query.execute pairs ...
  db.write.queue_wait                                    7.04     0.01  |                                         █  |
  db.write.execute                                       7.06     0.21  |                                         █  |
  db.query                                               7.32     0.15  |                                           █|
    db.write.queue_wait                                  7.35     0.02  |                                           █|
    db.write.execute                                     7.38     0.06  |                                           █|

26 spans, 1 trace.

The durations are self-consistent: children fit inside parents, the 4.88ms db.write.execute is
the internal catalog build, and the whole of startup is 7.48ms — which is what starting Datasette
against a 500-row database should cost.

A table page. GET /demo/dogs?_size=100 against a 500-row table:

                                                        start      dur
db.query                                                 0.00     0.10  |█                                           |
  db.query.execute                                       0.04     0.01  |█                                           |
db.query                                                 0.12     0.07  |█                                           |
  db.query.execute                                       0.14     0.01  |█                                           |
db.query                                                 0.20     0.07  |█                                           |
  db.query.execute                                       0.23     0.01  |█                                           |
... 30 more ...

66 spans, 33 traces.

33 separate traces, because nothing here creates a span for the request — that is the PR 2
limitation restated as output, and it is the honest reason to review the two together.

One db.query span in full:

kind: CLIENT
db.system            = 'sqlite'
db.namespace         = 'demo'
db.query.text        = 'select id, name, age from dogs order by id limit 101'
db.operation.name    = 'SELECT'
db.collection.name   = 'dogs'
datasette.rows_returned = 101
datasette.truncated     = False
datasette.time_limit_ms = 1000

The thing #1730 is about. On an idle instance the gap between db.query and
db.query.execute is small — across the 33 db.query spans above, min 0.05ms, median 0.09ms,
max 0.45ms. That gap is the whole point, and it only becomes interesting under load. Twelve
concurrent identical queries against three SQL threads:

   start  db.query    wait  execute
    0.00     14.82    0.07    14.70
    0.02     14.97    0.12    14.80
    0.09     14.66    0.25    14.34
    0.17     29.14   14.56    14.46
    0.20     29.31   14.60    14.57
    0.21     29.31   14.75    14.48
    0.23     44.01   28.99    14.95
    0.24     43.97   29.16    14.69
    0.26     43.75   29.21    14.48
    0.27     58.31   43.70    14.55
    0.28     58.40   43.82    14.54
    0.30     58.37   43.89    14.41

queue wait: min 0.07ms  median 28.99ms  max 43.89ms
execute:    min 14.34ms median 14.55ms  max 14.95ms

Four waves of three, and db.query climbs 15 → 29 → 44 → 58ms while db.query.execute stays
flat at 14.5ms. The existing tracer reports one number here, and that number would be 58ms for a
query that took 14.5ms to run. Separating the two makes "your database is slow" and "your thread
pool is saturated" distinguishable, which is the request in #1730.

(Sanity check on those numbers, since a duration bug elsewhere in this work survived every test I
had: 12 queries ÷ 3 threads = 4 waves × 14.5ms = 58ms, which is exactly the largest db.query.
The arithmetic closes.)

Performance

Measured on this diff, against main at e889403, on the same machine and the same database file.
Workload is one table page — /bench/records?_size=100 on a 5,000-row table with facet
suggestion on. Each run is 80 requests after 15 warm-up requests, taking the median request time;
each configuration is a number of independent runs, and I report the median of those run medians
plus the full range across runs.

	runs	median	range across runs	spans/request
main, no provider	15	9.80ms	9.46 – 10.81	0
this PR, no provider	15	9.98ms	9.74 – 11.31	0
main, SDK provider	5	9.58ms	9.51 – 10.72	0
this PR, SDK provider	10	11.25ms	10.61 – 11.92	58.2

With no provider installed — the default, and what everyone who does not opt in gets — there is
no measurable regression. The medians differ by 0.18ms, and run-to-run spread within a single
configuration is 1.3–1.6ms. The delta is well inside the noise. I am deliberately not quoting
0.18ms as a result: this benchmark cannot resolve it. What it can say is that ~58 no-op spans per
page do not show up in end-to-end page latency.

With an SDK provider installed the cost is real and measurable: +1.67ms against main with
the same provider, or +1.27ms against this same branch with the provider removed. Over 58.2 spans
that is roughly 22µs per span. This is a best case for the SDK — SimpleSpanProcessor writing to
an InMemorySpanExporter, so no serialization and no network. A real OTLP exporter adds its own
cost on top, but that cost is paid only by operators who chose to turn tracing on, and it is the
SDK's cost rather than Datasette's.

Both datasette/telemetry.py's docstring and the new docs state this measurement rather than
claiming spans are free. An earlier version of this work had a docstring saying spans "cost
approximately nothing" while its own benchmark showed +7.1ms on a large page; I would rather the
comment and the number agree.

Caveat on resolution: this is a Python end-to-end benchmark on a laptop, so it resolves about a
millisecond. It is the right instrument for "does turning this off cost users anything" and the
wrong one for micro-attribution.

How to test this

pip install -e '.[test]'
pytest -n auto -m "not serial" && pytest -m "serial"

# core must never import the SDK
grep -rn 'opentelemetry\.sdk' datasette/     # must be empty

# see spans with no infrastructure
OTEL_TRACES_EXPORTER=console OTEL_METRICS_EXPORTER=none OTEL_LOGS_EXPORTER=none \
  opentelemetry-instrument datasette mydb.db

Note OTEL_TRACES_EXPORTER=console datasette mydb.db on its own produces nothing — that variable
is read by the SDK's auto-configuration, which only runs under opentelemetry-instrument. Core
installs no provider, so plain datasette emits nothing at all. This trips everyone up once.

Full serial suite on this branch: 2353 passed, 39 skipped, 6 xfailed, 15 xpassed, 141 subtests,
no failures and no new warnings.

Known limitations

• Every span is currently a root span. Nothing here creates a span for the HTTP request, so a
  trace UI shows many single-span traces per page. PR 2 fixes this, and the two really are best
  reviewed and released together — merging this one alone and cutting a release would ship a version
  whose traces look broken. If you'd prefer them as a single PR, say so and I'll combine them; I
  split them because the request span is the only new code here and I wanted it reviewable on its
  own.
• No metrics, no plugin hook spans, no permission spans, no template/facet spans. All are built on a
  branch stack and will follow as separate PRs. The roadmap is in the tracking issue.
• No parameter values, by default or otherwise, in this PR.
• Three timeout sites still produce ERROR spans. The rule above — a deliberately short query
  budget is not a failure — keys on the caller passing custom_time_limit. Three call sites
  swallow QueryInterrupted but pass no custom limit, so a timeout there still marks the span
  ERROR: the table page's count query (datasette/views/table_extras.py), expand_foreign_keys
  (datasette/app.py) and foreign_table_counts (datasette/views/row.py). Fixing them means
  changing what limit those callers request, which is a behaviour change rather than a telemetry
  one, so I left it out of scope. Happy to do it here if you'd rather.
• db.operation.name reports WITH for a statement opening with a CTE, as described above.
• Two plugin hooks — register_output_renderer and asgi_wrapper — are dispatched from
  Datasette.__init__() and .app(), before invoke_startup(), so anything they query falls
  outside the datasette.startup span. Measured: a default install emits zero spans from either,
  since Datasette queries no database there, so this only affects plugins. Covering them would
  mean holding a span open across object construction.
• An embedder using Datasette().app() inside a host application should install its
  TracerProvider before serving traffic. Spans emitted before a provider exists aren't recorded.
  (This is ordinary OTel behaviour, not something Datasette controls, and nothing is permanently
  affected — those spans are just dropped.)

_{Stack created with GitHub Stacks CLI • Give Feedback 💬}

[codecov]

Codecov Report

❌ Patch coverage is 0% with 265 lines in your changes missing coverage. Please review.
✅ Project coverage is 0.00%. Comparing base (e889403) to head (2de3d67).

Files with missing lines	Patch %	Lines
datasette/database.py	0.00%	151 Missing ⚠️
datasette/telemetry_registry.py	0.00%	55 Missing ⚠️
datasette/app.py	0.00%	37 Missing ⚠️
datasette/telemetry.py	0.00%	21 Missing ⚠️
datasette/views/table.py	0.00%	1 Missing ⚠️

Additional details and impacted files

@@          Coverage Diff           @@
##            main   #2862    +/-   ##
======================================
  Coverage   0.00%   0.00%            
======================================
  Files         73      75     +2     
  Lines      12279   12449   +170     
======================================
- Misses     12279   12449   +170     

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
• 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.