pkg/sql/logictest/tests/5node/5node_test: TestLogic_distsql_stats failed

[github-actions]

pkg/sql/logictest/tests/5node/5node_test.TestLogic_distsql_stats failed on master @ e440b11dbd3c14f27e202ece2acff2d0777d9555:

github.com/cockroachdb/cockroach/pkg/kv.(*DB).TxnWithAdmissionControl(0xbeb7f2c4d00?, {0x7d966d0, 0xbeb81355950}, 0x73f3900?, 0x0?, 0x0, 0xbeb7f79bd40)
	pkg/kv/db.go:1125 +0xf5
github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).txn.func2({0x7d966d0?, 0xbeb81355950?}, 0x6762fa0?)
	pkg/sql/internal.go:2050 +0x3b
github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).txn(0xbeb5d472bd0, {0x7d966d0, 0xbeb81355950}, 0xbeb5cd40060, {0xbeb7f2c4ef8, 0x1, 0xbeb7f2c4e01?})
	pkg/sql/internal.go:2064 +0x285
github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).Txn(0xbeb5d472bd0, {0x7d966d0, 0xbeb81355950}, 0xbeb7f73c5a0, {0xbeb7f2c4ef8, 0x1, 0x1})
	pkg/sql/internal.go:1985 +0x97
github.com/cockroachdb/cockroach/pkg/sql.(*createStatsResumer).Resume(0xbeb78c6e518, {0x7d966d0, 0xbeb81355950}, {0x73de600?, 0xbeb78c6e5a8})
	pkg/sql/create_stats.go:1064 +0x58a
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine.func2(0xbeb8a88fc80?, 0x0?, 0xbeb6d51f8e8, {0x7d7de30?, 0xbeb78c6e518?}, {0x7d966d0?, 0xbeb81355950?}, {0x73de600?, 0xbeb78c6e5a8?})
	pkg/jobs/registry.go:1663 +0xb4
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine(0xbeb5d9d2808, {0x7d966d0, 0xbeb81355680}, {0x73de600, 0xbeb78c6e5a8}, {0x7d7de30, 0xbeb78c6e518}, 0xbeb8a88fc80, {0x77ffcbd, 0x7}, ...)
	pkg/jobs/registry.go:1664 +0xb7f
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).runJob(0xbeb5d9d2808, {0x7d966d0, 0xbeb81355680}, {0x7d7de30, 0xbeb78c6e518}, 0xbeb8a88fc80, {0x77ffcbd, 0x7}, {0xbeb92d84840, 0x17})
	pkg/jobs/adopt.go:503 +0x585
github.com/cockroachdb/cockroach/pkg/jobs.(*StartableJob).Start.func2({0xbeb8cf15b40?, 0x7d972b8?})
	pkg/jobs/jobs.go:812 +0xe5
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1({0x7d972b8, 0xbeb7f50b180})
	pkg/util/stop/stopper.go:447 +0x8a
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx in goroutine 7639
	pkg/util/stop/stopper.go:445 +0x125

goroutine 18331 [sync.Cond.Wait, "pebble":"wal-sync"]:
sync.runtime_notifyListWait(0xbeb72de20a8, 0x7e3)
	GOROOT/src/runtime/sema.go:617 +0x1b3
sync.(*Cond).Wait(0xbeb60e0a0d0?)
	GOROOT/src/sync/cond.go:71 +0x73
github.com/cockroachdb/pebble/record.(*flusherCond).Wait(...)
	external/com_github_cockroachdb_pebble/record/log_writer.go:371
github.com/cockroachdb/pebble/record.(*LogWriter).flushLoop(0xbeb72de2000, {0x6b6dc40?, 0xda56bc0?})
	external/com_github_cockroachdb_pebble/record/log_writer.go:682 +0x197
runtime/pprof.Do({0x7d964c0?, 0xda56bc0?}, {{0xbeb5b4a7800?, 0xbeb73472130?, 0xc723c0?}}, 0xbeb792befc0)
	GOROOT/src/runtime/pprof/runtime.go:57 +0x8c
github.com/cockroachdb/pebble/record.NewLogWriter.func2()
	external/com_github_cockroachdb_pebble/record/log_writer.go:596 +0x50
created by github.com/cockroachdb/pebble/record.NewLogWriter in goroutine 8698
	external/com_github_cockroachdb_pebble/record/log_writer.go:595 +0x558

goroutine 504142 [chan receive, "distsql.appname":"$ internal-resume-job-1172565656189501441", "distsql.gateway":"1", "distsql.txn":"c9e51573-8a64-43a5-b592-6b1d902a6de9", "f":"91609c97", "job":"CREATE STATS id=1172565656189501441", "n":"5"]:
github.com/cockroachdb/cockroach/pkg/sql/execinfra.(*RowChannel).Next(0x0?)
	pkg/sql/execinfra/base.go:448 +0x28
