Attribute the served read floor (~0.2 s server-side on a trivial read) and expose it as usage

Measurement

Call	Wall time, 3 runs
`GET /healthz` (round trip only)	0.10 s, 0.11 s, 0.18 s
`omnigraph snapshot --json` (metadata only)	0.66 s, 0.58 s, 0.57 s
`query -e 'match { $p: Person } return { $p.slug } limit 1'`	0.36 s, 0.34 s, 0.36 s
`query -e 'match { $p: Person } return { count($p) as n }'` (4,678 rows)	0.45 s, 0.35 s, 0.35 s
keyed lookup `Person { slug: $s }`	0.42 s, 0.39 s, 0.38 s
`omnigraph version` (CLI startup)	0.01 s

So a trivial served read costs about 0.35 s, of which 0.10–0.15 s is the round trip. The remaining ~0.2 s is server-side and unattributed. It is not manifest reloading: the warm-read contract (crates/omnigraph/tests/warm_read_cost.rs, since v0.7.1 #268) makes a warm same-branch read zero __manifest reads and one version probe. snapshot being slower than a query is itself unexplained.

For the agent workload (many small calls per task) this fixed floor outranks any plan choice; RFC 0047 (#791) makes this rollout step 7.

Ask

Attribute the floor per phase on the server: auth/token verification, settings resolution, version probe (object-store round trips and their latency from the serving region), compile-cache hit, table open by location+version, the scan itself, result encoding. The existing helpers::cost object-store counters and warm_read_cost.rs give the request counts; wall time per phase needs a tracing span or the additive usage object RFC 0047 (rfc: RFC 0047, search plan truth on engine v2 #791) proposes, which reports time per phase (authentication, target resolution, compilation, planning, execution, serialization).
Explain why snapshot costs ~0.6 s when a query costs ~0.35 s.
Cut what the attribution shows, in order of size. Caching of immutable version-pinned state is invariant-12-clean if that is where the time is; a second version probe or a per-request policy/token round trip would be a different fix.

Acceptance

A trivial served read's server-side time is reported per phase in the response (or a tracing export), and a cost test pins the object-store request count of that read at its current value so the floor cannot regress silently.

rfc: replace Phase A's caching item with attribution of the measured …

Attributed on main (80406fee) against a local RustFS, with and without toxiproxy adding 15 ms each way (~30 ms per request). The fixture is a 4,678-row Person graph, served with omnigraph-server --cluster s3://…. Times are medians of 7.

Call	RustFS ~1 ms	+30 ms per request
`GET /healthz`	12 ms	15 ms
trivial read (`limit 1`)	20 ms	257 ms
`count`	20 ms	260 ms
keyed lookup	20 ms	293 ms
`snapshot`	21 ms	495 ms

With fast storage the server-side floor is about 8 ms, so the floor is serial object-store round trips, not CPU.

Requests per warm call. I put a logging TCP proxy in front of RustFS; three runs per call were identical.

Trivial read, 8 requests:
- GET _schema.pg
- HEAD and GET _schema.ir.json
- HEAD and GET __schema_state.json
- LIST __manifest/_versions/
- 2 data-file range GETs
Keyed lookup, 9 or 10: the same prefix plus more data GETs.
snapshot, 14: the schema check and the _versions/ LIST twice, then one more LIST and a GET of the manifest. That explains why snapshot costs about twice a query (question 2).

Where the unattributed time goes. The 5 schema requests (about 3 serial round trips) come from ensure_schema_state_valid, which re-validates the full schema contract on every operation so a long-lived handle catches external drift of the source, IR or state (see its comment in crates/omnigraph/src/db/omnigraph.rs). The warm-read contract in warm_read_cost.rs pins __manifest reads, so these schema-file reads are outside what it guards. At S3 latency they cost more than the manifest probe itself. Separately, the limit 1 read plans a full-fragment range (4,678 rows) rather than a single row.

A cheap direction consistent with invariant 12: a conditional check (ETag or If-None-Match) of the three contract objects in one parallel round trip, or folding a contract digest into the manifest the version probe already reads. Either would keep drift detection without two sequential round trips per request.

Re-measured after #834 (the schema contract moved into the catalog), with the setup of the 2026-09-25 comment: RustFS 1.0.0-beta.12, toxiproxy adding 15 ms each way, a logging proxy counting S3 requests, a 4,678-row Person graph served with omnigraph-server --cluster s3://…. Medians of 7 after two warm-up calls. One difference: this build is a debug build of main 97f293e plus unrelated planner changes (RFC 0047 steps 2–3, which add plan acceptance on the CPU and no storage requests for these queries), so the fast-storage column carries debug-build CPU.

Call	Requests then	Requests now	~1 ms storage	+30 ms per request, then	+30 ms per request, now
`GET /healthz`	0	0	0.6 ms	15 ms	0.9 ms
trivial read (`limit 1`)	8	2	10 ms	257 ms	73 ms
`count`		1	5 ms	260 ms	38 ms
keyed lookup	9–10	3	11 ms	293 ms	113 ms
`snapshot`	14	4	9 ms	495 ms	145 ms

The five schema-contract requests per call are gone (warm_read_cost.rs::warm_query_validates_schema_contract_once now pins zero), which was most of the floor. Every remaining request is one serial round trip:

Every read lists __manifest/_versions/ once: the warm-read contract's one version probe.
The trivial read then makes one data-file range GET; the keyed lookup makes two serial range GETs on the same data file.
snapshot still lists __manifest/_versions/ three times before one manifest GET. server_snapshot (crates/omnigraph-server/src/handlers.rs) calls snapshot_of(target), which resolves the branch (one listing), then internal_schema_version_of(target), which resolves it again and calls internal_schema_stamp_at, which opens __manifest at its newest version (a listing and the manifest GET). So the storage-format stamp in the response comes from whatever version is newest at that moment, not from the snapshot it is returned beside. Resolving once and reading the stamp at the snapshot's own manifest version would make the response coherent and drop at least two of the four requests.

What remains of this issue is the per-phase usage object (RFC 0047 step 7), plus the snapshot double resolution above.

Proposal: the `usage` object (RFC 0047 step 7)

RFC 0047 specifies "time per phase (authentication, target resolution, compilation, planning, execution, serialization) in an additive usage object". The re-measurement above shows the floor is now serial object-store round trips, so the object should report requests as well as time. Proposed shape on ReadOutput (POST /graphs/{id}/query):

"usage": {
  "total_ms": 72.4,
  "phases_ms": {
    "authenticate": 0.1,
    "resolve": 31.2,
    "compile": 0.3,
    "plan": 0.8,
    "execute": 39.8,
    "serialize": 0.2
  },
  "storage_requests": 2
}

Milliseconds as decimals, measured on the server from request admission to the body being ready; total_ms is that whole span, so it also covers anything between phases.
compile is near zero on a compiled-query cache hit; the phase stays present.
storage_requests counts object-store requests issued while serving this read (the version probe and data reads), from the same wrapper the cost tests use today; it is omitted if counting is unavailable for a backend.
Always present on JSON responses; it costs a few clock reads and one counter.
Arrow stream responses (application/vnd.apache.arrow.stream) cannot carry a body field before the rows, so they get the standard Server-Timing header with the phases known before the first byte (authenticate, resolve, compile, plan). JSON responses carry the same header too, so proxies and browser tools see it.
Mutations, loads and snapshot are out of scope for this step; the shape extends to them unchanged.

To agree on:

The field names and milliseconds as decimals.
storage_requests in the object (it is the number that explains the floor).
Always on, rather than behind a request flag.
Server-Timing for Arrow streams, and on JSON as well.

More data from a 0.13.0 server reached over HTTPS from a laptop, with the release CLI (10 ms start-up). The graph has 653 tables and about 4,900 commits.

Call	Time
`/healthz`, reused connection	0.16–0.21 s
Read returning no rows (`limit 0`)	0.45 s
Node by `@id`, at the branch	0.56–0.66 s
Same read pinned to the head commit	1.03–1.18 s
Same read pinned 200 commits back	1.43–1.45 s
`snapshot --json` (653 tables, 163 KB)	0.49–0.52 s
`schema show` (199 KB)	0.47–0.57 s
`changes poll`, caught up	0.45 s

The pinned-read surcharge has its own cause (snapshot-id reads skip the read caches) and its own issue, #1052. Clients that need a node with its relationships make one request per relationship group today, so this floor multiplies: a node with 92 relationship groups pays it about 185 times.

Navigation Menu

Repository navigation

Attribute the served read floor (~0.2 s server-side on a trivial read) and expose it as usage #752

Measurement

Ask

Acceptance

Proposal: the `usage` object (RFC 0047 step 7)

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Attribute the served read floor (~0.2 s server-side on a trivial read) and expose it as usage #752

Description

Measurement

Ask

Acceptance

Activity

ragnorc commented on Sep 25, 2026

ragnorc commented on Oct 2, 2026

ragnorc commented on Oct 2, 2026

Proposal: the usage object (RFC 0047 step 7)

ragnorc commented on Oct 17, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

Proposal: the `usage` object (RFC 0047 step 7)