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.

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

roachtest: unoptimized-query-oracle/disable-rules=all/seed-multi-region failed #90504

Closed
cockroach-teamcity opened this issue Oct 22, 2022 · 14 comments · Fixed by #91244
Closed
Assignees
Labels
branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-roachtest O-robot Originated from a bot. T-sql-queries SQL Queries Team
Milestone

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Oct 22, 2022

roachtest.unoptimized-query-oracle/disable-rules=all/seed-multi-region failed with artifacts on master @ a3b578466bcdcc5d2bbea628d33c337d87b9f4b8:

test artifacts and logs in: /artifacts/unoptimized-query-oracle/disable-rules=all/seed-multi-region/run_1
(test_runner.go:1062).teardownTest: test timed out (1h0m0s)

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

/cc @cockroachdb/sql-queries

This test on roachdash | Improve this report!

Jira issue: CRDB-20803

@cockroach-teamcity cockroach-teamcity added branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-roachtest O-robot Originated from a bot. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. labels Oct 22, 2022
@cockroach-teamcity cockroach-teamcity added this to the 22.2 milestone Oct 22, 2022
@blathers-crl blathers-crl bot added the T-sql-queries SQL Queries Team label Oct 22, 2022
@DrewKimball
Copy link
Collaborator

Seeing these messages repeat in the kv-distribution.log for node 1:

[n1,replicate,s1,r53/1:/{Table/104-Max}] allocate voter: []›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251  error processing replica: avoid up-replicating to fragile quorum: ‹0 of 4 live stores are able to take a new replica for the range (2 already have a voter, 0 already have a non-voter); replicas must match constraints [{+region=europe-west2:1}]; voting replicas must match voter_constraints [{+region=europe-west2}]›‹›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹trace:›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹     0.000ms      0.000ms    === operation:process replica _unfinished:1 _verbose:1 node:1 replicate: store:1 range:53/1:/{Table/104-Max}›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹     0.065ms      0.065ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:682 [n1,replicate,s1,r53/1:/{Table/104-Max}] add voter - missing voter need=3, have=1, priority=10001.00›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹     0.086ms      0.021ms    event:kv/kvserver/replicate_queue.go:866 [n1,replicate,s1,r53/1:/{Table/104-Max}] next replica action: add voter›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹     0.130ms      0.044ms    event:kv/kvserver/allocator/storepool/store_pool.go:1054 [n1,replicate,s1,r53/1:/{Table/104-Max}] s2 is a live target, candidate for rebalancing›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹     0.150ms      0.020ms    event:kv/kvserver/allocator/storepool/store_pool.go:1054 [n1,replicate,s1,r53/1:/{Table/104-Max}] s3 is a live target, candidate for rebalancing›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹     0.172ms      0.022ms    event:kv/kvserver/allocator/storepool/store_pool.go:1054 [n1,replicate,s1,r53/1:/{Table/104-Max}] s4 is a live target, candidate for rebalancing›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹     0.210ms      0.037ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:1037 [n1,replicate,s1,r53/1:/{Table/104-Max}] allocate voter: [›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹s3, valid:true, fulldisk:false, necessary:true, diversity:0.75, highReadAmp: false, l0SubLevels: 0, converges:0, balance:-1, rangeCount:51, queriesPerSecond:12.03]›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹     0.238ms      0.029ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:1039 [n1,replicate,s1,r53/1:/{Table/104-Max}] add target: s3, valid:true, fulldisk:false, necessary:true, diversity:0.75, highReadAmp: false, l0SubLevels: 0, converges:0, balance:-1, rangeCount:51, queriesPerSecond:12.03›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹     0.286ms      0.048ms    event:kv/kvserver/allocator/storepool/store_pool.go:1054 [n1,replicate,s1,r53/1:/{Table/104-Max}] s4 is a live target, candidate for rebalancing›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹     0.303ms      0.017ms    event:kv/kvserver/allocator/storepool/store_pool.go:1054 [n1,replicate,s1,r53/1:/{Table/104-Max}] s2 is a live target, candidate for rebalancing›
I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251 +‹     0.321ms      0.018ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:1037 [n1,replicate,s1,r53/1:/{Table/104-Max}] allocate voter: []›
I221022 11:10:30.597518 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1252  error processing replica: avoid up-replicating to fragile quorum: ‹0 of 4 live stores are able to take a new replica for the range (2 already have a voter, 0 already have a non-voter); replicas must match constraints [{+region=europe-west2:1}]; voting replicas must match voter_constraints [{+region=europe-west2}]›‹›

