ateapi: trace PostgreSQL statements in the store - #1462
Conversation
The store's pgx pools carried no tracer, so no span was ever emitted for database work: a traced GetActor arrived as a single gRPC server span with the PostgreSQL time indistinguishable from handler overhead, and even the multi-span suspend/resume traces showed step, atelet and snapshot spans but nothing for the many store round-trips between them. The store blind spot in docs/metrics/substrate.yaml describes the metrics half of this; the trace half is what this change closes. Attach a QueryTracer to the pool config (the watch pool inherits it via Copy). Each statement becomes a client span named after its leading keyword (db.SELECT, db.UPDATE, ...) with the parameterized statement text as db.query.text — arguments never appear in it. Spans only join an existing trace: statements from background work (outbox polling, lease maintenance) carry no surrounding span, and opening a root span for each would flood the backend with single-span traces. pgx.ErrNoRows leaves the span unmarked, since the store maps it to NotFound as an expected lookup outcome.
| if !trace.SpanContextFromContext(ctx).IsValid() { | ||
| return ctx | ||
| } | ||
| ctx, _ = otel.Tracer("atepg").Start(ctx, querySpanName(data.SQL), |
There was a problem hiding this comment.
Is an error here an impossible condition? Are we ok swallowing the error?
There was a problem hiding this comment.
The discarded value is the span, not an error. Start cannot fail. Its signature is Start(ctx, name, ...) (context.Context, Span). The OpenTelemetry API is built so tracing never breaks the app: if sampling is off you just get an inert span back, never an error.
We discard the span because Start also stores a copy inside the returned context, and that copy is the one we need. The span gets closed in a different function: pgx carries our returned context through the query and passes it to TraceQueryEnd, which retrieves the span with trace.SpanFromContext and ends it. A local span variable would go out of scope as soon as TraceQueryStart returns.
2 participants
The store's pgx pools carried no tracer, so no span was ever emitted for database work: a traced GetActor arrived as a single gRPC server span with the PostgreSQL time indistinguishable from handler overhead, and even the multi-span suspend/resume traces showed step, atelet and snapshot spans but nothing for the many store round-trips between them. The store blind spot in docs/metrics/substrate.yaml describes the metrics half of this; the trace half is what this change closes.
Attach a QueryTracer to the pool config (the watch pool inherits it via Copy). Each statement becomes a client span named after its leading keyword (db.SELECT, db.UPDATE, ...) with the parameterized statement text as db.query.text — arguments never appear in it. Spans only join an existing trace: statements from background work (outbox polling, lease maintenance) carry no surrounding span, and opening a root span for each would flood the backend with single-span traces. pgx.ErrNoRows leaves the span unmarked, since the store maps it to NotFound as an expected lookup outcome.
Fixes #1455