github.com/cockroachdb/cockroach/pkg/sql/rowexec.(*sampleAggregator).mainLoop(0xbeb7f924008, {0x7d966d0, 0xbeb7f73de90}, {0x7d603f0, 0xbeb7f813508})
	pkg/sql/rowexec/sample_aggregator.go:261 +0x182
github.com/cockroachdb/cockroach/pkg/sql/rowexec.(*sampleAggregator).Run(0xbeb7f924008, {0x7d966d0?, 0xbeb7f73de90?}, {0x7d603f0, 0xbeb7f813508})
	pkg/sql/rowexec/sample_aggregator.go:209 +0x129
github.com/cockroachdb/cockroach/pkg/sql/flowinfra.(*FlowBase).StartInternal.func1(0x1?)
	pkg/sql/flowinfra/flow.go:518 +0x122
created by github.com/cockroachdb/cockroach/pkg/sql/flowinfra.(*FlowBase).StartInternal in goroutine 504138
	pkg/sql/flowinfra/flow.go:513 +0x434

Parameters:

• attempt=1
• run=1
• shard=15

Help

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

This test on roachdash | Improve this report!

Jira issue: CRDB-63606

[ZhouXing19]

/investigate

[github-actions]

Investigation: TestLogic_distsql_stats

Investigated failure: #169671
Failure SHA: e440b11dbd3c14f27e202ece2acff2d0777d9555
Confidence: moderate

What This Test Does

TestLogic_distsql_stats runs the distsql_stats logic test with a 5-node cluster. It exercises distributed statistics collection (CREATE STATISTICS) on various tables, including a 20,000-row table called big with 20,000 histogram buckets.

Where the Failure Occurs

The test times out after 15 minutes. It gets stuck at the second CREATE STATISTICS s_dynamic FROM big statement (line 200 of distsql_stats, approximately the 33rd test statement). The goroutine dump shows a samplerProcessor goroutine (504141) in [runnable] state, stuck in a table scan via ScanConflictingIntentsForDroppingLatchesEarly → Pebble iteration:

• sampler.go:248 → tablereader.go:276 → fetcher.go:745 → replica_read.go:429 → engine.go:2040

The sampleAggregator (goroutine 504142) is blocked on RowChannel.Next() waiting for data from the sampler, and the flow's Wait (goroutine 504144) is blocked waiting for the flow goroutines to finish.

Analysis

Hypothesis: Extremely low default-batch-bytes-limit metamorphic constant causes excessive round-trips (confidence: high)

The test run's metamorphic constants include:

• default-batch-bytes-limit = 81 (bytes) — the production default is much larger; the metamorphic range is [1, 64KiB]
• distsql_workmem = 26342B (~26KB) — also very low

With default-batch-bytes-limit=81, each KV Scan request returns only ~81 bytes of results. The big table has 20,000 rows of INT PRIMARY KEY data (~360KB total). This means the stats collection needs ~4,400+ individual batch requests to scan the entire table, compared to perhaps a handful under normal batch sizes.

Each batch request follows the full KV send path, including:

1. ScanConflictingIntentsForDroppingLatchesEarly — scanning the lock table for conflicting intents before evaluation
2. Transaction management for the inconsistent scan (via StartInconsistentScan)
3. Regular Pebble iteration for actual data

The goroutine dump confirms the sampler is actively running (state: [runnable]) in the Pebble iteration layer at colblk.RawBytes.At — the scan is progressing but is extremely slow due to the overhead of thousands of tiny batches.

Timeline:

• 15:26:21 — Test starts, first few statements pass quickly
• 15:31:48 — 30 statements done (includes first CREATE STATISTICS s_dynamic FROM big which took ~5.5 min)
• 15:37:20 — 32 statements done (second CREATE STATISTICS s_dynamic FROM big started)
• 15:41:15 — Test times out after 15 minutes; second stats collection still running after ~4 minutes with no completion

The first CREATE STATISTICS on big already took ~5.5 minutes (vs near-instant under normal batch sizes). The second one likely would have taken similar time but the cumulative duration exceeded the 15-minute test timeout.

Why this is a flake, not a deterministic failure: The default-batch-bytes-limit is a metamorphic constant randomly chosen from [1, 64KiB]. Values near the minimum (like 81) are rare and cause the pathological slowness. Most test runs pick larger values and complete in time.

Possible fixes:

1. Increase the test timeout for this specific test or shard.
2. Use a smaller table (big) for the dynamic sampling tests — 20,000 rows with 20,000 histogram buckets is expensive even under normal conditions.
3. Clamp default-batch-bytes-limit to a higher minimum in ClampMetamorphicConstantUnderDuress (currently clamped to 10KiB minimum under duress at base.go:50, but this test doesn't run under duress).
4. Override default-batch-bytes-limit to a sane minimum specifically for the stats collection path, since it's already a background operation and extreme low-batch-size testing adds little value there.

Related Issues and PRs

• #151839 (closed) — Same test name, but different failure mode (distribution: full vs distribution: local mismatch at statement 436). Not related.
• #140353 (closed) — Same test name, also a different failure mode (EXPLAIN output mismatch). Was caused by PR #150238. Not related.
• #141979 (closed) — Same test name, different failure. Not related.
• #160337 (closed) — sampleAggregator.Run() panic causing goroutine deadlock. Different root cause (panic in truncateDatum), but same code path. Not related to this timeout.
• #127649 (open) — Memory exceeded in sampleAggregator causes stats collection to fail. Related area but different symptom.

Timeline

No recent changes to the test file or the core stats collection code. The default-batch-bytes-limit metamorphic constant has existed for a long time with range [1, 64KiB]. This failure is a rare metamorphic flake triggered by an unlucky combination of very low default-batch-bytes-limit (81) and a test workload that does multiple full table scans on a 20,000-row table.

Detailed evidence and investigation notes

Log Excerpts

Test progress (from test.log):

[15:26:18] setting distsql_workmem='26342B';
[15:26:21] --- progress: distsql_stats: 5 statements
[15:31:48] --- progress: distsql_stats: 30 statements
[15:37:20] --- progress: distsql_stats: 32 statements
-- Test timed out at 2026-05-04 15:41:15 Universal --
panic: test timed out after 15m0s

Key metamorphic constants:

initialized metamorphic constant "default-batch-bytes-limit" with value 81
initialized metamorphic constant "kv.concurrency.virtual_intent_resolution.enabled" with value true

Stuck goroutine (504141) — samplerProcessor scanning table:

goroutine 504141 [runnable, "job":"CREATE STATS id=1172565656189501441", "n":"5"]:
github.com/cockroachdb/pebble/sstable/colblk.RawBytes.At(...)
  → keyspanIter.materializeSpan → keyspanIter.SeekGE → mergingIter.initMinRangeDelIters
  → mergingIter.Next → Iterator.nextUserKey → Iterator.SeekGE
  → pebbleIterator.SeekEngineKeyGE → LockTableIterator.SeekEngineKeyGE
  → ScanConflictingIntentsForDroppingLatchesEarly
  → canDropLatchesBeforeEval → executeReadOnlyBatch → ...
  → tableReader.Next → samplerProcessor.mainLoop

Blocked sampleAggregator (504142) — waiting for sampler data:

goroutine 504142 [chan receive, "job":"CREATE STATS id=1172565656189501441"]:
  RowChannel.Next → sampleAggregator.mainLoop → sampleAggregator.Run

Code References

• default-batch-bytes-limit metamorphic constant: rowinfra/base.go:43-50
• ScanConflictingIntentsForDroppingLatchesEarly: engine.go:1977-2040
• canDropLatchesBeforeEval: replica_read.go:394-451
• Stats collection via StartInconsistentScan: fetcher.go:667-754
• samplerProcessor.mainLoop: sampler.go:234-248
• Test file statement at line 200: distsql_stats:200 — CREATE STATISTICS s_dynamic FROM big

Things Ruled Out

• sampleAggregator panic/deadlock (rowexec: a panic in sampleAggregator.Run() can cause a goroutine deadlock #160337): No panic occurred; the goroutine was still running. The sampleAggregator was correctly waiting for input.
• EXPLAIN output mismatch (pkg/sql/logictest/tests/5node/5node_test: TestLogic_distsql_stats failed #140353, pkg/sql/logictest/tests/5node/5node_test: TestLogic_distsql_stats failed #151839): The test didn't reach the EXPLAIN statements — it timed out much earlier during CREATE STATISTICS.
• Recent code changes: No recent changes to stats collection, sampler, or batch bytes limit code. This is a pure metamorphic flake.
• Memory pressure: The distsql_workmem=26342B is low but not the primary cause. It constrains the sampler's memory budget but the bottleneck is the scan throughput, not memory.

Other Failure Occurrences

This is the first occurrence in this issue. Previous issues with the same test name had different failure modes (EXPLAIN output mismatches, not timeouts during CREATE STATISTICS).

Tooling Feedback

No issues with available tooling. The EngFlow artifact download script worked well.

---

Workflow run

---

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