Node 1 is us-east1, node 2 is us-west1, node 3 is europe-west2, node 4 is us-east1. I see these lines in the query-oracle logs:

ALTER DATABASE defaultdb SET PRIMARY REGION "europe-west2";
ALTER TABLE seed_mr_table SET LOCALITY REGIONAL BY ROW;

cockroach-kv-distribution.log

@cockroach-teamcity

This comment was marked as off-topic.

@rytaft
Copy link
Collaborator

rytaft commented Oct 24, 2022

The most recent failure is an OOM on node 1

@rytaft
Copy link
Collaborator

rytaft commented Oct 24, 2022

Here's the memory profile:
Screen Shot 2022-10-24 at 10 30 18 AM
zoom in:
Screen Shot 2022-10-24 at 10 35 23 AM

@mgartner
Copy link
Collaborator

Removing the release-blocker label.

@mgartner mgartner removed release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. blocks-22.2.0-beta.5 labels Oct 24, 2022
@cockroach-teamcity
Copy link
Member Author

roachtest.unoptimized-query-oracle/disable-rules=all/seed-multi-region failed with artifacts on master @ c5decaeb69155399647909163451f3d8ca7858b6:

test artifacts and logs in: /artifacts/unoptimized-query-oracle/disable-rules=all/seed-multi-region/run_1
(test_runner.go:1062).teardownTest: test timed out (1h0m0s)

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

@DrewKimball
Copy link
Collaborator

DrewKimball commented Oct 25, 2022

From node 1 log for the most recent failure:

I221025 11:25:11.748283 1524 sql/schema_change_plan_node.go:129 ⋮ [n1,client=35.185.13.72:33144,user=root] 2257  schema change waiting for concurrent schema changes on descriptor 104, waited 25m55.751163976s so far
W221025 11:25:12.880952 309 server/node.go:1000 ⋮ [n1,summaries] 2258  health alerts detected: {Alerts:[{StoreID:1 Category:‹METRICS› Description:‹ranges.underreplicated› Value:1}]}
W221025 11:25:22.915989 309 server/node.go:1000 ⋮ [n1,summaries] 2259  health alerts detected: {Alerts:[{StoreID:1 Category:‹METRICS› Description:‹ranges.underreplicated› Value:1}]}
W221025 11:25:32.881266 309 server/node.go:1000 ⋮ [n1,summaries] 2260  health alerts detected: {Alerts:[{StoreID:1 Category:‹METRICS› Description:‹ranges.underreplicated› Value:1}]}
I221025 11:25:42.154393 1524 sql/schema_change_plan_node.go:129 ⋮ [n1,client=35.185.13.72:33144,user=root] 2261  schema change waiting for concurrent schema changes on descriptor 104, waited 26m26.157272113s so far
W221025 11:25:42.881018 309 server/node.go:1000 ⋮ [n1,summaries] 2262  health alerts detected: {Alerts:[{StoreID:1 Category:‹METRICS› Description:‹ranges.underreplicated› Value:1}]}
W221025 11:25:52.887353 309 server/node.go:1000 ⋮ [n1,summaries] 2263  health alerts detected: {Alerts:[{StoreID:1 Category:‹METRICS› Description:‹ranges.underreplicated› Value:1}]}
W221025 11:26:02.881625 309 server/node.go:1000 ⋮ [n1,summaries] 2264  health alerts detected: {Alerts:[{StoreID:1 Category:‹METRICS› Description:‹ranges.underreplicated› Value:1}]}
I221025 11:26:10.696189 478 jobs/adopt.go:108 ⋮ [n1] 2265  claimed 1 jobs
I221025 11:26:10.959466 69289 jobs/adopt.go:243 ⋮ [n1] 2266  job 808146582675259395: resuming execution
I221025 11:26:11.442887 69292 jobs/registry.go:1219 ⋮ [n1] 2267  AUTO SCHEMA TELEMETRY job 808146582675259395: stepping through state running with error: <nil>
I221025 11:26:11.903930 69292 jobs/registry.go:1219 ⋮ [n1] 2268  AUTO SCHEMA TELEMETRY job 808146582675259395: stepping through state succeeded with error: <nil>
I221025 11:26:12.507105 1524 sql/schema_change_plan_node.go:129 ⋮ [n1,client=35.185.13.72:33144,user=root] 2269  schema change waiting for concurrent schema changes on descriptor 104, waited 26m56.509985895s so far
W221025 11:26:12.889588 309 server/node.go:1000 ⋮ [n1,summaries] 2270  health alerts detected: {Alerts:[{StoreID:1 Category:‹METRICS› Description:‹ranges.underreplicated› Value:1}]}
I221025 11:26:19.236044 14 util/log/clog.go:409 ⋮ [-] 2271  SIGQUIT received. stack traces:
I221025 11:26:19.236044 14 util/log/clog.go:409 ⋮ [-] 2271 +‹goroutine 14 [running]:›
I221025 11:26:19.236044 14 util/log/clog.go:409 ⋮ [-] 2271 +‹github.com/cockroachdb/cockroach/pkg/util/log.getStacks(0x1)›
I221025 11:26:19.236044 14 util/log/clog.go:409 ⋮ [-] 2271 +‹	github.com/cockroachdb/cockroach/pkg/util/log/get_stacks.go:25 +0x89›
I221025 11:26:19.236044 14 util/log/clog.go:409 ⋮ [-] 2271 +‹github.com/cockroachdb/cockroach/pkg/util/log.DumpStacks({0x67b5f38, 0xc000078088}, {0x5320ca6, 0x10})›
I221025 11:26:19.236044 14 util/log/clog.go:409 ⋮ [-] 2271 +‹	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:407 +0x50›
I221025 11:26:19.236044 14 util/log/clog.go:409 ⋮ [-] 2271 +‹github.com/cockroachdb/cockroach/pkg/cli.debugSignalSetup.func1()›
I221025 11:26:19.236044 14 util/log/clog.go:409 ⋮ [-] 2271 +‹	github.com/cockroachdb/cockroach/pkg/cli/cli.go:335 +0x59›
I221025 11:26:19.236044 14 util/log/clog.go:409 ⋮ [-] 2271 +‹created by github.com/cockroachdb/cockroach/pkg/cli.debugSignalSetup›
I221025 11:26:19.236044 14 util/log/clog.go:409 ⋮ [-] 2271 +‹	github.com/cockroachdb/cockroach/pkg/cli/cli.go:329 +0x10d›
I221025 11:26:19.236044 14 util/log/clog.go:409 ⋮ [-] 2271 +

