ateapi: trace PostgreSQL statements in the store by git286 · Pull Request #1462 · agent-substrate/substrate

Da Huang (git286) · 2026-09-03T23:52:58Z

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

It's a good idea to open an issue first for discussion.

Tests pass
Appropriate changes to documentation are included in the PR

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.

Julian Gutierrez Oschmann (juli4n) · 2026-09-04T14:02:03Z

+	if !trace.SpanContextFromContext(ctx).IsValid() {
+		return ctx
+	}
+	ctx, _ = otel.Tracer("atepg").Start(ctx, querySpanName(data.SQL),


Is an error here an impossible condition? Are we ok swallowing the error?

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)

Thanks, added some comments around mainly semconv and performance!

Krisztian F (krisztianfekete) · 2026-09-07T12:33:12Z

+	if data.Err != nil && !errors.Is(data.Err, pgx.ErrNoRows) {
+		span.RecordError(data.Err)
+		span.SetStatus(codes.Error, data.Err.Error())
+	}


Is it possible that this is dead code?

You are right, it is dead code. pgx never passes ErrNoRows to TraceQueryEnd. It creates that error for the caller after the rows are already closed, so the tracer only sees the real error from the result reader. I removed the check and the test for it. I also added a test against a real PostgreSQL that does a lookup miss and checks the span stays unmarked.

Krisztian F (krisztianfekete) · 2026-09-07T12:34:04Z

+
+	// 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})


See https://github.com/agent-substrate/substrate/pull/1462/changes#r3949759419 also

Removed together with the ErrNoRows branch.

Krisztian F (krisztianfekete) · 2026-09-07T12:34:58Z

+	sr := tracetest.NewSpanRecorder()
+	tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr))
+	prev := otel.GetTracerProvider()
+	otel.SetTracerProvider(tp)


We have a convention of not swapping the global provider in our tests.

Fixed. The tracer now takes a TracerProvider in its constructor. Connect passes the global one and the tests pass a local recording one, same as the controlapi tests. All tracer tests run with t.Parallel now.

Krisztian F (krisztianfekete) · 2026-09-07T12:36:10Z

+	// Per-statement trace spans; the watch pool inherits this through Copy().
+	cfg.ConnConfig.Tracer = queryTracer{}


Can we add a simple test to assert what the comment states?

Added TestPoolConfigTracerSharedWithWatchPool. It calls poolConfig, copies the config and checks both point to the same tracer.

Krisztian F (krisztianfekete) · 2026-09-07T12:37:46Z

+	if len(fields) == 0 {
+		return "db.query"
+	}
+	return "db." + strings.ToUpper(fields[0])


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/

Done. Span name is now the summary like "SELECT actors" or "UPDATE workers". The store uses one hand written statement per call so a small keyword scan is enough. It takes the first keyword and the table after FROM, INTO, UPDATE or TABLE. If the statement has a JOIN, a subquery or no table, only the keyword is used, as the spec asks. I kept the original casing so BEGIN and COMMIT from pgx show as "begin" and "commit". The test runs the scan over the real statements from the store.

Krisztian F (krisztianfekete) · 2026-09-07T12:40:22Z

+	// 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())


I think we should have access to SQLSTATE here, if so, can we pull it into db.response.status_code + error.type?

Yes, we have it. For a PgError I now set db.response.status_code and error.type to the SQLSTATE. For other errors like a canceled context, error.type is the Go type name. The PostgreSQL test checks a missing table gives 42P01.

Krisztian F (krisztianfekete) · 2026-09-07T12:41:50Z

