Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ccl/multiregionccl: TestMultiRegionDataDriven failed #99563

Closed
cockroach-teamcity opened this issue Mar 25, 2023 · 10 comments
Closed

ccl/multiregionccl: TestMultiRegionDataDriven failed #99563

cockroach-teamcity opened this issue Mar 25, 2023 · 10 comments
Assignees
@chengxiong-ruan
Labels
branch-release-23.1 Used to mark GA and release blockers, technical advisories, and bugs for 23.1 C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. skipped-test T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions)
Milestone
23.1

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Mar 25, 2023 •
edited by cockroach-jira-scripts
Loading

ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-23.1 @ f351747ed97862fc037717cadec23f18073fb6be:

=== RUN   TestMultiRegionDataDriven
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/e558fc8050776f4c54ea39ba371b49da/logTestMultiRegionDataDriven1641751117
    test_log_scope.go:79: use -show-logs to present logs inline
=== CONT  TestMultiRegionDataDriven
    datadriven_test.go:436: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/e558fc8050776f4c54ea39ba371b49da/logTestMultiRegionDataDriven1641751117
--- FAIL: TestMultiRegionDataDriven (196.98s)
=== RUN   TestMultiRegionDataDriven/regional_by_row
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/492/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:1:
        new-cluster [1 args]
        <no input to command>
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/492/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:4:
        exec-sql [1 args]
        CREATE DATABASE db PRIMARY REGION "us-east-1" REGIONS  "us-west-1", "us-central-1";
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/492/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:8:
        exec-sql [1 args]
        CREATE TABLE db.rbr(k INT PRIMARY KEY, v INT) LOCALITY REGIONAL BY ROW;
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/492/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:12:
        exec-sql [1 args]
        INSERT INTO db.rbr (k, v, crdb_region) VALUES (1, 1, 'us-east-1'), (2, 2, 'us-central-1'), (3, 3, 'us-west-1')
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/492/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:19:
        wait-for-zone-config-changes [8 args]
        <no input to command>
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/492/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:22:
        wait-for-zone-config-changes [8 args]
        <no input to command>
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/492/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:25:
         
        expected:
        
        found:
        could not get leaseholder: no valid lease
    --- FAIL: TestMultiRegionDataDriven/regional_by_row (167.74s)

Parameters: TAGS=bazel,gss

Help

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

Same failure on other branches

/cc @cockroachdb/sql-schema

This test on roachdash | Improve this report!

Jira issue: CRDB-25936
@cockroach-teamcity cockroach-teamcity added branch-release-23.1 Used to mark GA and release blockers, technical advisories, and bugs for 23.1 C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Mar 25, 2023
@cockroach-teamcity cockroach-teamcity added this to the 23.1 milestone Mar 25, 2023
@blathers-crl blathers-crl bot added the T-sql-schema-deprecated Use T-sql-foundations instead label Mar 25, 2023
@cockroach-teamcity
Copy link
Member Author

ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-23.1 @ 186218edb86b5974501b2976cfd0704d4d6d1beb:

=== RUN   TestMultiRegionDataDriven
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/e558fc8050776f4c54ea39ba371b49da/logTestMultiRegionDataDriven2800035990
    test_log_scope.go:79: use -show-logs to present logs inline
=== CONT  TestMultiRegionDataDriven
    datadriven_test.go:436: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/e558fc8050776f4c54ea39ba371b49da/logTestMultiRegionDataDriven2800035990
--- FAIL: TestMultiRegionDataDriven (177.14s)
=== RUN   TestMultiRegionDataDriven/regional_by_row
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2070/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:1:
        new-cluster [1 args]
        <no input to command>
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2070/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:4:
        exec-sql [1 args]
        CREATE DATABASE db PRIMARY REGION "us-east-1" REGIONS  "us-west-1", "us-central-1";
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2070/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:8:
        exec-sql [1 args]
        CREATE TABLE db.rbr(k INT PRIMARY KEY, v INT) LOCALITY REGIONAL BY ROW;
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2070/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:12:
        exec-sql [1 args]
        INSERT INTO db.rbr (k, v, crdb_region) VALUES (1, 1, 'us-east-1'), (2, 2, 'us-central-1'), (3, 3, 'us-west-1')
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2070/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:19:
        wait-for-zone-config-changes [8 args]
        <no input to command>
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2070/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:22:
        wait-for-zone-config-changes [8 args]
        <no input to command>
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2070/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:25:
         
        expected:
        
        found:
        expected leaseholder 6 but got 7
    --- FAIL: TestMultiRegionDataDriven/regional_by_row (146.04s)

Parameters: TAGS=bazel,gss

Help

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

Same failure on other branches

This test on roachdash | Improve this report!

@ajwerner
Copy link
Contributor

This is the 23.1 branch manifestation of #98020. Assigning to @matthewtodd to close when the fix is back ported.

@cockroach-teamcity
Copy link
Member Author

ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-23.1 @ a34af06d8e7230e4052db80d55da21a06013f81b:

=== RUN   TestMultiRegionDataDriven
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/e558fc8050776f4c54ea39ba371b49da/logTestMultiRegionDataDriven4188669779
    test_log_scope.go:79: use -show-logs to present logs inline
=== CONT  TestMultiRegionDataDriven
    datadriven_test.go:436: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/e558fc8050776f4c54ea39ba371b49da/logTestMultiRegionDataDriven4188669779
--- FAIL: TestMultiRegionDataDriven (173.32s)
=== RUN   TestMultiRegionDataDriven/regional_by_row
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2944/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:1:
        new-cluster [1 args]
        <no input to command>
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2944/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:4:
        exec-sql [1 args]
        CREATE DATABASE db PRIMARY REGION "us-east-1" REGIONS  "us-west-1", "us-central-1";
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2944/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:8:
        exec-sql [1 args]
        CREATE TABLE db.rbr(k INT PRIMARY KEY, v INT) LOCALITY REGIONAL BY ROW;
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2944/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:12:
        exec-sql [1 args]
        INSERT INTO db.rbr (k, v, crdb_region) VALUES (1, 1, 'us-east-1'), (2, 2, 'us-central-1'), (3, 3, 'us-west-1')
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2944/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:19:
        wait-for-zone-config-changes [8 args]
        <no input to command>
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2944/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:22:
         
        expected:
        
        found:
        expected node %!s(int=4) to have replica type voter but was not found
    --- FAIL: TestMultiRegionDataDriven/regional_by_row (139.38s)

Parameters: TAGS=bazel,gss

Help

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

Same failure on other branches

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-23.1 @ b15bd6f312c63f45d6246044238ef4645bfcd3a3:

=== RUN   TestMultiRegionDataDriven
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/92210d9178e507c2b00f19c1ad4bbd36/logTestMultiRegionDataDriven16186114
    test_log_scope.go:79: use -show-logs to present logs inline
=== CONT  TestMultiRegionDataDriven
    datadriven_test.go:436: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/92210d9178e507c2b00f19c1ad4bbd36/logTestMultiRegionDataDriven16186114