Seeing these lines in the setup:

ALTER DATABASE defaultdb SET PRIMARY REGION "us-west1";
ALTER TABLE seed_mr_table SET LOCALITY REGIONAL BY ROW;

Looks like the same thing as the first failure:

I221025 11:17:53.119404 3072 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1406  error processing replica: avoid up-replicating to fragile quorum: ‹0 of 4 live stores are able to take a new replica for the range (2 already have a voter, 0 already have a non-voter); replicas must match constraints [{+region=us-west1:1}]; voting replicas must match voter_constraints [{+region=us-west1}]›‹›

@rytaft
Copy link
Collaborator

rytaft commented Oct 25, 2022

I opened a new issue for the OOM: #90645

@cockroach-teamcity
Copy link
Member Author

roachtest.unoptimized-query-oracle/disable-rules=all/seed-multi-region failed with artifacts on master @ 1b1c8da55be48c174b7b370b305f42622546209f:

test artifacts and logs in: /artifacts/unoptimized-query-oracle/disable-rules=all/seed-multi-region/run_1
(test_impl.go:314).Errorf: test timed out (1h0m0s)

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

@rytaft
Copy link
Collaborator

rytaft commented Nov 3, 2022

This seems relevant (from the last failure, which was a timeout):

goroutine 30067036 [IO wait, 30 minutes]:
internal/poll.runtime_pollWait(0x7fb1ee3dc5e8, 0x72)
	GOROOT/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc004e52000?, 0xc00496f000?, 0x0)
	GOROOT/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	GOROOT/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc004e52000, {0xc00496f000, 0x1000, 0x1000})
	GOROOT/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc004e52000, {0xc00496f000?, 0x0?, 0x188?})
	GOROOT/src/net/fd_posix.go:55 +0x29
net.(*conn).Read(0xc00246b3f8, {0xc00496f000?, 0xc0064c8f20?, 0x0?})
	GOROOT/src/net/net.go:183 +0x45
