Add draft performance report and in-process A/B results

The end-to-end section is still to be filled in.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01F8mEgRS8swZfYqwqrVMeo5
This commit is contained in:
Claude 2026-10-13 01:12:18 +00:00
commit 34ad7ac3d9
No known key found for this signature in database
5 changed files with 3846 additions and 0 deletions

View file

@ -0,0 +1,404 @@
# Datasette request/response performance on Python 3.15
This directory holds a profiling study of Datasette's core URL handling and
request/response cycle at commit `cf113a5`. It covers routing, middleware,
`Request`/`Response`, cookies and signing, URL building, template plumbing,
static files and error paths. Optimising SQL queries against user data was
out of scope. Per-request work that only *touches* SQLite without being a
data query, such as probing a throwaway `:memory:` connection on every
request, was in scope and is labelled "DB-adjacent".
Everything was measured on **Python 3.15.0b4** (installed with `uv python
install 3.15`). Profiling used the new statistical sampling profiler,
`python -m profiling.sampling` (PEP 799).
**Nothing in `datasette/` is changed by this branch.** The proposed changes
are the patch files in `patches/`, one per optimisation, plus
`patches/ALL-combined.diff`.
## Headline results
`ALL-combined.diff` applies 48 patches to `cf113a5`. With it applied, the
full test suite passes on 3.15: 2869 passed, which is the 2829 baseline
tests plus 40 new ones. Black and ruff are clean.
These timings are in-process: the harness calls the ASGI app directly, with
no HTTP server. The fixtures database is opened mutable (the `datasette
data.db` default) with 3 SQL threads. Each figure is the median of 5
interleaved rounds. Base and patched trees were checked out at the same path
depth.
| Request | Before | After | Change |
|---|---:|---:|---:|
| `GET /favicon.ico` | 897 µs | 31 µs | −97% |
| `GET /-/static/app.css` (83 KB) | 4,141 µs | 147 µs | −96% |
| `GET /-/static/app.css?_hash=…`, the URL every page links to | 4,386 µs | 200 µs | −95% |
| `GET /-/versions` (HTML) | 3,420 µs | 1,011 µs | −70% |
| `GET /-/versions.json` | 1,935 µs | 596 µs | −69% |
| `GET /fixtures/nope/nope/nope/nope` (404 page) | 1,509 µs | 484 µs | −68% |
| `GET /-` (301 redirect) | 120 µs | 39 µs | −67% |
| `GET /-/actor.json` with a `ds_actor` cookie | 206 µs | 80 µs | −61% |
| `GET /-/static/app.css` → 304 (`If-None-Match`) | 274 µs | 120 µs | −56% |
| `GET /fixtures/` (trailing-slash redirect) | 102 µs | 50 µs | −51% |
| `POST /-/actor.json` (405) | 118 µs | 58 µs | −51% |
| `GET /fixtures/facetable.json?_size=5…` | 6,794 µs | 3,635 µs | −46% |
| `GET /fixtures/facetable/1.json` | 3,031 µs | 1,894 µs | −38% |
| `GET /fixtures/compound_three_primary_keys?_size=100` | 48.8 ms | 32.3 ms | −34% |
| `GET /fixtures/facetable?_size=5` (HTML) | 58.2 ms | 43.0 ms | −26% |
| `GET /` (index HTML) | 62.2 ms | 49.8 ms | −20% |
| `GET /…/compound_three_primary_keys.csv?_size=1000` | 21.6 ms | 17.2 ms | −20% |
| `GET /fixtures` (database HTML) | 65.5 ms | 55.7 ms | −15% |
| `GET /.json` | 53.7 ms | 47.5 ms | −11% |
The same fixtures opened as an **immutable** database (`datasette -i`):
| Request | Before | After | Change |
|---|---:|---:|---:|
| `GET /fixtures/facetable.json?…` | 7,300 µs | 1,981 µs | −73% |
| `GET /fixtures/facetable/1.json` | 3,386 µs | 1,094 µs | −68% |
| `GET /fixtures` | 53.3 ms | 23.8 ms | −55% |
| `GET /fixtures/facetable` | 56.5 ms | 28.0 ms | −50% |
For the light endpoints, no patched round was slower than any base round.
The heavy pages (tens of ms, dominated by SQL thread-pool round trips) vary
±10–15% between rounds, so their gains are less precise. The raw per-round
numbers are in `results/`.
End-to-end results under a real `datasette serve` (uvicorn) are
[further down](#end-to-end-under-datasette-serve). There, the HTTP server
layer is a large fixed cost, so the in-process percentages are diluted on
light requests. Fixing the server stack is a lever of the same size.
## Where the time went (baseline)
Share of wall-clock samples on the event-loop thread, from 10 kHz wall-mode
profiles of the in-process harness at `cf113a5` (`results/baseline-profile-breakdown.txt`):
| Request | Biggest costs |
|---|---|
| Cookie-authenticated JSON (`/-/actor.json`) | re-parsing cookies, headers and query string 32%; itsdangerous signing 20%; GC 11%; dispatch (inspect, hooks, telemetry, routing) 10% |
| Anonymous redirect (`/-`) | dispatch 27% (17% is `inspect.signature()`); GC 16%; signing 10%; re-parsing 10% |
| 404 page | Jinja 78%: walking every template directory, plus `static()` calling `Path.resolve()` 5–12 times |
| `/-/versions.json` | SQLite work on the event loop 53%: a new `:memory:` connection and FTS probes on every request |
| `/-/static/app.css` | waiting on the thread pool 81%: one `aiofiles` hop per 4 KB chunk |
| `/fixtures/facetable.json` | waiting on the thread pool 83%: 12 SQL round trips per request, most of them schema introspection |
Most of the cost is re-doing work that never changes. Every access to
`request.cookies` re-parses the Cookie header, and there are three per
request. Every `sign`/`unsign` call builds a new serializer. Every request
unsigns a `ds_messages` cookie that isn't there, which raises an exception
and leaves a reference cycle for the GC. Every view call runs
`inspect.signature()`. Every 404 walks every template directory. Every static
asset is hashed or chunked in ways that cost far more than the bytes. None
of this is new work per request; it is repeated work.
## The proposed changes
Each patch applies on its own to `cf113a5` with `git apply`, unless noted.
They were found and prototyped by investigators working per area, with
interleaved A/B timing, profiler evidence and the relevant tests. Each area
was then reviewed adversarially for correctness, security and plugin
compatibility. Where the reviewer asked for changes, the corrected version
is the one in this directory.
"In-process effect" is from the final sequential run of each area's patches
alone against the same base (`results/inprocess-summary.txt`). Effects
below about ±8% are inside the noise of that run. Smaller wins are
supported by micro-benchmarks and profiler sample shares in the area notes.
### Request object and router — `request-object-*`, `signing-*`
Area effect: cookie-auth JSON −52%, redirect −39%, trailing slash −37%,
POST 405 −44%, static 304 −35%, index HTML −14%.
| Patch | What it does |
|---|---|
| `request-object-1-cache-request-headers` | `Request.headers` decoded every scope header on every access: 4–18 times per request. It is now cached per `Request` against a snapshot of `scope["headers"]`, so it stays correct when `route_path` reassigns `request.scope` or a plugin replaces or appends headers. It still returns a fresh dict. |
| `request-object-2-memoize-cookie-parse` | `Request.cookies` built a new `SimpleCookie` on every access. Parsing is now memoised by Cookie-header string (LRU of 128, headers up to 8 KB only), and a copy is returned. |
| `request-object-3-single-pass-send-wrapper` | The Cache-Control/Vary privacy wrapper in `route_path` built `request.headers` twice and made four passes over the response headers. It now makes one pass. Output was fuzzed as byte-identical. |
| `request-object-4-cache-request-args` | `Request.args` re-ran `parse_qs` 29–34 times per table request. It is now cached per query string, with fresh lists on each access. |
| `request-object-5-skip-absent-ds-messages-unsign` | `route_path` unsigned the `ds_messages` cookie even when absent. `unsign("")` always raises `BadSignature`, and the traceback it left behind formed a reference cycle that triggered GC. (`signing-2` is the same fix; apply only one.) |
| `signing-1-cache-serializer` | `Datasette.sign`/`unsign` built a new `URLSafeSerializer` per call: itsdangerous runs `json.dumps({})` to sniff the serializer and re-derives the key. Serializers are now cached per `(secret, namespace)`. Unhashable secrets, such as key-rotation lists, fall back to an uncached serializer. |
| `signing-3-actor-cookie-single-parse` | `actor_from_request` read `request.cookies` twice. |
### Routing and view dispatch — `routing-*`
Area effect: redirect −17%. `datasette.client` requests are 13–44% faster;
see `routing-2`.
| Patch | What it does |
|---|---|
| `routing-1-cache-view-signatures` | `_gather_arguments` called `inspect.signature()` on every request for every wrapped view and output renderer, and `wrap_view_function` called `inspect.iscoroutinefunction` per request. The parameter names are now cached in a `WeakKeyDictionary`, and the coroutine check moves to wrap time. |
| `routing-2-reuse-default-routes` | `DatasetteClient.app` calls `ds.app()` for **every** `datasette.client` request, which rebuilt about 61 routes and called `get_plugins()`. The default route table is now reused until the plugin registry or `static_mounts` changes. Plugin `register_routes` is still called every time. `ds.app()` drops from 318 to 5 µs. |
### Middleware, OpenTelemetry and GC — `middleware-gc-*`
Area effect: static 304 −11%, trailing slash −10%, index HTML −15%,
index JSON −12%.
| Patch | What it does |
|---|---|
| `middleware-gc-1-telemetry-no-provider-fast-path` | With no OpenTelemetry provider installed, `TelemetryMiddleware` still ran `extract()` and three nested no-op span context managers on every request, about 8 µs. It now skips the span when it would be `INVALID_SPAN` anyway. |
| `middleware-gc-2-skip-noop-db-query-spans` | Two no-op spans per SQL query (`db.query` and `db.query.execute`), about 10 µs of Python per query, which adds up on pages making 70+ queries. (Conflicts textually with patch 1; `ALL-combined.diff` resolves it.) |
| `middleware-gc-3-csrftoken-no-scope-cycle` | The legacy `scope["csrftoken"]` closure captured `scope` and was stored in it, so every request leaked a cycle to the GC. Combined with `request-object-5`, a request that makes no permission checks, such as `/-/actor.json`, now leaves **zero** cyclic garbage, down from 53 objects. Permission checks still leave about 13 each; see the bugs list. |
| `middleware-gc-4-router-single-scope-copy` | One `dict(scope, …)` copy per request instead of two, and a module-level import instead of one per request. |
| `middleware-gc-5-telemetry-header-getter-length-check` | The trace-context header getter lowercased every header name. It now compares lengths first. |
| `middleware-gc-7-tracer-trace-fast-path` | `datasette.tracer.trace()` looked up the asyncio task on every SQL query even with no `?_trace=1`. Decorator use of `@trace(...)` keeps working. |
### Static files — `static-files-*`
Area effect: favicon −92%, `app.css` −94%, `app.css?_hash=` −95%, 404 page
−47%.
| Patch | What it does |
|---|---|
| `static-files-1-cache-hash-param-sha256` | A `?_hash=` request, which is every static URL Datasette's templates emit, ran `sha256_file()` over the whole file **synchronously on the event loop** on every request. The hash is now cached per `(inode, size, mtime_ns, ctime_ns)`. |
| `static-files-2-send-file-fewer-thread-hops` | `asgi_send_file` did a thread-pool hop for stat, open, close and every 4 KB read: about 25 hops and 21 ASGI messages for `app.css`. It now reads files up to 1 MiB in one hop and streams 64 KB chunks above that. |
| `static-files-3-memoize-static-template-urls` | The template `static()` helper resolved paths with `Path.resolve()` (about 50–90 µs) on every call, 5–12 times per HTML page. Successful results are now memoised. |
| `static-files-4-favicon-from-memory` | The favicon was re-read from disk, using 4 thread hops, on every request. |
| `static-files-5-resolve-static-root-once` | The static root was resolved again on every request. The first version of this patch was **refuted** in review, because a symlinked `--static` root re-pointed at runtime broke. This version re-resolves when the root's `(st_dev, st_ino)` changes and adds a regression test. |
| `static-files-6-serve-small-static-files-from-memory` | Files up to 1 MiB are served from a 16 MiB stat-validated in-memory cache, with zero thread hops. It keeps a running byte counter, after review found an O(n) re-sum on every cache miss. |
### Error paths — `error-paths-*`
Area effect: 404 page −20%. `table_json` −8% and permission checks generally
are faster through patch 2.
| Patch | What it does |
|---|---|
| `error-paths-1-list-only-pages-templates` | Every 404 called `Environment.list_templates()`, walking every template directory (the default one twice), to look for `pages/{wildcard}.html`. It now lists only `pages/`, with the same results and order on 19 loader shapes. |
| `error-paths-2-permission-params-no-per-request-regex` | `PermissionSQL.allow()` names each parameter `:reason_N` with a global counter, so `check_permissions_for_actions` compiled a never-seen regex for every permission check. It now does a single-pass rename. |
| `error-paths-3-rich-traceback-only-for-5xx` | **Bug.** With `rich` installed, every 4xx printed a `show_locals=True` traceback, about **0.9 s** per table-not-found 404. Unmatched-route 404s **crashed** with `ValueError` (500), because `print_exception` ran outside an `except` block. Rich tracebacks now print only for 5xx errors, as the plain-Python path already does. |
### Template rendering plumbing — `template-plumbing-*`
Area effect: 100-row table page −16%, table HTML −7%. Render-only, the
100-row table page goes from 13.1 ms to 5.7 ms.
| Patch | What it does |
|---|---|
| `template-plumbing-1-buffer-table-rows-in-templates` | In Jinja's async mode, every output fragment travels through `async for event in gen: yield event` at each `extends`/`block`/`include` level, about 170 ns per level per fragment. A 100-row table yields 6,810 fragments through 4–5 levels. The row loops in `_table.html` and `_query_results.html` are now captured with `{% set %}…{% endset %}`. Output is byte-identical on 47 endpoints. Users' overridden `_table.html` templates are unaffected. |
| `template-plumbing-2-buffer-base-content-block` | Does the same for `base.html`'s content block, inside an empty `{% with %}` so the buffer variable cannot shadow a child template's or plugin's `content_html`. That collision was found in review. |
| `template-plumbing-3-absolute-url-plain-str` | `absolute_url()` passed a `PrefixedUrlString` to `urljoin`, costing about 58 µs per call. |
| `template-plumbing-4-skip-render-cell-hook-without-impls` | `render_cell` was dispatched once per **cell** even with no plugin implementing it. `DATASETTE_TRACE_PLUGINS` output is unchanged. |
| `template-plumbing-5-hoist-table-path-out-of-row-loop` | `urls.table()` was computed once per row. |
| `template-plumbing-6-skip-template-hooks-without-impls` | `render_template` called six hooks with no implementations on every page. This saves about 12 µs. |
| `template-plumbing-7-database-view-reuse-selected-template` | The database view selected its template twice. |
Jinja async mode itself costs 35–43% on a render microbenchmark compared
with sync mode. It cannot be turned off, because templates call async
functions (`crumb_items`, `menu_links`) and the plugin docs promise that
awaitables in template context are auto-awaited.
### URL building — `url-building-*`
Area effect: table JSON −10%. Facet-heavy HTML pages improve 4–19% in the
area's lower-noise harness.
| Patch | What it does |
|---|---|
| `url-building-1-prefixed-url-string-class-methods` | `PrefixedUrlString.__getattribute__` called `dir(str)` and built a closure on **every** attribute access, about 9.5 µs each, and `urljoin` makes about 7 per call. The wrapped methods are now defined once on the class. A property test over 180,000 calls gave identical results. |
| `url-building-2-tilde-encode-safe-fast-path` | `tilde_encode` ran a per-byte generator even for names that need no encoding. A regex fast path was checked identical on 200,000 strings. |
| `url-building-3-tilde-decode-skip-token-when-nothing-to-decode` | `tilde_decode` called `secrets.token_hex(16)`, an `os.urandom` syscall, on every call, including for every database and table name in every URL. |
### Response serialization — `response-serialization-*`
These matter most under a real server, so the in-process harness shows
little.
| Patch | What it does |
|---|---|
| `response-serialization-1-chunk-csv-stream-writes` | CSV sent **one ASGI message per row**. A 20,000-row `_stream=1` CSV was 20,003 messages. It now buffers up to 64K characters, flushed per page. Under uvicorn, a 1,000-row CSV goes from 45 ms to 17 ms and a 20k-row stream from 1.24 s to 0.67 s. Bytes are identical. |
| `response-serialization-2-json-renderer-skip-infinity-scan` | The JSON renderer scanned every value of every row in Python for infinities. It now encodes with `allow_nan=False` and falls back to the old path on `ValueError`. **Behaviour change:** `_shape=arrayfirst` with an infinity in a non-first column used to 500 (AssertionError) and now returns 200. A regression test is included. |
| `response-serialization-3-csv-bytes-check-without-genexpr` | Per-row `any(isinstance(…) for …)` becomes `any(map(…))`. |
| `response-serialization-4-head-skips-csv-generation` | `HEAD` on a CSV endpoint generated and streamed the whole CSV. For `_stream=1` that meant paginating the whole table: 680 ms became 6 ms. Status and headers are identical. |
### DB-adjacent per-request work — `db-adjacent-*`
These are not data queries. They are introspection and probes that ran on
every request. Area effect: `/-/versions.json` −50%, `/-/versions` −27%,
table JSON −22%. On an immutable database, table JSON is −57%, row JSON −45%
and the database page −45%.
| Patch | What it does |
|---|---|
| `db-adjacent-1-cache-versions-probe` | `/-/versions` opened a `:memory:` connection, ran every `prepare_connection` hook and created three FTS virtual tables on **every** request. The result is now cached until the plugin set changes. |
| `db-adjacent-2-memoize-detect-json1` | `detect_json1()` with no connection opened a fresh SQLite connection on every table HTML page. |
| `db-adjacent-3-column-types-skip-introspection` | `get_column_types` ran `PRAGMA table_xinfo` even when no column types were assigned. |
| `db-adjacent-4-reuse-table-columns-for-sort` | `table_columns()` was introspected twice per table request. |
| `db-adjacent-5-row-reuse-resolved-results` | The row page ran the same primary-key `SELECT` twice. |
| `db-adjacent-6-cache-immutable-db-introspection` | For immutable databases the schema cannot change, so introspection is cached from one `sqlite_master` read. Review bounded the cache to real schema names, so junk `?_through=` names cannot fill it. |
| `db-adjacent-7-batch-refresh-schemas-reads` | `refresh_schemas()` made 8 sequential round trips to read the internal catalog. |
| `db-adjacent-8-skip-unused-label-column-lookups` | `table_view_data` looked up a label column for every foreign key, then discarded the result. |
### Found by the completeness critic — `critic-*`
| Patch | What it does |
|---|---|
| `critic-1-permission-sql-stable-param-names` | Because of the `:reason_N` counter, **the SQL text of every permission check was unique**, so SQLite re-prepared it every time: about 170 µs instead of 10 µs on the internal database. Parameters are now named by position. This needs `error-paths-2` applied first. With `error-paths-2` and `critic-2`, the effect was `/-/versions.json` −20%, row JSON −16% and table JSON −18%. |
| `critic-2-table-rows-dict-zip` | `dict(sqlite3.Row)` does a case-insensitive name lookup per column, which is O(columns²) per row. It now uses `zip` when names are unique. |
## End-to-end under `datasette serve`
E2E_PLACEHOLDER
## Bugs found along the way
Fixed by the patches above:
- **`rich` makes 4xx responses very slow and makes unmatched routes crash**
(`error-paths-3`).
- **`HEAD` on CSV URLs generates the entire CSV** (`response-serialization-4`).
- **`?_hash=` static requests hash the whole file on the event loop**
(`static-files-1`).
- **Every permission query is a fresh SQLite statement** (`critic-1`).
- **`_shape=arrayfirst` returns a 500** when a row holds an infinity outside
the first column (`response-serialization-2` changes this to 200).
Not fixed, reported for follow-up:
- **httpx2 retries a failed `import sniffio` on every `datasette.client`
request.** sniffio is no longer installed, and a failed import is not
cached, so `sys.path` finders are walked on every client and `TestClient`
request. That is about 29% of a client request (454 → 324 µs when the
failure is cached). Fix: depend on `sniffio`, or fix it upstream in httpx2.
- **`calculate_etag`'s cache is never invalidated.** After a static file is
edited in place, the old ETag keeps being served and clients get 304s for
changed content. Keying it on `(size, mtime_ns)`, as `static-files-1` does
for the hash, would fix it.
- **`tilde_decode` is non-deterministic** for input where a `~` escape is cut
short by `%`. For example, `tilde_decode("90~3%")` returns `90%` only about
63% of the time, because the random placeholder token gets decoded.
- **`--pdb` with an unmatched-route 404 crashes** in
`pdb.post_mortem(None)`.
- **`database_download` sends both `Content-Length` and
`Transfer-Encoding: chunked`.**
- **Foreign-key label links use `tilde_encode(database_name)`** instead of the
database route (`views/table.py` `LINK_WITH_LABEL`).
- **Each permission check leaves about 13 cyclic objects** through the
self-recursive closures in `Datasette._allowed_many`.
- **`tests/test_plugins.py` unregisters the wrong plugin** around line 1547.
## Further proposals, not in `ALL-combined.diff`
These are prototypes in `patches/optional/`. Each was measured, but either
not adversarially reviewed or carrying a trade-off to decide first:
- **Install httptools by default**, for example through a `datasette[fast]`
extra or `uvicorn[standard]`. See the end-to-end section. No code change.
- **Add `--no-access-log` to `datasette serve`.** The uvicorn access log is
8–13% of server CPU on light requests.
- **Send `Content-Length` on non-streaming responses.** About 3% end to end.
It also gives clients sizes and progress.
- `critic-3-extras-sequential`: table HTML resolves about 30 "extras" as
concurrent asyncio tasks (asyncinject `parallel=True`). Running them
sequentially measured −18 to −20% on table HTML. This contradicts
`run_sequential` in `table.py` (#2189), but the count and facet queries
may genuinely benefit from overlapping on large tables.
- `critic-5-request-scoped-introspection-memo`: foreign keys are
introspected 5×, and primary keys and `PRAGMA schema_version` 2×, per
table HTML request. A request-scoped memo plus a one-trip prefetch
measured −25% on table JSON. **It does not yet clear the memo on writes**
within the same request.
- `critic-6-inline-tableless-permission-checks`: permission checks whose
SQL reads no table could run inline (7 µs) instead of through the thread
pool (330 µs). That would take `/-/versions.json` from 567 to 238 µs.
- `critic-4-skip-fts-lookup-for-data-formats`: one FTS-detection round trip
per JSON/CSV table request that only HTML uses.
- `middleware-gc-6-serve-gc-freeze-after-startup`: `gc.freeze()` after
startup removes about 40 ms gen-2 pauses on query-heavy pages. It made no
difference end to end on light requests, and it hides startup objects
from `gc.get_objects()`. **Not recommended** without an opt-out.
## Ideas measured and rejected
- **uvloop.** `datasette serve` never uses it: `cli.py` calls
`asyncio.run()`, which bypasses uvicorn's `loop="auto"`. Forcing it gained
nothing measurable.
- **One combined alternation regex, or prefix dispatch, for routing.** Route
matching is 0.3–15 µs (2.5% of a row request). A combined regex is only
1.4× faster and unsafe for arbitrary plugin regexes.
- **Sync Jinja.** It is faster, but async template functions are a
documented API.
- **`auto_reload=False`, and caching negative template lookups.** These
would stop new or edited templates being picked up without a restart.
- **GC threshold tuning.** Within noise. GC came from cycles, which are now
removed, not from heap size.
- **Coalescing uvicorn's header and body writes.** No gain, because only the
first write of a response, the one that wakes the peer, is expensive.
- **Reusing one `httpx2.AsyncClient` across `datasette.client` calls.** It
would leak cookies between calls.
- **Running introspection on the event loop thread.** A locked database
would block the loop for up to the 5 s busy timeout.
- **Overlapping thread-pool trips with `asyncio.gather`.** This was 5–14%
*slower*: more wake-ups and GIL contention.
## The Python 3.15 sampling profiler
Every finding started from `profiling.sampling`. Examples:
```bash
# in-process steady-state loop, 10 kHz, collapsed stacks for analysis
python -m profiling.sampling run -r 10khz --mode wall --collapsed -o x.collapsed \
tools/bench_asgi.py loop actor_json_cookie --seconds 6
python tools/analyze_collapsed.py x.collapsed --buckets
python tools/analyze_collapsed.py x.collapsed --children "DatasetteRouter.handle_404"
# attach to a running `datasette serve` while load runs
python -m profiling.sampling attach -r 10khz -d 10 --mode cpu --collapsed -o serve.collapsed PID
# which tree is a server running? dump shows file paths in the live stack
python -m profiling.sampling dump PID
```
These features were all useful: wall, `cpu` and `gil` modes; `-a` for all
threads; `--async-aware`; `--opcodes` (with `--heatmap`/`--flamegraph`);
`--binary` plus `replay`; `--diff-flamegraph` against a binary baseline;
`--heatmap`; and `--blocking`. Sampling is out-of-process, so it slows the
target very little, and `attach` works on a production-shaped server with
no restart.
Things to know when reading its output on 3.15.0b4:
- **Many samples fail in non-blocking mode: 25–65% "error rate"**, worst
inside Jinja-compiled template code. Frames for included templates and
child blocks often never appear, so template-body cost shows up on
pass-through lines. `--blocking` drops errors to about 0.5% but slows the
target about 3×. The layer split matched between the two within about 6
points.
- **`<GC>` is attributed to whichever frame next hits the eval breaker**, so
it can appear under unrelated code such as `Datasette.setting`.
- **`run` puts the current directory first on `sys.path`** (like `-m` and
`-c`). Run it from outside a source tree you don't intend to import.
- **`--opcodes` is not accepted with `--collapsed` or `--pstats`.**
- **`--async-aware --async-mode all` failed with 100% errors** on the
table endpoint. It worked on lighter ones.
- **Line numbers after `--binary` + `replay` were sometimes implausible**,
for example comment lines. Line-level shares here come from direct
`--collapsed` runs.
## Reproducing
```bash
uv python install 3.15
uv venv -p 3.15 /tmp/venv315
uv pip install -p /tmp/venv315 -e . pytest pytest-asyncio pytest-xdist beautifulsoup4 \
pytest-timeout trustme cogapp opentelemetry-sdk "multipart-form-data-conformance==0.1a0"
# two trees at the same path depth: Datasette.static() calls Path.resolve(),
# which costs more for deeper install paths and skews HTML-page comparisons
git worktree add --detach ../t/base cf113a5
git worktree add --detach ../t/patched cf113a5
(cd ../t/patched && git apply "$OLDPWD"/perf/request-response/patches/ALL-combined.diff)
/tmp/venv315/bin/python perf/request-response/tools/measure_ab.py \
--tree base=../t/base --tree patched=../t/patched \
--endpoints actor_json_cookie,redirect_dash,versions_json,not_found,static_css \
--n 1000 --rounds 5
```
`tools/bench_asgi.py` drives the ASGI app directly with realistic browser
headers. `tools/measure_ab.py` interleaves trees round by round, using a
fresh process per run. `tools/analyze_collapsed.py` attributes collapsed
stacks to components. The measurements were taken on a 4-vCPU cloud VM, so
compare ratios rather than absolute numbers.

File diff suppressed because it is too large Load diff

View file

@ -0,0 +1,178 @@
{
"table_json": {
"base": {
"median_us": 7299.6,
"runs": [
6723.1,
7430.2,
7790.0,
7299.6,
7140.8
],
"status_bytes": [
200,
1273
]
},
"combined": {
"median_us": 1980.9,
"runs": [
2145.7,
1750.1,
1857.0,
1980.9,
2142.7
],
"status_bytes": [
200,
1273
]
},
"I_dbadj": {
"median_us": 3146.2,
"runs": [
2896.0,
3146.2,
2750.5,
3304.6,
3362.8
],
"status_bytes": [
200,
1273
]
}
},
"row_json": {
"base": {
"median_us": 3385.5,
"runs": [
3472.8,
3343.3,
4027.8,
3385.5,
2479.6
],
"status_bytes": [
200,
421
]
},
"combined": {
"median_us": 1094.3,
"runs": [
1084.0,
1003.5,
1158.9,
1135.3,
1094.3
],
"status_bytes": [
200,
421
]
},
"I_dbadj": {
"median_us": 1877.5,
"runs": [
1877.5,
1790.0,
1904.6,
1619.2,
1930.1
],
"status_bytes": [
200,
421
]
}
},
"table_html": {
"base": {
"median_us": 56531.2,
"runs": [
60362.7,
53480.1,
60845.5,
54625.8,
56531.2
],
"status_bytes": [
200,
26551
]
},
"combined": {
"median_us": 28022.1,
"runs": [
27050.7,
26873.7,
28022.1,
35357.3,
33434.1
],
"status_bytes": [
200,
26552
]
},
"I_dbadj": {
"median_us": 40504.6,
"runs": [
40504.6,
39669.0,
46714.0,
39604.1,
40924.9
],
"status_bytes": [
200,
26552
]
}
},
"database_html": {
"base": {
"median_us": 53347.4,
"runs": [
47349.1,
53347.4,
54882.2,
49281.6,
58689.8
],
"status_bytes": [
200,
23141
]
},
"combined": {
"median_us": 23781.4,
"runs": [
23541.9,
24287.6,
23251.2,
23781.4,
24122.2
],
"status_bytes": [
200,
23141
]
},
"I_dbadj": {
"median_us": 29426.4,
"runs": [
28348.9,
32079.5,
30833.4,
29426.4,
28495.4
],
"status_bytes": [
200,
23141
]
}
}
}

File diff suppressed because it is too large Load diff

View file

@ -0,0 +1,30 @@
endpoint base combinedA_request_signing B_routing C_middleware D_static E_errors F_templates G_urls H_response I_dbadj J_critic
versions_json 1935.0us 596.4us -69% 1806.5us -7% 2026.5us +5% 1874.8us -3% 2001.0us +3% 1947.0us +1% 1894.5us -2% 1881.1us -3% 1958.5us +1% 975.6us -50% 1542.0us -20%
actor_json_cookie 205.8us 80.3us -61% 98.7us -52% 204.8us -0% 191.7us -7% 217.3us +6% 222.5us +8% 190.4us -7% 224.8us +9% 220.8us +7% 195.9us -5% 201.1us -2%
static_css_304 274.0us 119.9us -56% 177.9us -35% 286.9us +5% 243.4us -11% 261.0us -5% 303.0us +11% 283.3us +3% 268.4us -2% 309.6us +13% 277.7us +1% 289.3us +6%
favicon 896.9us 31.3us -97% 757.7us -16% 967.8us +8% 806.5us -10% 73.6us -92% 852.4us -5% 784.1us -13% 868.8us -3% 845.9us -6% 806.8us -10% 883.4us -2%
redirect_dash 119.8us 39.4us -67% 72.8us -39% 99.0us -17% 111.5us -7% 125.3us +5% 126.8us +6% 124.5us +4% 123.2us +3% 126.0us +5% 130.7us +9% 121.5us +1%
trailing_slash 102.2us 50.0us -51% 64.1us -37% 110.7us +8% 92.3us -10% 106.5us +4% 104.9us +3% 104.9us +3% 113.0us +11% 108.2us +6% 104.4us +2% 101.8us -0%
not_found 1508.6us 483.8us -68% 1359.1us -10% 1546.1us +2% 1609.9us +7% 793.3us -47% 1208.4us -20% 1549.1us +3% 1500.1us -1% 1542.0us +2% 1537.4us +2% 1464.6us -3%
post_csrf_json 117.8us 57.7us -51% 65.9us -44% 114.8us -3% 122.2us +4% 119.6us +2% 118.1us +0% 117.5us -0% 120.5us +2% 126.0us +7% 129.9us +10% 114.9us -2%
static_css 4140.6us 147.0us -96% 4156.3us +0% 4431.9us +7% 4159.3us +0% 228.0us -94% 4064.1us -2% 4281.8us +3% 4267.3us +3% 4120.0us -0% 3997.6us -3% 3989.3us -4%
static_css_hash 4386.0us 200.0us -95% 3961.6us -10% 4498.0us +3% 4471.6us +2% 228.4us -95% 4423.9us +1% 4663.6us +6% 4568.6us +4% 4814.0us +10% 4457.0us +2% 4217.7us -4%
versions_html 3419.7us 1011.2us -70% 3540.3us +4% 3593.6us +5% 3414.7us -0% 3225.2us -6% 3365.4us -2% 3300.5us -3% 3367.6us -2% 3669.1us +7% 2500.4us -27% 2932.9us -14%
row_json 3031.1us 1893.9us -38% 2949.9us -3% 2876.3us -5% 2904.9us -4% 3117.4us +3% 3083.0us +2% 2920.7us -4% 3136.9us +3% 3028.9us -0% 2814.4us -7% 2537.2us -16%
table_json 6793.8us 3635.0us -46% 6046.1us -11% 6435.3us -5% 6367.8us -6% 6948.9us +2% 6268.7us -8% 6246.7us -8% 6093.0us -10% 6897.2us +2% 5327.3us -22% 5597.7us -18%
WARNING: status/bytes differ for row_json: {'base': (200, 420), 'combined': (200, 420), 'A_request_signing': (200, 421), 'B_routing': (200, 420), 'C_middleware': (200, 420), 'D_static': (200, 420), 'E_errors': (200, 421), 'F_templates': (200, 420), 'G_urls': (200, 420), 'H_response': (200, 419), 'I_dbadj': (200, 420), 'J_critic': (200, 419)}
endpoint base combinedA_request_signing B_routing C_middleware D_static E_errors F_templates G_urls H_response I_dbadj J_critic
index_html 62239.6us 49837.1us -20% 53709.0us -14% 55989.5us -10% 53208.8us -15% 60280.6us -3% 56233.2us -10% 57762.9us -7% 56583.0us -9% 59315.1us -5% 59276.0us -5% 57427.3us -8%
index_json 53657.9us 47492.6us -11% 56852.3us +6% 58082.3us +8% 47178.7us -12% 55826.2us +4% 52773.8us -2% 58680.3us +9% 57226.4us +7% 62428.9us +16% 53976.3us +1% 54827.2us +2%
database_html 65521.8us 55694.0us -15% 61789.9us -6% 64556.0us -1% 60600.5us -8% 62105.6us -5% 66711.1us +2% 61229.7us -7% 62698.2us -4% 66549.3us +2% 66807.6us +2% 66002.7us +1%
table_html 58207.3us 42954.1us -26% 58564.8us +1% 57928.2us -0% 56490.5us -3% 55819.1us -4% 58918.9us +1% 54376.2us -7% 58430.1us +0% 62191.9us +7% 55630.1us -4% 54872.0us -6%
table_html_100 48844.6us 32287.4us -34% 50922.8us +4% 45681.2us -6% 46526.3us -5% 46093.2us -6% 45938.2us -6% 40864.0us -16% 49289.5us +1% 50459.4us +3% 45203.7us -7% 49174.1us +1%
table_csv_1000 21580.3us 17162.9us -20% 21607.9us +0% 22777.9us +6% 22975.4us +6% 23429.8us +9% 23105.5us +7% 21913.8us +2% 24575.5us +14% 21727.9us +1% 20914.6us -3% 21068.3us -2%
WARNING: status/bytes differ for table_html: {'base': (200, 26552), 'combined': (200, 26552), 'A_request_signing': (200, 26552), 'B_routing': (200, 26552), 'C_middleware': (200, 26552), 'D_static': (200, 26552), 'E_errors': (200, 26552), 'F_templates': (200, 26552), 'G_urls': (200, 26552), 'H_response': (200, 26552), 'I_dbadj': (200, 26551), 'J_critic': (200, 26552)}
WARNING: status/bytes differ for table_html_100: {'base': (200, 66670), 'combined': (200, 66670), 'A_request_signing': (200, 66670), 'B_routing': (200, 66670), 'C_middleware': (200, 66670), 'D_static': (200, 66670), 'E_errors': (200, 66670), 'F_templates': (200, 66670), 'G_urls': (200, 66670), 'H_response': (200, 66669), 'I_dbadj': (200, 66670), 'J_critic': (200, 66670)}
endpoint base combined I_dbadj
table_json 7299.6us 1980.9us -73% 3146.2us -57%
row_json 3385.5us 1094.3us -68% 1877.5us -45%
table_html 56531.2us 28022.1us -50% 40504.6us -28%
database_html 53347.4us 23781.4us -55% 29426.4us -45%
WARNING: status/bytes differ for table_html: {'base': (200, 26551), 'combined': (200, 26552), 'I_dbadj': (200, 26552)}