--- FAIL: TestMultiRegionDataDriven (222.29s)
=== RUN   TestMultiRegionDataDriven/regional_by_row
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/6664/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:1:
        new-cluster [1 args]
        <no input to command>
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/6664/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:4:
        exec-sql [1 args]
        CREATE DATABASE db PRIMARY REGION "us-east-1" REGIONS  "us-west-1", "us-central-1";
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/6664/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:8:
        exec-sql [1 args]
        CREATE TABLE db.rbr(k INT PRIMARY KEY, v INT) LOCALITY REGIONAL BY ROW;
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/6664/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:12:
        exec-sql [1 args]
        INSERT INTO db.rbr (k, v, crdb_region) VALUES (1, 1, 'us-east-1'), (2, 2, 'us-central-1'), (3, 3, 'us-west-1')
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/6664/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:19:
        wait-for-zone-config-changes [8 args]
        <no input to command>
        ----
    datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/6664/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/regional_by_row:22:
         
        expected:
        
        found:
        could not get leaseholder: no valid lease
    --- FAIL: TestMultiRegionDataDriven/regional_by_row (185.75s)
Help

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

Same failure on other branches

This test on roachdash | Improve this report!

@cockroach-teamcity cockroach-teamcity mentioned this issue Apr 14, 2023
Closed
@cockroach-teamcity
Copy link
Member Author

ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-23.1 @ 84905b8396e7cd7ef999b264faaafe13110d631a:

             2.947ms      0.063ms        event:sql/flowinfra/flow.go:462 [n1,client=127.0.0.1:58628,user=root] starting (0 processors, 0 startables) asynchronously
             3.008ms      0.062ms        event:sql/colflow/vectorized_flow.go:325 [n1,client=127.0.0.1:58628,user=root] running the batch flow coordinator in the flow's goroutine
             9.327ms      6.319ms        event:component:<flow_id:<8aa38727-e9d8-4f77-b03f-5c4f56d5245a> type:FLOW id:0 sql_instance_id:1 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<> tuples_read:<> batch_requests_issued:<> kv_time:<> contention_time:<> num_interface_steps:<> num_internal_steps:<> num_interface_seeks:<> num_internal_seeks:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<value_plus_one:20481 > max_disk_usage:<value_plus_one:1 > consumed_ru:<> >
             9.157ms     -0.170ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"8aa38727-e9d8-4f77-b03f-5c4f56d5245a","type":"FLOW","id":0,"sqlInstanceId":1},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"0"},"tuplesRead":{"valuePlusOne":"0"},"batchRequestsIssued":{"valuePlusOne":"0"},"kvTime":{"valuePlusOne":"0s"},"contentionTime":{"valuePlusOne":"0s"},"numInterfaceSteps":{"valuePlusOne":"0"},"numInternalSteps":{"valuePlusOne":"0"},"numInterfaceSeeks":{"valuePlusOne":"0"},"numInternalSeeks":{"valuePlusOne":"0"},"blockBytes":{"valuePlusOne":"0"},"blockBytesInCache":{"valuePlusOne":"0"},"keyBytes":{"valuePlusOne":"0"},"valueBytes":{"valuePlusOne":"0"},"pointCount":{"valuePlusOne":"0"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"0"},"rangeKeyCount":{"valuePlusOne":"0"},"rangeKeyContainedPoints":{"valuePlusOne":"0"},"rangeKeySkippedPoints":{"valuePlusOne":"0"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"0"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"},"cpuTime":{"valuePlusOne":"0s"}},"output":{"numBatches":{"valuePlusOne":"0"},"numTuples":{"valuePlusOne":"0"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"20481"},"maxDiskUsage":{"valuePlusOne":"1"},"consumedRu":{"valuePlusOne":"0"}}}
             3.020ms     -6.137ms        === operation:batch flow coordinator _unfinished:1 _verbose:1 node:1 client:127.0.0.1:58628 user:root cockroach.flowid:8aa38727-e9d8-4f77-b03f-5c4f56d5245a cockroach.processorid:0
             8.424ms      5.404ms        event:component:<flow_id:<8aa38727-e9d8-4f77-b03f-5c4f56d5245a> type:PROCESSOR id:0 sql_instance_id:1 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<value_plus_one:12 > tuples_read:<value_plus_one:2 > batch_requests_issued:<value_plus_one:2 > kv_time:<value_plus_one:<nanos:4981069 > > contention_time:<value_plus_one:<nanos:1 > > num_interface_steps:<value_plus_one:1 > num_internal_steps:<value_plus_one:1 > num_interface_seeks:<value_plus_one:2 > num_internal_seeks:<value_plus_one:2 > block_bytes:<value_plus_one:5516 > block_bytes_in_cache:<value_plus_one:5516 > key_bytes:<value_plus_one:15 > value_bytes:<value_plus_one:8 > point_count:<value_plus_one:2 > points_covered_by_range_tombstones:<value_plus_one:1 > range_key_count:<value_plus_one:1 > range_key_contained_points:<value_plus_one:1 > range_key_skipped_points:<value_plus_one:1 > kv_cpu_time:<> num_gets:<value_plus_one:2 > num_scans:<value_plus_one:1 > num_reverse_scans:<value_plus_one:1 > > exec:<exec_time:<> max_allocated_mem:<value_plus_one:20481 > max_allocated_disk:<> consumed_ru:<value_plus_one:1 > cpu_time:<value_plus_one:<nanos:345902 > > > output:<num_batches:<value_plus_one:2 > num_tuples:<value_plus_one:2 > > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
             8.553ms      0.130ms        event:component:<flow_id:<00000000-0000-0000-0000-000000000000> type:UNSET id:0 sql_instance_id:0 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<> tuples_read:<> batch_requests_issued:<> kv_time:<> contention_time:<> num_interface_steps:<> num_internal_steps:<> num_interface_seeks:<> num_internal_seeks:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
             8.291ms     -0.262ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"8aa38727-e9d8-4f77-b03f-5c4f56d5245a","type":"PROCESSOR","id":0,"sqlInstanceId":1},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"12"},"tuplesRead":{"valuePlusOne":"2"},"batchRequestsIssued":{"valuePlusOne":"2"},"kvTime":{"valuePlusOne":"0.004981069s"},"contentionTime":{"valuePlusOne":"0.000000001s"},"numInterfaceSteps":{"valuePlusOne":"1"},"numInternalSteps":{"valuePlusOne":"1"},"numInterfaceSeeks":{"valuePlusOne":"2"},"numInternalSeeks":{"valuePlusOne":"2"},"blockBytes":{"valuePlusOne":"5516"},"blockBytesInCache":{"valuePlusOne":"5516"},"keyBytes":{"valuePlusOne":"15"},"valueBytes":{"valuePlusOne":"8"},"pointCount":{"valuePlusOne":"2"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"1"},"rangeKeyCount":{"valuePlusOne":"1"},"rangeKeyContainedPoints":{"valuePlusOne":"1"},"rangeKeySkippedPoints":{"valuePlusOne":"1"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"2"},"numScans":{"valuePlusOne":"1"},"numReverseScans":{"valuePlusOne":"1"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"20481"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"1"},"cpuTime":{"valuePlusOne":"0.000345902s"}},"output":{"numBatches":{"valuePlusOne":"2"},"numTuples":{"valuePlusOne":"2"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"}}}
             8.440ms      0.149ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"00000000-0000-0000-0000-000000000000","type":"UNSET","id":0,"sqlInstanceId":0},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"0"},"tuplesRead":{"valuePlusOne":"0"},"batchRequestsIssued":{"valuePlusOne":"0"},"kvTime":{"valuePlusOne":"0s"},"contentionTime":{"valuePlusOne":"0s"},"numInterfaceSteps":{"valuePlusOne":"0"},"numInternalSteps":{"valuePlusOne":"0"},"numInterfaceSeeks":{"valuePlusOne":"0"},"numInternalSeeks":{"valuePlusOne":"0"},"blockBytes":{"valuePlusOne":"0"},"blockBytesInCache":{"valuePlusOne":"0"},"keyBytes":{"valuePlusOne":"0"},"valueBytes":{"valuePlusOne":"0"},"pointCount":{"valuePlusOne":"0"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"0"},"rangeKeyCount":{"valuePlusOne":"0"},"rangeKeyContainedPoints":{"valuePlusOne":"0"},"rangeKeySkippedPoints":{"valuePlusOne":"0"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"0"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"},"cpuTime":{"valuePlusOne":"0s"}},"output":{"numBatches":{"valuePlusOne":"0"},"numTuples":{"valuePlusOne":"0"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"}}}
             3.088ms     -5.352ms        === operation:colbatchscan _unfinished:1 _verbose:1 node:1 client:127.0.0.1:58628 user:root
             3.088ms      0.000ms        [txn coordinator send: {count: 1, duration 4ms}]
             3.088ms      0.000ms        [dist sender send: {count: 1, duration 4ms}]
             3.088ms      0.000ms        [/cockroach.roachpb.Internal/Batch: {count: 1, duration 2ms}]
             3.394ms      0.306ms        event:sql/row/kv_batch_fetcher.go:475 [n1,client=127.0.0.1:58628,user=root] Scan /Table/108/1/1/0
             3.438ms      0.044ms            === operation:txn coordinator send _verbose:1 node:1 client:127.0.0.1:58628 user:root txnID:aa48d797-8bb7-45f3-88ea-0b2b8936a250
             3.438ms      0.000ms            [dist sender send: {count: 1, duration 4ms}]
             3.438ms      0.000ms            [/cockroach.roachpb.Internal/Batch: {count: 1, duration 2ms}]
             3.527ms      0.089ms                === operation:dist sender send _verbose:1 node:1 client:127.0.0.1:58628 user:root txn:aa48d797
             3.527ms      0.000ms                [/cockroach.roachpb.Internal/Batch: {count: 1, duration 2ms}]
             3.618ms      0.091ms                event:kv/kvclient/kvcoord/range_iter.go:188 [n1,client=127.0.0.1:58628,user=root,txn=aa48d797] querying next range at /Table/108/1/1/0
             3.753ms      0.135ms                event:kv/kvclient/kvcoord/range_iter.go:225 [n1,client=127.0.0.1:58628,user=root,txn=aa48d797] key: /Table/108/1/1/0, desc: r63:/{Table/108-Max} [(n1,s1):1, (n3,s3):8, (n2,s2):5, (n5,s5):6NON_VOTER, (n4,s4):9NON_VOTER, next=10, gen=23]
             3.873ms      0.120ms                event:kv/kvclient/kvcoord/dist_sender.go:2051 [n1,client=127.0.0.1:58628,user=root,txn=aa48d797] routing to nearest replica; leaseholder not required
             4.230ms      0.357ms                event:kv/kvclient/kvcoord/dist_sender.go:2109 [n1,client=127.0.0.1:58628,user=root,txn=aa48d797] r63: sending batch 1 Get to (n1,s1):1
             4.316ms      0.086ms                event:rpc/nodedialer/nodedialer.go:157 [n1,client=127.0.0.1:58628,user=root,txn=aa48d797] sending request to local client
             4.380ms      0.064ms                    === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server request:Get [/Table/108/1/1/0,/Min), [txn: aa48d797], [can-forward-ts]
             4.516ms      0.136ms                    event:server/node.go:1171 [n1] node received request: 1 Get
             4.747ms      0.231ms                    event:kv/kvserver/store_send.go:167 [n1,s1] executing Get [/Table/108/1/1/0,/Min), [txn: aa48d797], [can-forward-ts]
             4.909ms      0.162ms                    event:kv/kvserver/replica_send.go:179 [n1,s1,r63/1:/{Table/108-Max}] read-only path
             5.020ms      0.111ms                    event:kv/kvserver/concurrency/concurrency_manager.go:194 [n1,s1,r63/1:/{Table/108-Max}] sequencing request
             5.083ms      0.063ms                    event:kv/kvserver/concurrency/concurrency_manager.go:275 [n1,s1,r63/1:/{Table/108-Max}] acquiring latches
             5.177ms      0.094ms                    event:kv/kvserver/concurrency/concurrency_manager.go:319 [n1,s1,r63/1:/{Table/108-Max}] scanning lock table for conflicting locks
             5.515ms      0.338ms                    event:kv/kvserver/replica_follower_read.go:127 [n1,s1,r63/1:/{Table/108-Max}] serving via follower read; query timestamp below closed timestamp by 200.609516ms
             5.603ms      0.087ms                    event:kv/kvserver/replica_read.go:296 [n1,s1,r63/1:/{Table/108-Max}] can drop latches early for batch (Get [/Table/108/1/1/0,/Min), [txn: aa48d797], [can-forward-ts]); scanning lock table first to detect conflicts
             5.710ms      0.108ms                    event:kv/kvserver/replica_read.go:113 [n1,s1,r63/1:/{Table/108-Max}] lock table scan complete without conflicts; dropping latches early
             5.817ms      0.107ms                    event:kv/kvserver/replica_read.go:408 [n1,s1,r63/1:/{Table/108-Max}] executing read-only batch
             6.055ms      0.237ms                    event:kv/kvserver/replica_evaluate.go:550 [n1,s1,r63/1:/{Table/108-Max}] evaluated Get command header:<key:"\364\211\211\210" > , txn="sql txn" meta={id=aa48d797 key=/Min pri=0.00009276 epo=0 ts=1681542987.095005886,0 min=1681542987.095005886,0 seq=0} lock=false stat=PENDING rts=1681542987.095005886,0 wto=false gul=1681542987.595005886,0 : resp=header:<num_keys:1 num_bytes:7 > value:<raw_bytes:"\375\311[\010\n#\002" timestamp:<wall_time:1681542975214585223 > > , err=<nil>
             6.188ms      0.134ms                    event:scan stats: stepped 0 times (0 internal); seeked 1 times (1 internal); block-bytes: (total 5.4 KiB, cached 5.4 KiB); points: (count 1 , key-bytes 14 B, value-bytes 7 B, tombstoned: 0 ) ranges: (count 0 ), (contained-points 0 , skipped-points 0 ) evaluated requests: 1 gets, 0 scans, 0 reverse scans
             6.363ms      0.175ms                    event:kv/kvserver/replica_read.go:221 [n1,s1,r63/1:/{Table/108-Max}] read completed
             6.463ms      0.099ms                    event:kv/kvserver/replica_send.go:321 [n1,s1,r63/1:/{Table/108-Max}] client had stale range info; returning an update
             6.090ms     -0.373ms                    structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"1","numInternalSeeks":"1","numInterfaceSteps":"0","numInternalSteps":"0","blockBytes":"5515","blockBytesInCache":"5515","keyBytes":"14","valueBytes":"7","pointCount":"1","pointsCoveredByRangeTombstones":"0","rangeKeyCount":"0","rangeKeyContainedPoints":"0","rangeKeySkippedPoints":"0","separatedPointCount":"0","separatedPointValueBytes":"0","separatedPointValueBytesFetched":"0","numGets":"1","numScans":"0","numReverseScans":"0"}
             7.105ms      2.789ms                event:kv/kvclient/kvcoord/dist_sender.go:2238 [n1,client=127.0.0.1:58628,user=root,txn=aa48d797] received updated range info: [desc: r63:/{Table/108-Max} [(n1,s1):1, (n3,s3):8, (n2,s2):5, (n5,s5):6NON_VOTER, (n4,s4):9NON_VOTER, next=10, gen=23], lease: repl=(n3,s3):8 seq=3 start=1681542987.024682225,0 epo=1 pro=1681542987.029369245,0, closed_timestamp_policy: LEAD_FOR_GLOBAL_READS]
             7.332ms      0.228ms                event:kv/kvclient/rangecache/range_cache.go:1083 [n1,client=127.0.0.1:58628,user=root,txn=aa48d797] evict cached descriptor: desc=desc:r63:/{Table/108-Max} [(n1,s1):1, (n3,s3):8, (n2,s2):5, (n5,s5):6NON_VOTER, (n4,s4):9NON_VOTER, next=10, gen=23], lease:repl=(n3,s3):8 seq=2 start=1681542987.024682225,0 exp=1681542993.023918187,0 pro=1681542987.023918187,0
             7.451ms      0.119ms                event:kv/kvclient/rangecache/range_cache.go:594 [n1,client=127.0.0.1:58628,user=root,txn=aa48d797] evicting cached range descriptor with 1 replacements
             7.529ms      0.078ms                event:kv/kvclient/rangecache/range_cache.go:1252 [n1,client=127.0.0.1:58628,user=root,txn=aa48d797] clearing entries overlapping r63:/{Table/108-Max} [(n1,s1):1, (n3,s3):8, (n2,s2):5, (n5,s5):6NON_VOTER, (n4,s4):9NON_VOTER, next=10, gen=23]
             7.721ms      4.284ms            event:kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:576 [n1,client=127.0.0.1:58628,user=root,txn=aa48d797] recording span to refresh: /Table/108/1/1/0
             9.597ms      7.038ms    event:sql/conn_executor_exec.go:963 [n1,client=127.0.0.1:58628,user=root] execution ends
             9.666ms      0.069ms    event:sql/conn_executor_exec.go:963 [n1,client=127.0.0.1:58628,user=root] rows affected: 1
            11.683ms      2.017ms        === operation:commit sql txn _verbose:1 node:1 client:127.0.0.1:58628 user:root
            12.065ms      2.399ms    event:sql/conn_executor_exec.go:2724 [n1,client=127.0.0.1:58628,user=root] AutoCommit. err: <nil>
    --- FAIL: TestMultiRegionDataDriven/global_tables (58.17s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

Same failure on other branches

This test on roachdash | Improve this report!

@cockroach-teamcity cockroach-teamcity mentioned this issue Apr 19, 2023
Closed
@matthewtodd matthewtodd mentioned this issue Apr 24, 2023
Merged
@matthewtodd
Copy link
Contributor

I've just sent #102192 to address these flakes.

craig bot pushed a commit that referenced this issue Apr 26, 2023
@matthewtodd
Merge #102192
e22055e 
102192: sqlstats: only include local region in statement_statistics r=j82w a=matthewtodd

Part of #89949.

Addresses #98020.
Addresses #99563.

Related to cockroachdb/roachperf#129.
Related to #102170.

Previously, we attempted to record all the regions hit in a single statement execution in the sqlstats tables, leaning on the sqlAddressResolver to map traced nodeIDs to localities at execution time.

While the sqlAddressResolver is generally non-blocking, the introduction of this code did cause some of the multiregion "this query shouldn't span regions" tests to start [flaking][] and it's more recently been [implicated][] in a 2.5% performance regression.

Given that the probabilistic nature of the tracing meant that we generally weren't capturing all the relevant nodeIDs anyway, it seems like the most prudent thing to do here is take a step back and regroup.

In the short term, let's stop even trying to gather all these regions. In the medium/long term, let's see if we can find a better approach.

[flaking]: #98020
[implicated]: https://github.com/cockroachdb/roachperf/pull/129

Release note: None

Co-authored-by: Matthew Todd <[email protected]>
This was referenced Apr 26, 2023
Merged
Merged
@cockroach-teamcity cockroach-teamcity mentioned this issue May 7, 2023
Closed
@exalate-issue-sync exalate-issue-sync bot added T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions) and removed T-sql-schema-deprecated Use T-sql-foundations instead labels May 10, 2023
@cockroach-teamcity cockroach-teamcity mentioned this issue May 16, 2023
Closed
@matthewtodd
Copy link
Contributor

