sql: TestExplainAnalyzeDebug failed

[cockroach-teamcity]

sql.TestExplainAnalyzeDebug failed with artifacts on master @ c6bf8649e12010033f6fe9038884147bb4521ca7:

=== RUN   TestExplainAnalyzeDebug
    test_log_scope.go:172: test logs captured to: /artifacts/tmp/_tmp/492cc08314ebb30515b6f60e383090f4/logTestExplainAnalyzeDebug2346279296
    test_log_scope.go:82: use -show-logs to present logs inline
    test_server_shim.go:95: cluster virtualization disabled due to issue: #155944 (expected label: C-bug)
    explain_bundle_test.go:1407: -- test log scope end --
--- FAIL: TestExplainAnalyzeDebug (23.54s)
=== RUN   TestExplainAnalyzeDebug/with_in-flight_trace
    explain_bundle_test.go:1539: unexpected list of files:
          [descriptors.json distsql.html env.sql opt-v.txt opt-vv.txt opt.txt plan.txt schema.sql schema_changes.txt statement.sql trace-jaeger.json trace.json trace.txt vec-v.txt vec.txt]
        expected:
          [descriptors.json distsql.html env.sql inflight-trace-jaeger-n1.json inflight-trace-n1.txt opt-v.txt opt-vv.txt opt.txt plan.txt schema.sql schema_changes.txt statement.sql trace-jaeger.json trace.json trace.txt vec-v.txt vec.txt]
--- FAIL: TestExplainAnalyzeDebug/with_in-flight_trace (1.39s)

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

Jira issue: CRDB-64877

[michae2]

/investigate

[github-actions]

Investigation: TestExplainAnalyzeDebug/with_in-flight_trace

Investigated failure: #171742 (issue body)
Failure SHA: c6bf8649e12010033f6fe9038884147bb4521ca7
Confidence: high (known flake pattern, same failure mode as prior occurrences)

What This Test Does

TestExplainAnalyzeDebug/with_in-flight_trace verifies that when the cluster setting sql.stmt_diagnostics.in_flight_trace_collector.poll_interval is non-zero, the EXPLAIN ANALYZE (DEBUG) statement bundle includes in-flight trace files (inflight-trace-n1.txt and inflight-trace-jaeger-n1.json). It sets the poll interval to 250ms, then runs SELECT pg_sleep(1) expecting the collector goroutine to poll at least once during the 1s sleep window.

Where the Failure Occurs

The test fails at the file list comparison in checkBundleContents at explain_bundle_test.go:1630. The bundle is missing inflight-trace-n1.txt and inflight-trace-jaeger-n1.json:

actual:   [descriptors.json distsql.html env.sql opt-v.txt opt-vv.txt opt.txt plan.txt schema.sql schema_changes.txt statement.sql trace-jaeger.json trace.json trace.txt vec-v.txt vec.txt]
expected: [descriptors.json distsql.html env.sql inflight-trace-jaeger-n1.json inflight-trace-n1.txt opt-v.txt opt-vv.txt opt.txt plan.txt schema.sql schema_changes.txt statement.sql trace-jaeger.json trace.json trace.txt vec-v.txt vec.txt]

Analysis

Hypothesis: Timing-sensitive race between the in-flight trace collector and query completion (likely cause, high confidence)

The in-flight trace collector works as follows (instrumentation.go:374-412):

1. A goroutine is started that sleeps for the poll interval (250ms), then calls pollInFlightTrace.
2. pollInFlightTrace issues a gRPC call via the crdb_internal.cluster_inflight_traces virtual table (instrumentation.go:320-341).
3. The gRPC call goes through DialTracingClient to reach the local node (collector.go:150).
4. When pg_sleep(1) finishes, the main goroutine calls inFlightTraceCollector.finish() which cancels the collector context.

The race: The collector needs to complete at least one full poll cycle (250ms wait + gRPC dial + query execution) within the ~1s window that pg_sleep(1) provides. If gRPC dial to the local node takes too long (e.g. >750ms), the poll never succeeds before cancellation.