bufio.(*Reader).Read(0xc0031bd020, {0xc0064c8f20, 0x5, 0xc004e52000?})
	GOROOT/src/bufio/bufio.go:237 +0x1bb
io.ReadAtLeast({0x71a78a0, 0xc0031bd020}, {0xc0064c8f20, 0x5, 0x200}, 0x5)
	GOROOT/src/io/io.go:332 +0x9a
io.ReadFull(...)
	GOROOT/src/io/io.go:351
github.com/lib/pq.(*conn).recvMessage(0xc0064c8f00, 0xc0089c2900)
	github.com/lib/pq/external/com_github_lib_pq/conn.go:1004 +0xca
github.com/lib/pq.(*conn).recv1Buf(0xc0064c8f00, 0x1000?)
	github.com/lib/pq/external/com_github_lib_pq/conn.go:1059 +0x2e
github.com/lib/pq.(*conn).recv1(...)
	github.com/lib/pq/external/com_github_lib_pq/conn.go:1086
github.com/lib/pq.(*conn).simpleQuery(0xc0064c8f00, {0xc00172c840?, 0x182})
	github.com/lib/pq/external/com_github_lib_pq/conn.go:696 +0x234
github.com/lib/pq.(*conn).query(0xc0064c8f00, {0xc00172c840, 0x182}, {0xa69fb98, 0x0, 0x0})
	github.com/lib/pq/external/com_github_lib_pq/conn.go:889 +0x3ee
github.com/lib/pq.(*conn).QueryContext(0x7fb20ff8a128?, {0x71f81d0, 0xc0000ba060}, {0xc00172c840, 0x182}, {0xa69fb98, 0x0, 0xfb5c32?})
	github.com/lib/pq/external/com_github_lib_pq/conn_go18.go:24 +0xd7
database/sql.ctxDriverQuery({0x71f81d0?, 0xc0000ba060?}, {0x7fb23e0a37c0?, 0xc0064c8f00?}, {0x0?, 0x0?}, {0xc00172c840?, 0x43a86d?}, {0xa69fb98, 0x0, ...})
	GOROOT/src/database/sql/ctxutil.go:48 +0xe5
database/sql.(*DB).queryDC.func1()
	GOROOT/src/database/sql/sql.go:1757 +0x175
database/sql.withLock({0x71c7668, 0xc00338ac60}, 0xc006dbce50)
	GOROOT/src/database/sql/sql.go:3439 +0x8c
database/sql.(*DB).queryDC(0xc0056ff401?, {0x71f81d0, 0xc0000ba060}, {0x0, 0x0}, 0xc00338ac60, 0xc003021cb0, {0xc00172c840, 0x182}, {0x0, ...})
	GOROOT/src/database/sql/sql.go:1752 +0x211
database/sql.(*DB).query(0x550740?, {0x71f81d0, 0xc0000ba060}, {0xc00172c840, 0x182}, {0x0, 0x0, 0x0}, 0x0?)
	GOROOT/src/database/sql/sql.go:1735 +0xfd
database/sql.(*DB).QueryContext(0x182?, {0x71f81d0, 0xc0000ba060}, {0xc00172c840, 0x182}, {0x0, 0x0, 0x0})
	GOROOT/src/database/sql/sql.go:1708 +0xda
database/sql.(*DB).Query(...)
	GOROOT/src/database/sql/sql.go:1726
github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.(*queryComparisonHelper).runQuery.func1({0xc00172c840?, 0x5baf260?})
	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/query_comparison_util.go:298 +0x85
github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.(*queryComparisonHelper).runQuery(0xc0089c34e8, {0xc00172c840, 0x182})
	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/query_comparison_util.go:318 +0x265
github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.runUnoptimizedQueryOracleImpl(0x13f?, 0xc00635a4e0, {0xc006a55d40, 0xc0034055e0, 0xc003405600, 0xc002f9a270, 0x43b, {0xc0064e19c0, 0x4, 0x4}, ...}, ...)
	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/unoptimized_query_oracle.go:126 +0x1f8
github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.registerUnoptimizedQueryOracle.func1.1(0x0?, 0x0?, {0xc006a55d40, 0xc0034055e0, 0xc003405600, 0xc002f9a270, 0x43b, {0x0, 0x0, 0x0}, ...})
	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/unoptimized_query_oracle.go:67 +0x5e