+	ctx, _ = otel.Tracer("atepg").Start(ctx, querySpanName(data.SQL),
+		trace.WithSpanKind(trace.SpanKindClient),
+		trace.WithAttributes(
+			attribute.String("db.system.name", "postgresql"),


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

Switched to the semconv v1.40.0 constants. Added server.address, server.port, db.namespace, db.operation.name, db.collection.name and db.query.summary. The connection level ones are computed once from the pool config, not per statement, because conn.Config() copies the whole config on every call. Small note, the spec lists server.address as Recommended, not Required, but it is cheap so I added it.

Krisztian F (krisztianfekete) · 2026-09-07T12:44:02Z

+	if !trace.SpanContextFromContext(ctx).IsValid() {
+		return ctx
+	}


Can we use IsSampled() here? Should be identical but cheaper, right?

Good idea. Changed to IsSampled. It is not exactly the same check but it is safe here because every sampler in serverboot is ParentBased, so a child of an unsampled parent can never be sampled. It saves the non recording span and the context wrap on every statement. I left a comment in the code about the ParentBased assumption. I also made TraceQueryEnd only end a span that TraceQueryStart opened, so an unsampled parent is never touched.

Krisztian F (krisztianfekete) · 2026-09-07T12:46:44Z

+	if !trace.SpanContextFromContext(ctx).IsValid() {
+		return ctx
+	}
+	ctx, _ = otel.Tracer("atepg").Start(ctx, querySpanName(data.SQL),


Can we cache the tracer in a struct field instead of resolving it per statement?

Done. The tracer is resolved once in the constructor and kept in a struct field. This also gives the tests a place to inject their provider.

Krisztian F (krisztianfekete) · 2026-09-07T12:48:51Z

+func querySpanName(sql string) string {
+	fields := strings.Fields(sql)
+	if len(fields) == 0 {
+		return "db.query"
+	}
+	return "db." + strings.ToUpper(fields[0])
+}


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.

I would keep them. In pgx, Begin and Commit are normal Exec calls, so each one is a real round trip to the server. COMMIT is where the WAL flush waits, so a lot of the PostgreSQL time we want to see in the trace lands in that span. If we skip it, the gap shows up as unexplained time in the parent span again.

The noise is also smaller than it looks. Only three transactions in atepg.go run on the request path. The outbox ones run in background work with no parent span, so they never produce spans.

I like the idea of one INTERNAL span per transaction with the statements nested under it. That needs a small helper around pool.Begin in the store, so I would do it in a follow up PR to keep this one focused on the pgx tracer. Is that ok with you?

Sure, would you mind opening an issue to track this?

Sure, opened #1537.

Review follow-ups for the pgx QueryTracer. Spans are named by their query summary ("SELECT actors", "commit") and carry db.operation.name, db.collection.name, db.query.summary, server.address, server.port and db.namespace from the semconv v1.40.0 package, with the connection-level attributes computed once from the pool configuration. A failed statement records its SQLSTATE as db.response.status_code and error.type; other errors report their Go type. The tracer is resolved once, in a constructor that takes the TracerProvider, so tests inject a local recording provider instead of swapping the global one. Statements under an unsampled parent are skipped with IsSampled, which is safe because every serverboot sampler is ParentBased, and TraceQueryEnd only ends a span that TraceQueryStart opened. The pgx.ErrNoRows check is gone: pgx synthesizes that error for the caller after the rows are closed, so it never reached the tracer. A test against the PostgreSQL testcontainer checks the span sequence that real pgx calls produce, including begin and commit, an unmarked lookup miss, and SQLSTATE 42P01 for a missing table.

staticcheck SA1019: Value.Emit is deprecated in favor of Value.String.

Krisztian F (krisztianfekete)

Can you please add a few lines to observability docs and maybe docs/dev/best-practices/tracing.md? E.g. saying that the store now emits one span per statement, that it follows the component sampler and has no separate on/off switch, and that begin and commit appear as spans.

Krisztian F (krisztianfekete) · 2026-09-08T17:41:13Z

+	at := -1
+	for i, f := range fields[1:] {
+		switch {
+		case strings.EqualFold(f, "JOIN"):
+			return operation, ""
+		case at < 0 && strings.EqualFold(f, marker):
+			at = i + 2
+		}
+	}


This takes the first FROM, which is the one inside the subquery when the outer SELECT has no table.

If there is a nested SELECT after the first word, can we return no collection? Then both become keyword only.

Good catch, fixed. Now a SELECT that comes before the FROM means the FROM belongs to a subquery, so we return only the keyword. SELECT EXISTS(SELECT 1 FROM t) and SELECT (SELECT xid FROM t) become just SELECT. I check only before the FROM, so SELECT proto FROM actors WHERE name IN (SELECT ...) still gives actors and INSERT INTO t SELECT ... still gives t. Added these cases to the test.

A SELECT that opens before the first FROM owns that FROM, as in SELECT EXISTS(SELECT 1 FROM t), so the outer statement reads no table and the summary is the keyword alone. A subquery after the FROM, or the SELECT feeding an INSERT INTO, leaves the collection in place. The observability guide and the tracing best practices now describe the store spans: one client span per statement named by its query summary, begin and commit included, joining only already sampled traces with no switch of their own, and none from background work.

Da Huang (git286) · 2026-09-08T18:01:05Z

Added the docs. One paragraph in the Tracing section of docs/observability.md and one in the sampling section of docs/dev/best-practices/tracing.md. They say the store emits one client span per statement named by the query summary, that begin and commit show up as spans, that the spans only join a trace that is already sampled so they follow the ateapi sampler and have no switch of their own, and that background work like outbox polling produces no spans.

The subquery case is fixed and the follow up for transaction spans is #1537.

The last run-tests job failed on TestActorLifecycle_WithExternalVolumes, which is the flaky test in #1533. This push runs it again.

Da Huang (git286) requested a review from Julian Gutierrez Oschmann (juli4n) September 3, 2026 23:54

Da Huang (git286) added area/api-machinery area/observability labels Sep 3, 2026

Da Huang (git286) requested a review from Benjamin Elder (BenTheElder) September 3, 2026 23:57

Julian Gutierrez Oschmann (juli4n) reviewed Sep 4, 2026

View reviewed changes

Eitan Yarmush (EItanya) requested a review from Krisztian F (krisztianfekete) September 4, 2026 19:49

Krisztian F (krisztianfekete) reviewed Sep 7, 2026

View reviewed changes

Da Huang (git286) force-pushed the fix-atepg-query-tracing branch from 716f392 to 46dc944 Compare September 8, 2026 15:29

ateapi: use attribute.Value.String in the store tracer test

1fffb91

staticcheck SA1019: Value.Emit is deprecated in favor of Value.String.

Krisztian F (krisztianfekete) reviewed Sep 8, 2026

View reviewed changes

Da Huang (git286) mentioned this pull request Sep 8, 2026

atepg: wrap request path transactions in one span #1537

Open

		// Per-statement trace spans; the watch pool inherits this through Copy().
		cfg.ConnConfig.Tracer = queryTracer{}

Uh oh!

Conversation

Da Huang (git286) commented Sep 3, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Krisztian F (krisztianfekete) left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Krisztian F (krisztianfekete) left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Da Huang (git286) commented Sep 8, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Da Huang (git286) commented Sep 3, 2026 •

edited

Loading