roachtest: clearrange/checks=true failed: MVCCStats divergence #86542

cockroach-teamcity · 2022-08-22T09:19:00Z

roachtest.clearrange/checks=true failed with artifacts on master @ aaf50e920ceff3c2863ab96b9e3614b8434b70a8:

		  | I220822 09:18:04.571921 361 workload/pgx_helpers.go:79  [-] 33  pgx logger [error]: Exec logParams=map[args:[2579421732937982817 f9] err:unexpected EOF pid:5510701 sql:kv-2 time:13.509937ms]
		  | I220822 09:18:04.571954 370 workload/pgx_helpers.go:79  [-] 34  pgx logger [error]: Exec logParams=map[args:[2264071080716551703 c2] err:unexpected EOF pid:6281931 sql:kv-2 time:23.314191ms]
		  | I220822 09:18:04.571983 364 workload/pgx_helpers.go:79  [-] 35  pgx logger [error]: Exec logParams=map[args:[4863347191029465407 1d] err:unexpected EOF pid:5518672 sql:kv-2 time:23.41852ms]
		  | I220822 09:18:04.572012 156 workload/pgx_helpers.go:79  [-] 36  pgx logger [error]: Exec logParams=map[args:[-1175214458801366906 2c] err:unexpected EOF pid:5328080 sql:kv-2 time:22.889022ms]
		  | Error: unexpected EOF
		  | COMMAND_PROBLEM: exit status 1
		  |    6: 
		  | UNCLASSIFIED_PROBLEM: context canceled
		  |    7: 
		  | UNCLASSIFIED_PROBLEM: context canceled
		  |    8: 
		  | UNCLASSIFIED_PROBLEM: context canceled
		  |    9: 
		  | UNCLASSIFIED_PROBLEM: context canceled
		  |   10: 
		  | UNCLASSIFIED_PROBLEM: context canceled
		Wraps: (4) secondary error attachment
		  | COMMAND_PROBLEM: exit status 1
		  | (1) COMMAND_PROBLEM
		  | Wraps: (2) Node 5. Command with error:
		  |   | ``````
		  |   | ./cockroach workload run kv --concurrency=32 --duration=1h
		  |   | ``````
		  | Wraps: (3) exit status 1
		  | Error types: (1) errors.Cmd (2) *hintdetail.withDetail (3) *exec.ExitError
		Wraps: (5) context canceled
		Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) *cluster.WithCommandDetails (4) *secondary.withSecondaryError (5) *errors.errorString

	monitor.go:127,clearrange.go:206,clearrange.go:39,test_runner.go:896: monitor failure: monitor command failure: unexpected node event: 5: dead (exit status 7)
		(1) attached stack trace
		  -- stack trace:
		  | main.(*monitorImpl).WaitE
		  | 	main/pkg/cmd/roachtest/monitor.go:115
		  | main.(*monitorImpl).Wait
		  | 	main/pkg/cmd/roachtest/monitor.go:123
		  | github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.runClearRange
		  | 	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/clearrange.go:206
		  | github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.registerClearRange.func1
		  | 	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/clearrange.go:39
		  | [...repeated from below...]
		Wraps: (2) monitor failure
		Wraps: (3) attached stack trace
		  -- stack trace:
		  | main.(*monitorImpl).wait.func3
		  | 	main/pkg/cmd/roachtest/monitor.go:202
		  | runtime.goexit
		  | 	GOROOT/src/runtime/asm_amd64.s:1571
		Wraps: (4) monitor command failure
		Wraps: (5) unexpected node event: 5: dead (exit status 7)
		Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) *withstack.withStack (4) *errutil.withPrefix (5) *errors.errorString

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=16 , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

/cc @cockroachdb/storage _{This test on roachdash | Improve this report!

Jira issue: CRDB-18804
Epic CRDB-16237}

The text was updated successfully, but these errors were encountered:

jbowens · 2022-08-22T14:27:25Z

n5 exited after it detected its MVCC Stats divergence.