github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.runOneRoundQueryComparison({0x71f8208, 0xc0032aade0}, 0x0?, 0x0?, {0x7273b78, 0xc00803f600}, {0x7294a00, 0xc0043a0b00}, 0xc0089c3f30)
	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/query_comparison_util.go:241 +0x1932
github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.runQueryComparison({0x71f8198, 0xc00473aa40}, {0x7273b78, 0xc00803f600}, {0x7294a00, 0xc0043a0b00}, 0x5b4d96?)
	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/query_comparison_util.go:67 +0x44b
github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.registerUnoptimizedQueryOracle.func1({0x71f8198, 0xc00473aa40}, {0x7273b78, 0xc00803f600}, {0x7294a00, 0xc0043a0b00})
	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/unoptimized_query_oracle.go:63 +0xfb
main.(*testRunner).runTest.func2()
	main/pkg/cmd/roachtest/test_runner.go:923 +0xa3
created by main.(*testRunner).runTest
	main/pkg/cmd/roachtest/test_runner.go:908 +0x8de

@rytaft
Copy link
Collaborator

rytaft commented Nov 3, 2022

This is the query that was executing:

SELECT 'X':::STRING AS col_357, e'\\xc380':::BYTES AS col_358, tab_96._bool AS col_359, tab_97.tableoid AS col_360 
FROM defaultdb.public.seed_mr_table@[0] AS tab_96 
JOIN defaultdb.public.seed_mr_table@[0] AS tab_97 
JOIN defaultdb.public.seed_mr_table@[0] AS tab_98 
  ON (tab_97._int4) = (tab_98._int4) 
  ON (tab_96._int4) = (tab_98._int4) 
ORDER BY tab_98._date DESC, tab_97._int4 ASC

Decoded plan gist:

    crdb_internal.decode_plan_gist
--------------------------------------
  • sort
  │ order
  │
  └── • render
      │
      └── • hash join
          │ equality: (_) = (_)
          │
          ├── • scan
          │     table: ?@?
          │     spans: FULL SCAN
          │
          └── • hash join
              │ equality: (_) = (_)
              │
              ├── • scan
              │     table: ?@?
              │     spans: FULL SCAN
              │
              └── • scan
                    table: ?@?
                    spans: FULL SCAN
(22 rows)

@rytaft
Copy link
Collaborator

rytaft commented Nov 3, 2022

I'm fairly certain that these health alerts are because we're only using 4 nodes for the multi-region config, which is not advisable:

I221022 11:10:27.350368 3008 13@kv/kvserver/replicate_queue.go:817 ⋮ [n1,replicate,s1,r53/1:‹/{Table/104-Max}›] 1251  error processing replica: avoid up-replicating to fragile quorum: ‹0 of 4 live stores are able to take a new replica for the range (2 already have a voter, 0 already have a non-voter); replicas must match constraints [{+region=europe-west2:1}]; voting replicas must match voter_constraints [{+region=europe-west2}]›‹›

I think I'll change the configs for this test and costfuzz to use 9 nodes and hope that fixes some of the issues.

@cockroach-teamcity
Copy link
Member Author

roachtest.unoptimized-query-oracle/disable-rules=all/seed-multi-region failed with artifacts on master @ 4c828ca5df8ea70b92ba58c6cb4868303cee1262:

test artifacts and logs in: /artifacts/unoptimized-query-oracle/disable-rules=all/seed-multi-region/run_1
(test_impl.go:314).Errorf: test timed out (1h0m0s)

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

@cucaroach
Copy link
Contributor

For last one node 1 was here:


