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.
Krisztian F (krisztianfekete)
left a comment
Krisztian F (krisztianfekete)
left a comment
There was a problem hiding this comment.
Thanks, added some comments around mainly semconv and performance!
| if data.Err != nil && !errors.Is(data.Err, pgx.ErrNoRows) { | ||
| span.RecordError(data.Err) | ||
| span.SetStatus(codes.Error, data.Err.Error()) | ||
| } |
There was a problem hiding this comment.
Is it possible that this is dead code?
|
|
||
| // ErrNoRows is an expected lookup outcome and must not mark the span. | ||
| qctx = qt.TraceQueryStart(ctx, nil, pgx.TraceQueryStartData{SQL: "SELECT id FROM actors"}) | ||
| qt.TraceQueryEnd(qctx, nil, pgx.TraceQueryEndData{Err: pgx.ErrNoRows}) |
There was a problem hiding this comment.
| sr := tracetest.NewSpanRecorder() | ||
| tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr)) | ||
| prev := otel.GetTracerProvider() | ||
| otel.SetTracerProvider(tp) |
There was a problem hiding this comment.
We have a convention of not swapping the global provider in our tests.
| // Per-statement trace spans; the watch pool inherits this through Copy(). | ||
| cfg.ConnConfig.Tracer = queryTracer{} |
There was a problem hiding this comment.
Can we add a simple test to assert what the comment states?
| if len(fields) == 0 { | ||
| return "db.query" | ||
| } | ||
| return "db." + strings.ToUpper(fields[0]) |
There was a problem hiding this comment.
Can we have db.query.summary, i.e. SELECT actors to match semconv's preferences?
See https://opentelemetry.io/docs/specs/semconv/db/database-spans/
| // NotFound), not a query failure. | ||
| if data.Err != nil && !errors.Is(data.Err, pgx.ErrNoRows) { | ||
| span.RecordError(data.Err) | ||
| span.SetStatus(codes.Error, data.Err.Error()) |
There was a problem hiding this comment.
I think we should have access to SQLSTATE here, if so, can we pull it into db.response.status_code + error.type?
| ctx, _ = otel.Tracer("atepg").Start(ctx, querySpanName(data.SQL), | ||
| trace.WithSpanKind(trace.SpanKindClient), | ||
| trace.WithAttributes( | ||
| attribute.String("db.system.name", "postgresql"), |
There was a problem hiding this comment.
Can we use semconv.DBSystemNamePostgreSQL / semconv.DBQueryTextKey instead? Also missing while we're in here:
server.address(Required),db.namespace,db.operation.name,db.collection.name
| if !trace.SpanContextFromContext(ctx).IsValid() { | ||
| return ctx | ||
| } |
There was a problem hiding this comment.
Can we use IsSampled() here? Should be identical but cheaper, right?
| if !trace.SpanContextFromContext(ctx).IsValid() { | ||
| return ctx | ||
| } | ||
| ctx, _ = otel.Tracer("atepg").Start(ctx, querySpanName(data.SQL), |
There was a problem hiding this comment.
Can we cache the tracer in a struct field instead of resolving it per statement?
| func querySpanName(sql string) string { | ||
| fields := strings.Fields(sql) | ||
| if len(fields) == 0 { | ||
| return "db.query" | ||
| } | ||
| return "db." + strings.ToUpper(fields[0]) | ||
| } |
There was a problem hiding this comment.
What do you think about skipping tx control statements, or wrap the tx in one INTERNAL span and nest the statements? Otherwise this might get a bit noisy as we are getting regular spans for BEGIN/INSERT/COMMIT/etc.
3 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