F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982  found a delta of {ContainsEstimates:0 LastUpdateNanos:1661159840223245283 IntentAge:0 GCBytesAge:0 LiveBytes:0 LiveCount:0 KeyBytes:0 KeyCount:0 ValBytes:0 ValCount:0 IntentBytes:0 IntentCount:0 SeparatedIntentCount:0 RangeKeyCount:0 RangeKeyBytes:0 RangeValCount:0 RangeValBytes:0 SysBytes:10 SysCount:0 AbortSpanBytes:0}
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !goroutine 5910946 [running]:
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !github.com/cockroachdb/cockroach/pkg/util/log.getStacks(0x1)
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !	github.com/cockroachdb/cockroach/pkg/util/log/get_stacks.go:25 +0x8a
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc001a4e920, {{{0xc003b6c900, 0x24}, {0x510835d, 0x1}, {0x0, 0x0}, {0x0, 0x0}}, 0x170da01d19a435b0, ...})
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:239 +0x97
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x5ebd520, 0xc01a7fd6e0}, 0x2, 0x4, 0x0, 0x0?, {0x50a751f, 0x14}, {0xc02d68a570, 0x1, ...})
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x645
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !github.com/cockroachdb/cockroach/pkg/util/log.Fatalf(...)
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !	github.com/cockroachdb/cockroach/bazel-out/k8-opt/bin/pkg/util/log/log_channels_generated.go:834
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).CheckConsistency(0xc003868000, {0x5ebd520, 0xc01a7fd6e0}, {{{0x0, 0x0, 0x0}, {0x0, 0x0, 0x0}, 0x0}, ...})
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_consistency.go:258 +0x1377
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*consistencyQueue).process(0xc002b9a330, {0x5ebd520, 0xc01a7fd6e0}, 0xc003868000, {0x0?, 0x0?})
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/consistency_queue.go:199 +0x193
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*mergeQueue).process(0xc002b9a1e0, {0x5ebd520, 0xc01a7fd6e0}, 0xc003868000, {0x7efc1ee55fe8, 0xc0019306c0})
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/merge_queue.go:415 +0x16b1
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*baseQueue).processReplica.func1({0x5ebd520, 0xc01a7fd6e0})
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/queue.go:980 +0x26e
F220822 09:18:04.414268 5910946 kv/kvserver/replica_consistency.go:258 ⋮ [n5,merge,s5,r555/3:‹/Table/106/1/14{137253-318677}›] 5982 !github.com/cockroachdb/cockroach/pkg/util/contextutil.RunWithTimeout({0x5ebd558?, 0xc01ab99470?}, {0xc003d31800, 0x1f}, 0xdf8475800, 0xc0050b1e20)
F

cc @cockroachdb/replication

erikgrinaker · 2022-08-22T16:03:16Z

Thanks @jbowens, I'll have a look.

blathers-crl · 2022-08-22T16:03:49Z

cc @cockroachdb/replication

cockroach-teamcity · 2022-08-23T14:08:30Z

roachtest.clearrange/checks=true failed with artifacts on master @ 80c274877a917580af62be6eb0cd48c8c7ae9c08:

test artifacts and logs in: /artifacts/clearrange/checks=true/run_1
	monitor.go:127,clearrange.go:206,clearrange.go:39,test_runner.go:896: monitor failure: monitor command failure: unexpected node event: 1: dead (exit status 137)
		(1) attached stack trace
		  -- stack trace:
		  | main.(*monitorImpl).WaitE
		  | 	main/pkg/cmd/roachtest/monitor.go:115
		  | main.(*monitorImpl).Wait
		  | 	main/pkg/cmd/roachtest/monitor.go:123
		  | github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.runClearRange
		  | 	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/clearrange.go:206
		  | github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.registerClearRange.func1
		  | 	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/clearrange.go:39
		  | [...repeated from below...]
		Wraps: (2) monitor failure
		Wraps: (3) attached stack trace
		  -- stack trace:
		  | main.(*monitorImpl).wait.func3
		  | 	main/pkg/cmd/roachtest/monitor.go:202
		  | runtime.goexit
		  | 	GOROOT/src/runtime/asm_amd64.s:1571
		Wraps: (4) monitor command failure
		Wraps: (5) unexpected node event: 1: dead (exit status 137)
		Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) *withstack.withStack (4) *errutil.withPrefix (5) *errors.errorString

	test_runner.go:1027,test_runner.go:926: test timed out (6h30m0s)

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=16 , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

_{This test on roachdash | Improve this report!}

nicktrav · 2022-08-23T14:44:09Z

This last failure seems a little different. The test timed out waiting for the last two merges to complete.

erikgrinaker · 2022-08-24T12:21:20Z

The stats failure here is similar to what we saw over in #81429, where we also had a discrepancy in SysBytes. SysBytes only applies for keys below LocalMax, i.e. system-local keys, and I don't believe we ever write MVCC range tombstones here, nor do we use the full-range GC fast path for these, so this doesn't seem related to the MVCC range key work. To be safe, I'm disallowing writing MVCC range tombstones across local keyspace in #86744.

This all leads me to believe this may have been a pre-existing problem, some sort of race when writing system-local data. It's unclear to me if this would be owned by storage or KV, but I'd like to hand it over either way.

nicktrav · 2022-08-24T14:10:31Z

cc: @itsbilal - reckon you could take a look?

cockroach-teamcity · 2022-08-25T14:26:03Z

roachtest.clearrange/checks=true failed with artifacts on master @ 524fd14da3fefcd849f44a835cc5f88f5dbdadcc:

test artifacts and logs in: /artifacts/clearrange/checks=true/run_1
	monitor.go:127,clearrange.go:206,clearrange.go:39,test_runner.go:896: monitor failure: monitor command failure: unexpected node event: 2: dead (exit status 137)
		(1) attached stack trace
		  -- stack trace:
		  | main.(*monitorImpl).WaitE
		  | 	main/pkg/cmd/roachtest/monitor.go:115
		  | main.(*monitorImpl).Wait
		  | 	main/pkg/cmd/roachtest/monitor.go:123
		  | github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.runClearRange
		  | 	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/clearrange.go:206
		  | github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.registerClearRange.func1
		  | 	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/clearrange.go:39
		  | [...repeated from below...]
		Wraps: (2) monitor failure
		Wraps: (3) attached stack trace
		  -- stack trace:
		  | main.(*monitorImpl).wait.func3
		  | 	main/pkg/cmd/roachtest/monitor.go:202
		  | runtime.goexit
		  | 	GOROOT/src/runtime/asm_amd64.s:1571
		Wraps: (4) monitor command failure
		Wraps: (5) unexpected node event: 2: dead (exit status 137)
		Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) *withstack.withStack (4) *errutil.withPrefix (5) *errors.errorString

	test_runner.go:1027,test_runner.go:926: test timed out (6h30m0s)

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=16 , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

_{This test on roachdash | Improve this report!}

itsbilal · 2022-08-25T21:16:47Z

I've yet to find a repro or come up with a reasonable cause for how we'd end up with stats delta in SysBytes, and since it seems unlikely to be caused by range keys (especially in light of #86744) I'm inclined to just wait and see if it happens again. I'll remove the release-blocker tag as both Erik and I agree this is not new behaviour.

The failure from this morning seems to also be one about waiting for the last two merges to complete. That's more fixable - especially if it's a reliable-ish flake - but it is a separate issue entirely it seems.

nicktrav · 2022-09-20T23:13:28Z

The stats divergence issue is likely resolved. The issue with the last two ranges failing to merge doesn't seem to reliably reproduce. Given this test hasn't failed in close to a month, I'm going to close it out.

93837: backupccl: deflake TestClusterRestoreFailCleanup r=stevendanna a=msbutler This test occasionally flakes due to #86806. To prevent the flakiness, this patch manually sets the kv.bulkio.write_metadata_sst.enabled cluster setting to false. When #86806 gets addressed, this patch should be reverted. Epic: None Release note: None 93897: kvnemesis: ignore `SysBytes:10` MVCC stats discrepancy r=erikgrinaker a=erikgrinaker Resolves #93890. Touches #93896. Touches #93312. Touches #86542. Epic: none Release note: None Co-authored-by: Michael Butler <[email protected]> Co-authored-by: Erik Grinaker <[email protected]>

cockroach-teamcity added this to the 22.2 milestone Aug 22, 2022

jbowens changed the title ~~roachtest: clearrange/checks=true failed~~ roachtest: clearrange/checks=true failed: MVCCStats diveragence Aug 22, 2022

jbowens changed the title ~~roachtest: clearrange/checks=true failed: MVCCStats diveragence~~ roachtest: clearrange/checks=true failed: MVCCStats divergence Aug 22, 2022

erikgrinaker self-assigned this Aug 22, 2022

exalate-issue-sync bot unassigned erikgrinaker Aug 22, 2022

exalate-issue-sync bot added the T-kv-replication label Aug 22, 2022

exalate-issue-sync bot assigned erikgrinaker Aug 22, 2022

nicktrav assigned itsbilal and unassigned erikgrinaker Aug 24, 2022

itsbilal removed the release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. label Aug 25, 2022

exalate-issue-sync bot added T-storage Storage Team and removed T-kv-replication labels Aug 29, 2022

nicktrav closed this as completed Sep 20, 2022

nicktrav added the X-unactionable This was closed because it was unactionable. label Dec 12, 2022

This was referenced Dec 19, 2022

kvserver: 10-byte discrepancy in SysBytes #93896

Open

kvnemesis: ignore SysBytes:10 MVCC stats discrepancy #93897

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

roachtest: clearrange/checks=true failed: MVCCStats divergence #86542

roachtest: clearrange/checks=true failed: MVCCStats divergence #86542

cockroach-teamcity commented Aug 22, 2022 •

edited by exalate-issue-sync bot

Loading

jbowens commented Aug 22, 2022

erikgrinaker commented Aug 22, 2022

blathers-crl bot commented Aug 22, 2022

cockroach-teamcity commented Aug 23, 2022

nicktrav commented Aug 23, 2022

erikgrinaker commented Aug 24, 2022

nicktrav commented Aug 24, 2022

cockroach-teamcity commented Aug 25, 2022

itsbilal commented Aug 25, 2022

nicktrav commented Sep 20, 2022

roachtest: clearrange/checks=true failed: MVCCStats divergence #86542

roachtest: clearrange/checks=true failed: MVCCStats divergence #86542

Comments

cockroach-teamcity commented Aug 22, 2022 • edited by exalate-issue-sync bot Loading

jbowens commented Aug 22, 2022

erikgrinaker commented Aug 22, 2022

blathers-crl bot commented Aug 22, 2022

cockroach-teamcity commented Aug 23, 2022

nicktrav commented Aug 23, 2022

erikgrinaker commented Aug 24, 2022

nicktrav commented Aug 24, 2022

cockroach-teamcity commented Aug 25, 2022

itsbilal commented Aug 25, 2022

nicktrav commented Sep 20, 2022

cockroach-teamcity commented Aug 22, 2022 •

edited by exalate-issue-sync bot

Loading