I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/pebble.(*memTable).prepare(0xc001cbe240?, 0xc0078fec60?)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/mem_table.go:175 +0xf9›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/pebble.(*DB).makeRoomForWrite(0xc0009b6500, 0xc0078fec60)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/db.go:1821 +0xa5›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/pebble.(*DB).commitWrite(0xc0009b6500, 0xc0078fec60, 0xc00120cc38?, 0xc0078fec60?)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/db.go:846 +0x185›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/pebble.(*commitPipeline).prepare(0xc00120cc00, 0xc0078fec60, 0x0?)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/commit.go:379 +0x144›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/pebble.(*commitPipeline).Commit(0xc00120cc00, 0xc0078fec60, 0x7?)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/commit.go:253 +0x5e›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/pebble.(*DB).Apply(0xc0009b6500, 0xc0078fec60, 0x70?)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/db.go:765 +0x1ce›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/pebble.(*Batch).Commit(...)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/batch.go:1049›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/storage.(*pebbleMapBatchWriter).Flush(0xc007fe4030)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/storage/disk_map.go:223 +0x34›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/storage.(*pebbleMapBatchWriter).Put(0xc007fe4030, {0xc006ce4030?, 0xc0094d5800?, 0x7e?}, {0xc009130000, 0x70, 0x80})›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/storage/disk_map.go:216 +0xaa›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql/rowcontainer.(*DiskRowContainer).AddRow(0xc0042d2160, {0x67f41e8, 0xc0094d5800}, {0xc00b6b0b00?, 0xc00b6b0b00?, 0xc0d2587f2dd8a132?})›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/rowcontainer/disk_row_container.go:186 +0xbd›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql/rowcontainer.(*DiskBackedRowContainer).AddRow(0xc006d94900, {0x67f41e8, 0xc0094d5800}, {0xc00b6b0b00, 0xe, 0xe})›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/rowcontainer/row_container.go:445 +0x46›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql/rowexec.(*sortAllProcessor).fill(0xc00b6b1080)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/rowexec/sorter.go:253 +0x1c4›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql/rowexec.(*sortAllProcessor).Start(0xc00b6b1080, {0x67f4140?, 0xc006be7680?})›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/rowexec/sorter.go:225 +0x65›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql/execinfra.(*ProcessorBaseNoHelper).Run(0xc00b6b1080, {0x67f4140?, 0xc006be7680?})›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/execinfra/processorsbase.go:732 +0x3a›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql/flowinfra.(*FlowBase).Run(0xc008a81680, {0x67f4140, 0xc006be7680})›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/flowinfra/flow.go:467 +0x254›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).Run(0xc00444c000, {0x67f41e8, 0xc0094d5170}, 0xc0017d7a40, 0xc00a719a20, 0xc006a48780, 0xc0052f4000, 0xc0050fa840, 0x0)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:688 +0xa78›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRun(0xc0094d51a0?, {0x67f41e8, 0xc0094d5170}, 0x0?, 0xc0017d7a40, 0x5227140?, {{0x67f6638?, 0xc002734280?}, 0x0?}, 0xc0052f4000)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1553 +0x1f9›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).PlanAndRunAll(0xc0017d7a40?, {0x67f41e8, 0xc0094d5170}, 0xc0050fa4e8?, 0x1?, 0xc0050fa4e8, 0xc0052f4000, 0xc000cc41e0?)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:1305 +0x206›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execWithDistSQLEngine(0xc0050fa000, {0x67f41e8, 0xc0094d5170}, 0xc0050fa4e8, 0xc0094d5170?, {0x7f956ed7d030?, 0xc0064fcb08}, 0x0?, 0xc00a719b68)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1572 +0x4c8›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).dispatchToExecutionEngine(0xc0050fa000, {0x67f41e8, 0xc009227560}, 0xc0050fa4e8, {0x7f956ed7d030, 0xc0064fcb08})›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1214 +0xb99›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmtInOpenState(0xc0050fa000, {0x67f41e8?, 0xc009227440?}, {{0x681ce80, 0xc009ff9ef0}, {0x0, 0x0, 0x0}, {0xc0067b35eb, 0x369}, ...}, ...)›
I221107 11:22:36.778722 20 util/log/clog.go:409 ⋮ [-] 8701 +‹	github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:723 +0x2534›

The loop in func (s *sortAllProcessor) fill() looks like a good candidate for a cancel checker.

craig bot pushed a commit that referenced this issue Nov 9, 2022
91244: roachprod,roachtest: change default zones and cluster size for some tests r=rytaft a=rytaft

This commit updates the default zones used for roachprod clusters to include three different zones from three different regions.

This commit also changes the cluster size for the multi-region versions of `costfuzz` and `unoptimized-query-oracle` to 9, so that we won't get errors related to a fragile quorum and underreplicated ranges.

Fixes #90504

Release note: None

Co-authored-by: Rebecca Taft <[email protected]>
@craig craig bot closed this as completed in e8a458d Nov 9, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-roachtest O-robot Originated from a bot. T-sql-queries SQL Queries Team
Projects
Archived in project
Development

Successfully merging a pull request may close this issue.

6 participants