sql: TestLogic_upsert_non_metamorphic failed due to too large batch size

[cockroach-teamcity]

pkg/sql/logictest/tests/fakedist-vec-off/fakedist-vec-off_test.TestLogic_upsert_non_metamorphic failed on master @ 53e4efd389167110d687e5dea8bf915fe2582a25:

    defer srv.Stopper().Stop(...)
    ts := srv.ApplicationLayer()

See also: https://go.crdb.dev/p/testserver-and-cluster-virtualization

pkg/testutils/physicalplanutils/fake_resolver.go:27: (FakeResolverForTestCluster)
	NOTICE: .NodeID() called via implicit interface StorageLayerInterface;
HINT: consider using .StorageLayer().NodeID() instead.

pkg/testutils/physicalplanutils/fake_resolver.go:28: (FakeResolverForTestCluster)
	NOTICE: .AdvRPCAddr() called via implicit interface ApplicationLayerInterface;
HINT: consider using .ApplicationLayer().AdvRPCAddr() instead.
TIP: consider replacing the test server initialization from:
    ts, ... := serverutils.StartServer(t, ...)
    defer ts.Stopper().Stop(...)
to:
    srv, ... := serverutils.StartServer(t, ...)
    defer srv.Stopper().Stop(...)
    ts := srv.ApplicationLayer()

See also: https://go.crdb.dev/p/testserver-and-cluster-virtualization

pkg/testutils/physicalplanutils/fake_resolver.go:27: (FakeResolverForTestCluster)
	NOTICE: .NodeID() called via implicit interface StorageLayerInterface;
HINT: consider using .StorageLayer().NodeID() instead.

pkg/testutils/physicalplanutils/fake_resolver.go:28: (FakeResolverForTestCluster)
	NOTICE: .AdvRPCAddr() called via implicit interface ApplicationLayerInterface;
HINT: consider using .ApplicationLayer().AdvRPCAddr() instead.
TIP: consider replacing the test server initialization from:
    ts, ... := serverutils.StartServer(t, ...)
    defer ts.Stopper().Stop(...)
to:
    srv, ... := serverutils.StartServer(t, ...)
    defer srv.Stopper().Stop(...)
    ts := srv.ApplicationLayer()

See also: https://go.crdb.dev/p/testserver-and-cluster-virtualization
[10:13:42] --- progress: /var/lib/engflow/worker/work/3/exec/bazel-out/k8-fastbuild/bin/pkg/sql/logictest/tests/fakedist-vec-off/fakedist-vec-off_test_/fakedist-vec-off_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/logictest/testdata/logic_test/upsert_non_metamorphic: 2 statements
[10:13:48] --- done: /var/lib/engflow/worker/work/3/exec/bazel-out/k8-fastbuild/bin/pkg/sql/logictest/tests/fakedist-vec-off/fakedist-vec-off_test_/fakedist-vec-off_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/logictest/testdata/logic_test/upsert_non_metamorphic with config fakedist-vec-off: 3 tests, 0 failures
    logic.go:4005: 
        /var/lib/engflow/worker/work/3/exec/bazel-out/k8-fastbuild/bin/pkg/sql/logictest/tests/fakedist-vec-off/fakedist-vec-off_test_/fakedist-vec-off_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/logictest/testdata/logic_test/upsert_non_metamorphic:22: error while processing
    logic.go:4005: 
        /var/lib/engflow/worker/work/3/exec/bazel-out/k8-fastbuild/bin/pkg/sql/logictest/tests/fakedist-vec-off/fakedist-vec-off_test_/fakedist-vec-off_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/logictest/testdata/logic_test/upsert_non_metamorphic:22: 
        expected success, but found
        (XXUUU) command is too large: 4207837 bytes (max: 4194304)
        replica_raft.go:271: in evalAndPropose()
    panic.go:541: -- test log scope end --
test logs left over in: outputs.zip/logTestLogic_upsert_non_metamorphic2229304595
--- FAIL: TestLogic_upsert_non_metamorphic (26.41s)

Parameters:

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

Help

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

/cc @cockroachdb/sql-queries

This test on roachdash | Improve this report!

Jira issue: CRDB-34955

[michae2]

Looks like this is a dupe of #116762, but that was closed by skipping 3-node-tenant under race.

I was not able to reproduce this by running for an hour on a gceworker with:

./dev test pkg/sql/logictest/tests/fakedist-vec-off --filter=TestLogic_upsert_non_metamorphic --race --stress --count 10000

[DrewKimball]

I notice the mutations continue adding to a batch until the condition *.ApproximateMutationBytes() >= maxBatchByteSize returns true, which means we'll tend to overrun the limit in memory-intensive cases. We could fix that, but since the default mutation batch size is significantly smaller than the default raft command size, it shouldn't be too much of a problem in practice. So, maybe we should just fix the test by slightly increasing the command size limit, say, to 5mb.

[rharding6373]

Removing release-blocker label since we believe this to be an unrealistic batch size setup.

[DrewKimball]

I haven't been able to reproduce, but I'm pretty sure the issue I mentioned here is what's causing the failure. The test uses rows of size ~100KB, and the failures show the limit exceeded by ~10KB.

For the related copy test TestLargeDynamicRows failures, the rows are ~2MB. Copy conservatively uses 1/3 of the max command size as its limit, but also suffers from the problem that it checks whether it's exceeded the limit after adding a row to the next batch. Since a single row is already half the max command size, its easy to create a batch that exceeds the limit.

[rytaft]

[triage] maybe we could make limit 5 MB instead of 4 in the test?

[rytaft]

This keeps failing, so increasing the priority to P-2

[mgartner]

We need to:

• backport go.mod: bump Pebble to 0be5a7466e36 #123247
• apply the same change to roachtests—those are the ones still failing

[DrewKimball]

It looks like the roachtest failures are using the default command size limit, so the same fix might not apply.

[yuzefovich]

I'm lowering this to P-3 since we haven't seen this failure in logic tests in a while and moving it to the backlog. Note that there is a separate issue for the COPY roachtest #121413 which seems more frequent, so that one is still P-2.

[yuzefovich]

We actually haven't had a failure in unit tests since #120766 merged about two months ago. All recent failures were in the roachtest (tracked in #121413 the fix to which is being merged right now), so I think it's safe to close this issue as having been fixed by #120766