In the prior occurrence (#151987 on s390x), server logs confirmed the same pattern: "getting span recordings from instance 1" was logged, but the subsequent DialTracingClient call took >1s, resulting in "failed to dial instance 1: gRPC: dial: context canceled". The entire in-flight trace collection returned zero traces.

This failure ran on AWS arm64 (Big VM, agent aws-arm-big-ppr-20260309--i-09e03708d90b6043c). The subtest completed in 1.39s (only 0.39s more than the 1s sleep), leaving a very tight margin for the collector.

When no traces are collected and no errors are present (the context cancellation error is intentionally ignored), addInFlightTrace in explain_bundle.go:537-556 simply doesn't add any inflight trace files to the bundle.

Potential fixes:

• Increase pg_sleep duration (e.g. to 3s) to give more margin for the collector goroutine.
• Decrease the poll interval further (e.g. to 50ms).
• Use testutils.SucceedsSoon or a retry loop instead of a fixed sleep.
• Add a synchronization mechanism to confirm the collector has polled at least once before allowing the query to finish.

Related Issues and PRs

Issue	Status	Failure Mode	Notes
#171742	Open	Missing inflight-trace files (arm64)	This failure
#171327	Closed	Missing inflight-trace files (s390x)	Same failure mode, closed as infra flake
#151987	Closed	Missing inflight-trace files (s390x)	Same failure mode. Logs confirmed gRPC dial timeout. Closed as one-off
#163120	Closed	Data race on master	Different failure mode (race detector)
#162406	Closed	Data race on master	Different failure mode (race detector)
#110186	Closed	Data race on master	Different failure mode (race detector)

All three "missing inflight-trace files" failures (#171742, #171327, #151987) share the exact same error signature and root cause. This is a recurring flake.

Timeline

• 2025-08-16: First occurrence of this specific flake pattern (sql: TestExplainAnalyzeDebug failed #151987, s390x, release-25.3). Closed as one-off.
• 2026-06-02: Second occurrence (sql: TestExplainAnalyzeDebug failed #171327, s390x, release-25.4). Closed as infra flake.
• 2026-06-02: Commit 3eb31daea11 added descriptors.json and schema_changes.txt to bundles (explaining their presence in the new expected file list).
• 2026-06-17: Third occurrence (sql: TestExplainAnalyzeDebug failed #171742, arm64, master). This failure. Now also labeled release-blocker.

The flake appears to be architecture-sensitive (s390x twice, arm64 once), suggesting slower environments are more susceptible to the gRPC dial latency issue.

Detailed evidence and investigation notes

Log Excerpts

From the test.log (shard 3):

=== RUN   TestExplainAnalyzeDebug/with_in-flight_trace
    explain_bundle_test.go:1539: unexpected list of files:
          [descriptors.json distsql.html env.sql opt-v.txt opt-vv.txt opt.txt plan.txt schema.sql schema_changes.txt statement.sql trace-jaeger.json trace.json trace.txt vec-v.txt vec.txt]
        expected:
          [descriptors.json distsql.html env.sql inflight-trace-jaeger-n1.json inflight-trace-n1.txt opt-v.txt opt-vv.txt opt.txt plan.txt schema.sql schema_changes.txt statement.sql trace-jaeger.json trace.json trace.txt vec-v.txt vec.txt]
--- FAIL: TestExplainAnalyzeDebug/with_in-flight_trace (1.39s)

From #151987 (prior occurrence with server logs available):

I250816 18:20:23.326947 ... SET CLUSTER SETTING "sql.stmt_diagnostics.in_flight_trace_collector.poll_interval" = '0.25s'
I250816 18:20:23.578911 ... [intExec=bundle-in-flight-trace] getting span recordings from instance 1
W250816 18:20:24.628767 ... [intExec=bundle-in-flight-trace] failed to dial instance 1: gRPC: dial: context canceled
I250816 18:20:24.661692 ... SET CLUSTER SETTING "sql.stmt_diagnostics.in_flight_trace_collector.poll_interval" = '0s'

The gap between "getting span recordings" (18:20:23.578) and "failed to dial" (18:20:24.628) is ~1.05s, confirming the gRPC dial consumed the entire pg_sleep(1) window.

Code References

The test at explain_bundle_test.go:1197-1207:

t.Run("with in-flight trace", func(t *testing.T) {
    r.Exec(t, "SET CLUSTER SETTING sql.stmt_diagnostics.in_flight_trace_collector.poll_interval = '0.25s'")
    defer r.Exec(t, "SET CLUSTER SETTING sql.stmt_diagnostics.in_flight_trace_collector.poll_interval = '0s'")
    rows := r.QueryStr(t, "EXPLAIN ANALYZE (DEBUG) SELECT pg_sleep(1)")
    checkBundle(
        t, fmt.Sprint(rows), "" /* tableName */, nil /* contentCheck */, false, /* expectErrors */
        base, plans, "distsql.html vec.txt vec-v.txt inflight-trace-n1.txt inflight-trace-jaeger-n1.json",
    )
})

The collector goroutine at instrumentation.go:381-412 waits for the poll interval before its first poll, then makes a gRPC call to crdb_internal.cluster_inflight_traces. If the first poll doesn't complete before pg_sleep(1) finishes, no traces are captured.

Things Ruled Out

• Recent code change causing regression: No changes to the inflight trace collector logic. The addition of descriptors.json and schema_changes.txt (commit 3eb31daea11) only added new files to the bundle and doesn't affect the inflight trace collection path.
• Data race: The current failure does not show any race detector output. Prior issues sql: TestExplainAnalyzeDebug failed #162406 and sql: TestExplainAnalyzeDebug failed #163120 had data race failures, but those are a different failure mode.
• Test logic bug: The test logic is correct. The issue is that the timing margins are too tight for slower environments.

Other Failure Occurrences

All three occurrences of this specific flake (missing inflight-trace files without errors) share the exact same error signature. The only difference is that the most recent failure includes descriptors.json and schema_changes.txt in both actual and expected file lists, which were added in June 2026. The earlier data race issues (#162406, #163120, #110186) are a distinct failure mode unrelated to this timing issue.

Tooling Feedback

• Could not check out the failure SHA (c6bf8649e12010033f6fe9038884147bb4521ca7) due to the blobless clone not having this commit reachable from the remote. Analysis was performed on the default branch tip, but the relevant code paths haven't changed since the failure SHA. A warning was not added to the top because the code analysis is still accurate.
• CockroachDB server logs for this specific failure were not available as separate artifacts (they were captured to a test log scope directory that isn't uploaded). The prior occurrence (sql: TestExplainAnalyzeDebug failed #151987) had server logs that confirmed the diagnosis.

---

Investigation triggered by this workflow run.

---

Was this investigation helpful? Leave a 👍 or 👎 on this comment.

[cockroach-teamcity]

sql.TestExplainAnalyzeDebug failed on master @ afb18ae81089acefa42004b206ebe97247534376:

=== RUN   TestExplainAnalyzeDebug
    test_log_scope.go:172: test logs captured to: outputs.zip/logTestExplainAnalyzeDebug1897422968
    test_log_scope.go:82: use -show-logs to present logs inline
    test_server_shim.go:95: cluster virtualization disabled due to issue: #155944 (expected label: C-bug)
    explain_bundle_test.go:719: error scanning '&{<nil> 0x1a7f91dc8c0}': sql: no rows in result set
    panic.go:694: -- test log scope end --
test logs left over in: outputs.zip/logTestExplainAnalyzeDebug1897422968
--- FAIL: TestExplainAnalyzeDebug (42.16s)
=== RUN   TestExplainAnalyzeDebug/deferred_routine_body_via_builtin
    testing.go:1913: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
--- FAIL: TestExplainAnalyzeDebug/deferred_routine_body_via_builtin (1.51s)
=== RUN   TestExplainAnalyzeDebug/deferred_routine_body_via_builtin/gist_match
    testing.go:1913: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
--- FAIL: TestExplainAnalyzeDebug/deferred_routine_body_via_builtin/gist_match (0.46s)

Parameters:

• attempt=1
• deadlock=true
• run=3
• shard=3

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

[cockroach-teamcity]

sql.TestExplainAnalyzeDebug failed on master @ 341fc15083f416a82fc22fbd8f5de6af2db1f40c:

=== RUN   TestExplainAnalyzeDebug
    test_log_scope.go:172: test logs captured to: outputs.zip/logTestExplainAnalyzeDebug1403033702
    test_log_scope.go:82: use -show-logs to present logs inline
    test_server_shim.go:95: cluster virtualization disabled due to issue: #155944 (expected label: C-bug)
    explain_bundle_test.go:719: error scanning '&{<nil> 0xc023657360}': sql: no rows in result set
    panic.go:694: -- test log scope end --
test logs left over in: outputs.zip/logTestExplainAnalyzeDebug1403033702
--- FAIL: TestExplainAnalyzeDebug (121.31s)
=== RUN   TestExplainAnalyzeDebug/deferred_routine_body_via_builtin
    testing.go:1913: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
--- FAIL: TestExplainAnalyzeDebug/deferred_routine_body_via_builtin (13.15s)
=== RUN   TestExplainAnalyzeDebug/deferred_routine_body_via_builtin/gist_match
    testing.go:1913: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
--- FAIL: TestExplainAnalyzeDebug/deferred_routine_body_via_builtin/gist_match (4.85s)

Parameters:

• attempt=1
• race=true
• run=1
• shard=3

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

[cockroach-teamcity]

sql.TestExplainAnalyzeDebug failed on master @ 73365ac18ba5e57e1566654035730b7fe137c0b7:

=== RUN   TestExplainAnalyzeDebug
    test_log_scope.go:172: test logs captured to: outputs.zip/logTestExplainAnalyzeDebug741530198
    test_log_scope.go:82: use -show-logs to present logs inline
    test_server_shim.go:95: cluster virtualization disabled due to issue: #155944 (expected label: C-bug)
    explain_bundle_test.go:719: error scanning '&{<nil> 0xc0255b1540}': sql: no rows in result set
    panic.go:694: -- test log scope end --
test logs left over in: outputs.zip/logTestExplainAnalyzeDebug741530198
--- FAIL: TestExplainAnalyzeDebug (131.43s)
=== RUN   TestExplainAnalyzeDebug/deferred_routine_body_via_builtin
    testing.go:1913: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
--- FAIL: TestExplainAnalyzeDebug/deferred_routine_body_via_builtin (13.05s)
=== RUN   TestExplainAnalyzeDebug/deferred_routine_body_via_builtin/gist_match
    testing.go:1913: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
--- FAIL: TestExplainAnalyzeDebug/deferred_routine_body_via_builtin/gist_match (5.03s)

Parameters:

• attempt=1
• race=true
• run=1
• shard=3

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

[cockroach-teamcity]

sql.TestExplainAnalyzeDebug failed on master @ 73365ac18ba5e57e1566654035730b7fe137c0b7:

=== RUN   TestExplainAnalyzeDebug
    test_log_scope.go:172: test logs captured to: outputs.zip/logTestExplainAnalyzeDebug1843912959
    test_log_scope.go:82: use -show-logs to present logs inline
    test_server_shim.go:95: cluster virtualization disabled due to issue: #155944 (expected label: C-bug)
    explain_bundle_test.go:719: error scanning '&{<nil> 0xc0231814a0}': sql: no rows in result set
    panic.go:694: -- test log scope end --
test logs left over in: outputs.zip/logTestExplainAnalyzeDebug1843912959
--- FAIL: TestExplainAnalyzeDebug (145.34s)
=== RUN   TestExplainAnalyzeDebug/deferred_routine_body_via_builtin
    testing.go:1913: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
--- FAIL: TestExplainAnalyzeDebug/deferred_routine_body_via_builtin (13.77s)
=== RUN   TestExplainAnalyzeDebug/deferred_routine_body_via_builtin/gist_match
    testing.go:1913: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test
--- FAIL: TestExplainAnalyzeDebug/deferred_routine_body_via_builtin/gist_match (5.33s)

Parameters:

• attempt=1
• race=true
• run=1
• shard=3

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!