Proposal: per-operation timing + datastore-read attribution in the Check debug trace

[poucet]

Problem

When debugging the latency of a single CheckPermission / CheckBulkPermissions
call via the debug trace (--with-tracing), it is currently very hard to tell
where the time actually goes. Two questions in particular cannot be answered
from a single response today:

1. Are sub-problems traversed in parallel or serially? ConcurrentChecker
   resolves sub_problems concurrently (union/all/difference →
   dispatchAllAsync → the semaphore-bounded taskrunner). A parent's duration
   is neither the sum nor the max of its children's durations, so from the trace
   you cannot tell whether siblings overlapped, serialized behind the
   concurrency limit, or where the idle gaps are — i.e. you cannot reconstruct
   the critical path.

2. Where are we blocked on datastore reads? The only DB signal derivable
   from the trace today is per-node self-time (node span minus children
   spans), which lumps datastore blocking and CPU together. For a bulk check
   suspected of being read-bound, that blob is exactly what you can't decompose.

The goal is to answer both from the response itself, on demand, without
standing up a sampled OpenTelemetry → Tempo pipeline.

Key observation

Both pieces of timing already exist on the server and are thrown away:

• internal/graph/check.go captures an absolute startTime when
  Debug != NO_DEBUG, uses it only to compute duration, then drops it.
• internal/datastore/proxy/observable.go (QueryRelationships /
  ReverseQueryRelationships) already times every relationship query from issue
  until the result iterator is fully drained — i.e. real blocking/streaming time
  — but it lands only in a Prometheus histogram (aggregate, by query_shape)
  and an OTel span, never in the per-check debug trace.

So this is plumbing of already-computed values, not new measurement.

Proposal

Add to CheckDebugTrace (public authzed.api.v1 and internal
dispatch.v1):

• start_time (google.protobuf.Timestamp) per node — combined with the
  existing authoritative duration, places every dispatch node on one absolute
  time axis. (end_time = start_time + duration is derived at the public
  boundary; included for convenience, droppable if a minimal surface is
  preferred.)
• repeated DatastoreQuery datastore_queries per node — each carrying
  {query_shape, start_time, duration, relationship_count} for the relationship
  reads that node issued itself. Per-query events (not one summed number)
  because a node can issue concurrent reads, so a sum could exceed the node's
  wall span; per-query start/duration lets a consumer see the overlap.

Capture mechanism

A context-scoped, mutex-guarded collector installed per node in
ConcurrentChecker.Check (only when Debug != NO_DEBUG). Each dispatched child
re-enters Check and gets its own collector, so reads attribute to the node
that issued them; remote dispatch hops already ship their own trace back in
DebugInfo and nest naturally. The observable proxy appends one
DatastoreQuery to the collector (when present) from the same spot that already
closes its timer — a single conditional branch that is a no-op when debug is
off.

Consuming the timeline

A consumer renders a Gantt: dispatch ops as [start, end] nested by
sub_problems (overlapping siblings → answers #1), and each datastore_query
as a sub-bar under its node (long bars on the critical path → answers #2).
Self-CPU per node becomes explicit: node span − union(children) −
union(own queries).

Compatibility

New fields only; old clients ignore them and buf breaking ... use: WIRE
passes. duration is unchanged and remains authoritative. The collector and the
proxy branch only activate when Debug != NO_DEBUG, so the non-debug hot path
is untouched.

Notes / cross-repo ordering

The public CheckDebugTrace lives in authzed/api, so the public field must
land and be published there before the spicedb-go buf dep can be bumped. The
internal dispatch-proto portion (dispatch.v1.CheckDebugTrace +
check.go/observable.go capture) is fully self-contained and can land first;
it already round-trips through DebugInfo, so the approach can be validated
end-to-end locally.

Open questions for maintainers

• end_time field vs start-only (clients compute end)?
• Query-event volume on broad bulk checks — gate datastore_queries behind a
  separate debug sub-level, or fine alongside start_time?
• Include schema / namespace / caveat reads (also timed via the same observe()
  helper) or relationship queries only to start?
• Synthetic combine node (combineResponseMetadata) — leave timing unset and
  derive its span from children (preferred), or set explicitly?

Happy to open the implementation as two PRs (internal dispatch proto first, then
the public authzed/api change + dep bump) once the design direction is agreed.