matthewtodd commented May 16, 2023 •
edited
Loading

@rafiss here is the release-23.1 version of #98020. cc @maryliag

@matthewtodd matthewtodd assigned rafiss and unassigned matthewtodd May 16, 2023
@cockroach-teamcity
Copy link
Member Author

ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-23.1 @ e84e2cabef32a59d88041132f059a6768dfe56bb:

             2.767ms      0.026ms    event:sql/distsql_running.go:815 [n4,client=127.0.0.1:51898,user=root] running DistSQL plan
             2.820ms      0.053ms        === operation:flow _verbose:1 node:4 client:127.0.0.1:51898 user:root
             2.887ms      0.067ms        event:sql/colflow/vectorized_flow.go:232 [n4,client=127.0.0.1:51898,user=root] setting up vectorized flow
             2.944ms      0.057ms        event:sql/colflow/vectorized_flow.go:282 [n4,client=127.0.0.1:51898,user=root] vectorized flow setup succeeded
             2.969ms      0.025ms        event:sql/flowinfra/flow.go:462 [n4,client=127.0.0.1:51898,user=root] starting (0 processors, 0 startables) asynchronously
             2.996ms      0.027ms        event:sql/colflow/vectorized_flow.go:325 [n4,client=127.0.0.1:51898,user=root] running the batch flow coordinator in the flow's goroutine
            13.785ms     10.789ms        event:component:<flow_id:<065e82dd-0197-41cb-a806-8640f68417ad> type:FLOW id:0 sql_instance_id:4 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<> tuples_read:<> batch_requests_issued:<> kv_time:<> contention_time:<> num_interface_steps:<> num_internal_steps:<> num_interface_seeks:<> num_internal_seeks:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<value_plus_one:20481 > max_disk_usage:<value_plus_one:1 > consumed_ru:<> >
            13.685ms     -0.100ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"065e82dd-0197-41cb-a806-8640f68417ad","type":"FLOW","id":0,"sqlInstanceId":4},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"0"},"tuplesRead":{"valuePlusOne":"0"},"batchRequestsIssued":{"valuePlusOne":"0"},"kvTime":{"valuePlusOne":"0s"},"contentionTime":{"valuePlusOne":"0s"},"numInterfaceSteps":{"valuePlusOne":"0"},"numInternalSteps":{"valuePlusOne":"0"},"numInterfaceSeeks":{"valuePlusOne":"0"},"numInternalSeeks":{"valuePlusOne":"0"},"blockBytes":{"valuePlusOne":"0"},"blockBytesInCache":{"valuePlusOne":"0"},"keyBytes":{"valuePlusOne":"0"},"valueBytes":{"valuePlusOne":"0"},"pointCount":{"valuePlusOne":"0"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"0"},"rangeKeyCount":{"valuePlusOne":"0"},"rangeKeyContainedPoints":{"valuePlusOne":"0"},"rangeKeySkippedPoints":{"valuePlusOne":"0"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"0"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"},"cpuTime":{"valuePlusOne":"0s"}},"output":{"numBatches":{"valuePlusOne":"0"},"numTuples":{"valuePlusOne":"0"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"20481"},"maxDiskUsage":{"valuePlusOne":"1"},"consumedRu":{"valuePlusOne":"0"}}}
             3.005ms    -10.680ms        === operation:batch flow coordinator _unfinished:1 _verbose:1 node:4 client:127.0.0.1:51898 user:root cockroach.flowid:065e82dd-0197-41cb-a806-8640f68417ad cockroach.processorid:0
            13.211ms     10.206ms        event:component:<flow_id:<065e82dd-0197-41cb-a806-8640f68417ad> type:PROCESSOR id:0 sql_instance_id:4 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<value_plus_one:12 > tuples_read:<value_plus_one:2 > batch_requests_issued:<value_plus_one:2 > kv_time:<value_plus_one:<nanos:9284417 > > contention_time:<value_plus_one:<nanos:1 > > num_interface_steps:<value_plus_one:1 > num_internal_steps:<value_plus_one:1 > num_interface_seeks:<value_plus_one:2 > num_internal_seeks:<value_plus_one:2 > block_bytes:<value_plus_one:1 > block_bytes_in_cache:<value_plus_one:1 > key_bytes:<value_plus_one:15 > value_bytes:<value_plus_one:8 > point_count:<value_plus_one:2 > points_covered_by_range_tombstones:<value_plus_one:1 > range_key_count:<value_plus_one:1 > range_key_contained_points:<value_plus_one:1 > range_key_skipped_points:<value_plus_one:1 > kv_cpu_time:<> num_gets:<value_plus_one:2 > num_scans:<value_plus_one:1 > num_reverse_scans:<value_plus_one:1 > > exec:<exec_time:<> max_allocated_mem:<value_plus_one:20481 > max_allocated_disk:<> consumed_ru:<value_plus_one:1 > cpu_time:<value_plus_one:<nanos:347717 > > > output:<num_batches:<value_plus_one:2 > num_tuples:<value_plus_one:2 > > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
            13.315ms      0.104ms        event:component:<flow_id:<00000000-0000-0000-0000-000000000000> type:UNSET id:0 sql_instance_id:0 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<> tuples_read:<> batch_requests_issued:<> kv_time:<> contention_time:<> num_interface_steps:<> num_internal_steps:<> num_interface_seeks:<> num_internal_seeks:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
            13.082ms     -0.233ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"065e82dd-0197-41cb-a806-8640f68417ad","type":"PROCESSOR","id":0,"sqlInstanceId":4},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"12"},"tuplesRead":{"valuePlusOne":"2"},"batchRequestsIssued":{"valuePlusOne":"2"},"kvTime":{"valuePlusOne":"0.009284417s"},"contentionTime":{"valuePlusOne":"0.000000001s"},"numInterfaceSteps":{"valuePlusOne":"1"},"numInternalSteps":{"valuePlusOne":"1"},"numInterfaceSeeks":{"valuePlusOne":"2"},"numInternalSeeks":{"valuePlusOne":"2"},"blockBytes":{"valuePlusOne":"1"},"blockBytesInCache":{"valuePlusOne":"1"},"keyBytes":{"valuePlusOne":"15"},"valueBytes":{"valuePlusOne":"8"},"pointCount":{"valuePlusOne":"2"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"1"},"rangeKeyCount":{"valuePlusOne":"1"},"rangeKeyContainedPoints":{"valuePlusOne":"1"},"rangeKeySkippedPoints":{"valuePlusOne":"1"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"2"},"numScans":{"valuePlusOne":"1"},"numReverseScans":{"valuePlusOne":"1"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"20481"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"1"},"cpuTime":{"valuePlusOne":"0.000347717s"}},"output":{"numBatches":{"valuePlusOne":"2"},"numTuples":{"valuePlusOne":"2"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"}}}
            13.227ms      0.145ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"00000000-0000-0000-0000-000000000000","type":"UNSET","id":0,"sqlInstanceId":0},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"0"},"tuplesRead":{"valuePlusOne":"0"},"batchRequestsIssued":{"valuePlusOne":"0"},"kvTime":{"valuePlusOne":"0s"},"contentionTime":{"valuePlusOne":"0s"},"numInterfaceSteps":{"valuePlusOne":"0"},"numInternalSteps":{"valuePlusOne":"0"},"numInterfaceSeeks":{"valuePlusOne":"0"},"numInternalSeeks":{"valuePlusOne":"0"},"blockBytes":{"valuePlusOne":"0"},"blockBytesInCache":{"valuePlusOne":"0"},"keyBytes":{"valuePlusOne":"0"},"valueBytes":{"valuePlusOne":"0"},"pointCount":{"valuePlusOne":"0"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"0"},"rangeKeyCount":{"valuePlusOne":"0"},"rangeKeyContainedPoints":{"valuePlusOne":"0"},"rangeKeySkippedPoints":{"valuePlusOne":"0"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"0"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"},"cpuTime":{"valuePlusOne":"0s"}},"output":{"numBatches":{"valuePlusOne":"0"},"numTuples":{"valuePlusOne":"0"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"}}}
             3.608ms     -9.618ms        === operation:colbatchscan _unfinished:1 _verbose:1 node:4 client:127.0.0.1:51898 user:root
             3.608ms      0.000ms        [/cockroach.roachpb.Internal/Batch: {count: 2, duration 9ms}]
             3.608ms      0.000ms        [txn coordinator send: {count: 1, duration 8ms}]
             3.608ms      0.000ms        [dist sender send: {count: 1, duration 8ms}]
             4.183ms      0.574ms        event:sql/row/kv_batch_fetcher.go:475 [n4,client=127.0.0.1:51898,user=root] Scan /Table/108/1/1/0
             4.392ms      0.209ms            === operation:txn coordinator send _verbose:1 node:4 client:127.0.0.1:51898 user:root txnID:ff8f0904-9ad4-475d-9d36-c40178a454c1
             4.392ms      0.000ms            [/cockroach.roachpb.Internal/Batch: {count: 2, duration 9ms}]
             4.392ms      0.000ms            [dist sender send: {count: 1, duration 8ms}]
             4.505ms      0.113ms                === operation:dist sender send _verbose:1 node:4 client:127.0.0.1:51898 user:root txn:ff8f0904
             4.505ms      0.000ms                [/cockroach.roachpb.Internal/Batch: {count: 2, duration 9ms}]
             4.619ms      0.114ms                event:kv/kvclient/kvcoord/range_iter.go:188 [n4,client=127.0.0.1:51898,user=root,txn=ff8f0904] querying next range at /Table/108/1/1/0
             5.092ms      0.473ms                event:kv/kvclient/kvcoord/range_iter.go:225 [n4,client=127.0.0.1:51898,user=root,txn=ff8f0904] key: /Table/108/1/1/0, desc: r65:/{Table/108-Max} [(n2,s2):1, (n1,s1):8, (n3,s3):5, (n5,s5):6NON_VOTER, next=10, gen=28]
             5.181ms      0.089ms                event:kv/kvclient/kvcoord/dist_sender.go:2069 [n4,client=127.0.0.1:51898,user=root,txn=ff8f0904] routing to nearest replica; leaseholder not required
             5.974ms      0.793ms                event:kv/kvclient/kvcoord/dist_sender.go:2127 [n4,client=127.0.0.1:51898,user=root,txn=ff8f0904] r65: sending batch 1 Get to (n3,s3):5
             6.089ms      0.115ms                event:rpc/nodedialer/nodedialer.go:166 [n4,client=127.0.0.1:51898,user=root,txn=ff8f0904] sending request to 127.0.0.1:44071
             6.143ms      0.054ms                    === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:4 client:127.0.0.1:51898 user:root txn:ff8f0904 span.kind:client
             6.423ms      0.280ms                    === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:3 span.kind:server request:Get [/Table/108/1/1/0,/Min), [txn: ff8f0904], [can-forward-ts]
             7.086ms      0.662ms                    event:server/node.go:1171 [n3] node received request: 1 Get
             7.195ms      0.109ms                    event:kv/kvserver/store_send.go:167 [n3,s3] executing Get [/Table/108/1/1/0,/Min), [txn: ff8f0904], [can-forward-ts]
             7.358ms      0.163ms                    event:kv/kvserver/replica_send.go:179 [n3,s3,r65/5:/{Table/108-Max}] read-only path
             7.464ms      0.106ms                    event:kv/kvserver/concurrency/concurrency_manager.go:194 [n3,s3,r65/5:/{Table/108-Max}] sequencing request
             7.564ms      0.100ms                    event:kv/kvserver/concurrency/concurrency_manager.go:275 [n3,s3,r65/5:/{Table/108-Max}] acquiring latches
             7.662ms      0.098ms                    event:kv/kvserver/concurrency/concurrency_manager.go:319 [n3,s3,r65/5:/{Table/108-Max}] scanning lock table for conflicting locks
             7.881ms      0.219ms                    event:kv/kvserver/replica_follower_read.go:127 [n3,s3,r65/5:/{Table/108-Max}] serving via follower read; query timestamp below closed timestamp by 190.781633ms
             7.972ms      0.092ms                    event:kv/kvserver/replica_read.go:296 [n3,s3,r65/5:/{Table/108-Max}] can drop latches early for batch (Get [/Table/108/1/1/0,/Min), [txn: ff8f0904], [can-forward-ts]); scanning lock table first to detect conflicts
             8.054ms      0.081ms                    event:kv/kvserver/replica_read.go:113 [n3,s3,r65/5:/{Table/108-Max}] lock table scan complete without conflicts; dropping latches early
             8.157ms      0.103ms                    event:kv/kvserver/replica_read.go:408 [n3,s3,r65/5:/{Table/108-Max}] executing read-only batch
             8.325ms      0.168ms                    event:kv/kvserver/replica_evaluate.go:550 [n3,s3,r65/5:/{Table/108-Max}] evaluated Get command header:<key:"\364\211\211\210" > , txn="sql txn" meta={id=ff8f0904 key=/Min pri=0.02284590 epo=0 ts=1685689014.582350901,0 min=1685689014.582350901,0 seq=0} lock=false stat=PENDING rts=1685689014.582350901,0 wto=false gul=1685689015.082350901,0 : resp=header:<num_keys:1 num_bytes:7 > value:<raw_bytes:"\375\311[\010\n#\002" timestamp:<wall_time:1685688999604009971 > > , err=<nil>
             8.513ms      0.188ms                    event:scan stats: stepped 0 times (0 internal); seeked 1 times (1 internal); block-bytes: (total 0 B, cached 0 B); points: (count 1 , key-bytes 14 B, value-bytes 7 B, tombstoned: 0 ) ranges: (count 0 ), (contained-points 0 , skipped-points 0 ) evaluated requests: 1 gets, 0 scans, 0 reverse scans
             8.674ms      0.161ms                    event:kv/kvserver/replica_read.go:221 [n3,s3,r65/5:/{Table/108-Max}] read completed
             8.351ms     -0.322ms                    structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"1","numInternalSeeks":"1","numInterfaceSteps":"0","numInternalSteps":"0","blockBytes":"0","blockBytesInCache":"0","keyBytes":"14","valueBytes":"7","pointCount":"1","pointsCoveredByRangeTombstones":"0","rangeKeyCount":"0","rangeKeyContainedPoints":"0","rangeKeySkippedPoints":"0","separatedPointCount":"0","separatedPointValueBytes":"0","separatedPointValueBytesFetched":"0","numGets":"1","numScans":"0","numReverseScans":"0"}
            12.625ms      8.234ms            event:kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:576 [n4,client=127.0.0.1:51898,user=root,txn=ff8f0904] recording span to refresh: /Table/108/1/1/0
            13.984ms     11.218ms    event:sql/conn_executor_exec.go:964 [n4,client=127.0.0.1:51898,user=root] execution ends
            14.018ms      0.033ms    event:sql/conn_executor_exec.go:964 [n4,client=127.0.0.1:51898,user=root] rows affected: 1
            14.516ms      0.498ms        === operation:commit sql txn _verbose:1 node:4 client:127.0.0.1:51898 user:root
            14.712ms      0.695ms    event:sql/conn_executor_exec.go:2731 [n4,client=127.0.0.1:51898,user=root] AutoCommit. err: <nil>
    --- FAIL: TestMultiRegionDataDriven/global_tables (63.34s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

Same failure on other branches

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-23.1 @ 870f9f667dd34bd0c926d38c08193db2672d78ff:

            18.534ms      0.119ms        event:sql/colflow/vectorized_flow.go:232 [n2,client=127.0.0.1:54034,hostssl,user=root] setting up vectorized flow
            18.640ms      0.106ms        event:sql/colflow/vectorized_flow.go:281 [n2,client=127.0.0.1:54034,hostssl,user=root] vectorized flow setup succeeded
            18.684ms      0.044ms        event:sql/flowinfra/flow.go:462 [n2,client=127.0.0.1:54034,hostssl,user=root] starting (0 processors, 0 startables) asynchronously
            19.191ms      0.507ms        event:sql/colflow/vectorized_flow.go:324 [n2,client=127.0.0.1:54034,hostssl,user=root] running the batch flow coordinator in the flow's goroutine
            20.061ms      0.869ms            === operation:batch flow coordinator _verbose:1 node:2 client:127.0.0.1:54034 hostssl: user:root cockroach.flowid:fa887b98-4a8e-48b3-af27-653949b033c2 cockroach.processorid:0
            20.061ms      0.000ms            [colbatchscan: {count: 1, duration 27ms, unfinished}]
            20.061ms      0.000ms            [txn coordinator send: {count: 1, duration 25ms}]
            20.061ms      0.000ms            [dist sender send: {count: 1, duration 24ms}]
            20.061ms      0.000ms            [/cockroach.roachpb.Internal/Batch: {count: 1, duration 7ms}]
            20.157ms      0.097ms                === operation:colbatchscan _unfinished:1 _verbose:1 node:2 client:127.0.0.1:54034 hostssl: user:root cockroach.flowid:fa887b98-4a8e-48b3-af27-653949b033c2 cockroach.processorid:0
            20.157ms      0.000ms                [txn coordinator send: {count: 1, duration 25ms}]
            20.157ms      0.000ms                [dist sender send: {count: 1, duration 24ms}]
            20.157ms      0.000ms                [/cockroach.roachpb.Internal/Batch: {count: 1, duration 7ms}]
            20.553ms      0.395ms                event:sql/row/kv_batch_fetcher.go:475 [n2,client=127.0.0.1:54034,hostssl,user=root] Scan /Table/108/1/1/0
            20.624ms      0.072ms                    === operation:txn coordinator send _verbose:1 node:2 client:127.0.0.1:54034 hostssl: user:root txnID:5923b618-7b09-41e6-b8ce-add97238752c
            20.624ms      0.000ms                    [dist sender send: {count: 1, duration 24ms}]
            20.624ms      0.000ms                    [/cockroach.roachpb.Internal/Batch: {count: 1, duration 7ms}]
            21.600ms      0.976ms                        === operation:dist sender send _verbose:1 node:2 client:127.0.0.1:54034 hostssl: user:root txn:5923b618
            21.600ms      0.000ms                        [/cockroach.roachpb.Internal/Batch: {count: 1, duration 7ms}]
            21.741ms      0.140ms                        event:kv/kvclient/kvcoord/range_iter.go:188 [n2,client=127.0.0.1:54034,hostssl,user=root,txn=5923b618] querying next range at /Table/108/1/1/0
            22.634ms      0.893ms                        event:kv/kvclient/kvcoord/range_iter.go:225 [n2,client=127.0.0.1:54034,hostssl,user=root,txn=5923b618] key: /Table/108/1/1/0, desc: r64:/{Table/108-Max} [(n1,s1):1, (n3,s3):5, (n2,s2):8, (n5,s5):6NON_VOTER, (n4,s4):9NON_VOTER, next=10, gen=23]
            22.747ms      0.113ms                        event:kv/kvclient/kvcoord/dist_sender.go:2069 [n2,client=127.0.0.1:54034,hostssl,user=root,txn=5923b618] routing to nearest replica; leaseholder not required
            35.912ms     13.165ms                        event:kv/kvclient/kvcoord/dist_sender.go:2127 [n2,client=127.0.0.1:54034,hostssl,user=root,txn=5923b618] r64: sending batch 1 Get to (n2,s2):8
            36.243ms      0.331ms                        event:rpc/nodedialer/nodedialer.go:157 [n2,client=127.0.0.1:54034,hostssl,user=root,txn=5923b618] sending request to local client
            38.574ms      2.331ms                            === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:2 span.kind:server request:Get [/Table/108/1/1/0,/Min), [txn: 5923b618], [can-forward-ts]
            39.075ms      0.501ms                            event:server/node.go:1171 [n2] node received request: 1 Get
            39.425ms      0.350ms                            event:kv/kvserver/store_send.go:167 [n2,s2] executing Get [/Table/108/1/1/0,/Min), [txn: 5923b618], [can-forward-ts]
            39.719ms      0.294ms                            event:kv/kvserver/replica_send.go:179 [n2,s2,r64/8:/{Table/108-Max}] read-only path
            39.816ms      0.097ms                            event:kv/kvserver/concurrency/concurrency_manager.go:194 [n2,s2,r64/8:/{Table/108-Max}] sequencing request
            39.863ms      0.047ms                            event:kv/kvserver/concurrency/concurrency_manager.go:275 [n2,s2,r64/8:/{Table/108-Max}] acquiring latches
            40.423ms      0.561ms                            event:kv/kvserver/concurrency/concurrency_manager.go:319 [n2,s2,r64/8:/{Table/108-Max}] scanning lock table for conflicting locks
            41.149ms      0.726ms                            event:kv/kvserver/replica_read.go:296 [n2,s2,r64/8:/{Table/108-Max}] can drop latches early for batch (Get [/Table/108/1/1/0,/Min), [txn: 5923b618], [can-forward-ts]); scanning lock table first to detect conflicts
            41.236ms      0.087ms                            event:kv/kvserver/replica_read.go:113 [n2,s2,r64/8:/{Table/108-Max}] lock table scan complete without conflicts; dropping latches early
            43.317ms      2.081ms                            event:kv/kvserver/replica_read.go:408 [n2,s2,r64/8:/{Table/108-Max}] executing read-only batch
            43.515ms      0.199ms                            event:kv/kvserver/replica_evaluate.go:550 [n2,s2,r64/8:/{Table/108-Max}] evaluated Get command header:<key:"\364\211\211\210" > , txn="sql txn" meta={id=5923b618 key=/Min pri=0.01521269 epo=0 ts=1685861322.210729315,0 min=1685861322.210729315,0 seq=0} lock=false stat=PENDING rts=1685861322.210729315,0 wto=false gul=1685861322.710729315,0 : resp=header:<num_keys:1 num_bytes:7 > value:<raw_bytes:"\375\311[\010\n#\002" timestamp:<wall_time:1685861309856583961 > > , err=<nil>
            43.994ms      0.479ms                            event:scan stats: stepped 0 times (0 internal); seeked 1 times (1 internal); block-bytes: (total 89 B, cached 89 B); points: (count 1 , key-bytes 14 B, value-bytes 7 B, tombstoned: 0 ) ranges: (count 0 ), (contained-points 0 , skipped-points 0 ) evaluated requests: 1 gets, 0 scans, 0 reverse scans
            44.880ms      0.886ms                            event:kv/kvserver/replica_read.go:221 [n2,s2,r64/8:/{Table/108-Max}] read completed
            43.540ms     -1.340ms                            structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"1","numInternalSeeks":"1","numInterfaceSteps":"0","numInternalSteps":"0","blockBytes":"89","blockBytesInCache":"89","keyBytes":"14","valueBytes":"7","pointCount":"1","pointsCoveredByRangeTombstones":"0","rangeKeyCount":"0","rangeKeyContainedPoints":"0","rangeKeySkippedPoints":"0","separatedPointCount":"0","separatedPointValueBytes":"0","separatedPointValueBytesFetched":"0","numGets":"1","numScans":"0","numReverseScans":"0"}
            46.018ms     25.394ms                    event:kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:576 [n2,client=127.0.0.1:54034,hostssl,user=root,txn=5923b618] recording span to refresh: /Table/108/1/1/0
            46.617ms     26.557ms            event:component:<flow_id:<fa887b98-4a8e-48b3-af27-653949b033c2> type:PROCESSOR id:0 sql_instance_id:2 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<value_plus_one:12 > tuples_read:<value_plus_one:2 > batch_requests_issued:<value_plus_one:2 > kv_time:<value_plus_one:<nanos:26137410 > > contention_time:<value_plus_one:<nanos:1 > > num_interface_steps:<value_plus_one:1 > num_internal_steps:<value_plus_one:1 > num_interface_seeks:<value_plus_one:2 > num_internal_seeks:<value_plus_one:2 > block_bytes:<value_plus_one:90 > block_bytes_in_cache:<value_plus_one:90 > key_bytes:<value_plus_one:15 > value_bytes:<value_plus_one:8 > point_count:<value_plus_one:2 > points_covered_by_range_tombstones:<value_plus_one:1 > range_key_count:<value_plus_one:1 > range_key_contained_points:<value_plus_one:1 > range_key_skipped_points:<value_plus_one:1 > kv_cpu_time:<> num_gets:<value_plus_one:2 > num_scans:<value_plus_one:1 > num_reverse_scans:<value_plus_one:1 > > exec:<exec_time:<> max_allocated_mem:<value_plus_one:20481 > max_allocated_disk:<> consumed_ru:<value_plus_one:1 > cpu_time:<value_plus_one:<nanos:334090 > > > output:<num_batches:<value_plus_one:2 > num_tuples:<value_plus_one:2 > > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
            46.751ms      0.134ms            event:component:<flow_id:<00000000-0000-0000-0000-000000000000> type:UNSET id:0 sql_instance_id:0 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<> tuples_read:<> batch_requests_issued:<> kv_time:<> contention_time:<> num_interface_steps:<> num_internal_steps:<> num_interface_seeks:<> num_internal_seeks:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
            46.470ms     -0.281ms            structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"fa887b98-4a8e-48b3-af27-653949b033c2","type":"PROCESSOR","id":0,"sqlInstanceId":2},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"12"},"tuplesRead":{"valuePlusOne":"2"},"batchRequestsIssued":{"valuePlusOne":"2"},"kvTime":{"valuePlusOne":"0.026137410s"},"contentionTime":{"valuePlusOne":"0.000000001s"},"numInterfaceSteps":{"valuePlusOne":"1"},"numInternalSteps":{"valuePlusOne":"1"},"numInterfaceSeeks":{"valuePlusOne":"2"},"numInternalSeeks":{"valuePlusOne":"2"},"blockBytes":{"valuePlusOne":"90"},"blockBytesInCache":{"valuePlusOne":"90"},"keyBytes":{"valuePlusOne":"15"},"valueBytes":{"valuePlusOne":"8"},"pointCount":{"valuePlusOne":"2"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"1"},"rangeKeyCount":{"valuePlusOne":"1"},"rangeKeyContainedPoints":{"valuePlusOne":"1"},"rangeKeySkippedPoints":{"valuePlusOne":"1"},"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"2"},"numScans":{"valuePlusOne":"1"},"numReverseScans":{"valuePlusOne":"1"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"20481"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"1"},"cpuTime":{"valuePlusOne":"0.000334090s"}},"output":{"numBatches":{"valuePlusOne":"2"},"numTuples":{"valuePlusOne":"2"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"}}}
            46.638ms      0.167ms            structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"00000000-0000-0000-0000-000000000000","type":"UNSET","id":0,"sqlInstanceId":0},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"0"},"tuplesRead":{"valuePlusOne":"0"},"batchRequestsIssued":{"valuePlusOne":"0"},"kvTime":{"valuePlusOne":"0s"},"contentionTime":{"valuePlusOne":"0s"},"numInterfaceSteps":{"valuePlusOne":"0"},"numInternalSteps":{"valuePlusOne":"0"},"numInterfaceSeeks":{"valuePlusOne":"0"},"numInternalSeeks":{"valuePlusOne":"0"},"blockBytes":{"valuePlusOne":"0"},"blockBytesInCache":{"valuePlusOne":"0"},"keyBytes":{"valuePlusOne":"0"},"valueBytes":{"valuePlusOne":"0"},"pointCount":{"valuePlusOne":"0"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"0"},"rangeKeyCount":{"valuePlusOne":"0"},"rangeKeyContainedPoints":{"valuePlusOne":"0"},"rangeKeySkippedPoints":{"valuePlusOne":"0"},"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"0"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"},"cpuTime":{"valuePlusOne":"0s"}},"output":{"numBatches":{"valuePlusOne":"0"},"numTuples":{"valuePlusOne":"0"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"}}}
            47.217ms     28.025ms        event:component:<flow_id:<fa887b98-4a8e-48b3-af27-653949b033c2> type:FLOW id:0 sql_instance_id:2 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<> tuples_read:<> batch_requests_issued:<> kv_time:<> contention_time:<> num_interface_steps:<> num_internal_steps:<> num_interface_seeks:<> num_internal_seeks:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<value_plus_one:20481 > max_disk_usage:<value_plus_one:1 > consumed_ru:<> >
            47.106ms     -0.110ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"fa887b98-4a8e-48b3-af27-653949b033c2","type":"FLOW","id":0,"sqlInstanceId":2},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"0"},"tuplesRead":{"valuePlusOne":"0"},"batchRequestsIssued":{"valuePlusOne":"0"},"kvTime":{"valuePlusOne":"0s"},"contentionTime":{"valuePlusOne":"0s"},"numInterfaceSteps":{"valuePlusOne":"0"},"numInternalSteps":{"valuePlusOne":"0"},"numInterfaceSeeks":{"valuePlusOne":"0"},"numInternalSeeks":{"valuePlusOne":"0"},"blockBytes":{"valuePlusOne":"0"},"blockBytesInCache":{"valuePlusOne":"0"},"keyBytes":{"valuePlusOne":"0"},"valueBytes":{"valuePlusOne":"0"},"pointCount":{"valuePlusOne":"0"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"0"},"rangeKeyCount":{"valuePlusOne":"0"},"rangeKeyContainedPoints":{"valuePlusOne":"0"},"rangeKeySkippedPoints":{"valuePlusOne":"0"},"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"0"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"},"cpuTime":{"valuePlusOne":"0s"}},"output":{"numBatches":{"valuePlusOne":"0"},"numTuples":{"valuePlusOne":"0"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"20481"},"maxDiskUsage":{"valuePlusOne":"1"},"consumedRu":{"valuePlusOne":"0"}}}
            47.464ms     29.080ms    event:sql/conn_executor_exec.go:964 [n2,client=127.0.0.1:54034,hostssl,user=root] execution ends
            47.500ms      0.037ms    event:sql/conn_executor_exec.go:964 [n2,client=127.0.0.1:54034,hostssl,user=root] rows affected: 1
            48.067ms      0.567ms        === operation:commit sql txn _verbose:1 node:2 client:127.0.0.1:54034 hostssl: user:root
            48.389ms      0.889ms    event:sql/conn_executor_exec.go:2731 [n2,client=127.0.0.1:54034,hostssl,user=root] AutoCommit. err: <nil>
    --- FAIL: TestMultiRegionDataDriven/global_tables (62.59s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

Same failure on other branches

This test on roachdash | Improve this report!

@rafiss rafiss assigned chengxiong-ruan and unassigned rafiss Jun 12, 2023
@chengxiong-ruan
Copy link
Contributor

closing in favor of #98020

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@chengxiong-ruan chengxiong-ruan

Labels
branch-release-23.1 Used to mark GA and release blockers, technical advisories, and bugs for 23.1 C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. skipped-test T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions)
Projects
None yet
Milestone
23.1
Development

No branches or pull requests
5 participants
@matthewtodd @rafiss @ajwerner @chengxiong-ruan @cockroach-teamcity