roachtest: kv/gracefuldraining failed

[cockroach-teamcity]

roachtest.kv/gracefuldraining failed with artifacts on master @ b6c13686495bbe9ad476b28033461ef7628e18a8:

(assertions.go:363).Fail: 
	Error Trace:	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/kv.go:621
	            				main/pkg/cmd/roachtest/monitor.go:120
	            				golang.org/x/sync/errgroup/external/org_golang_x_sync/errgroup/errgroup.go:78
	            				src/runtime/asm_amd64.s:1695
	Error:      	Received unexpected error:
	            	QPS of 1207.00 at time 2024-09-29 07:20:30.262333932 +0000 UTC m=+5522.211238862 is below minimum allowable QPS of 1800.00
	            	(1) attached stack trace
	            	  -- stack trace:
	            	  | github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.registerKVGracefulDraining.func1.3
	            	  | 	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/kv.go:604
	            	  | github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests.registerKVGracefulDraining.func1.5
	            	  | 	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/kv.go:621
	            	  | main.(*monitorImpl).Go.func1
	            	  | 	main/pkg/cmd/roachtest/monitor.go:120
	            	  | golang.org/x/sync/errgroup.(*Group).Go.func1
	            	  | 	golang.org/x/sync/errgroup/external/org_golang_x_sync/errgroup/errgroup.go:78
	            	  | runtime.goexit
	            	  | 	src/runtime/asm_amd64.s:1695
	            	Wraps: (2) QPS of 1207.00 at time 2024-09-29 07:20:30.262333932 +0000 UTC m=+5522.211238862 is below minimum allowable QPS of 1800.00
	            	Error types: (1) *withstack.withStack (2) *errutil.leafError
	Test:       	kv/gracefuldraining
(require.go:1357).NoError: FailNow called
(kv.go:642).func1: context cancelled while waiting
test artifacts and logs in: /artifacts/kv/gracefuldraining/cpu_arch=arm64/run_1

Parameters:

• ROACHTEST_arch=arm64
• ROACHTEST_cloud=gce
• ROACHTEST_coverageBuild=false
• ROACHTEST_cpu=4
• ROACHTEST_encrypted=false
• ROACHTEST_runtimeAssertionsBuild=false
• ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

See: Grafana

Same failure on other branches

• roachtest: kv/gracefuldraining failed #130760 roachtest: kv/gracefuldraining failed [C-test-failure O-roachtest O-robot T-kv X-duplicate branch-release-24.2]

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-42610

[kvoli]

The latency is reflected in the workload logs as well, 25s after restarting n6, after stopping n6 once.

# (07:20:28)
  151.0s        0          504.8          496.0      1.4      1.9      3.1     13.1 follower-read
  151.0s        0          489.8          493.3      1.5      1.9      2.4      6.6 read
  151.0s        0         1003.7          993.8      3.8      4.7      5.5     18.9 write
  152.0s        0          346.1          495.0      1.4      2.0      2.6      3.3 follower-read
  152.0s        0          306.1          492.1      1.5      2.1      2.6      3.9 read
  152.0s        0          653.2          991.5      3.8      5.0      5.5      7.1 write
  153.0s        0            7.0          491.8      1.4      1.9      1.9      1.9 follower-read
  153.0s        0           13.0          488.9   1342.2   1543.5   1610.6   1610.6 read
  153.0s        0           14.0          985.1      3.9      4.7      5.0      5.0 write

There's some correlated latency jumps for clock sync to n1 right as the test fails (n2,n3,n4,n5,n6):

Details

W240929 07:20:29.524490 239 2@rpc/clock_offset.go:291 ⋮ [T1,Vsystem,n2,rnode=1,raddr=‹10.128.0.145:26257›,class=default,rpc] 733  latency jump (prev avg 0.63ms, current 934.24ms)
W240929 07:20:29.602120 518 2@rpc/clock_offset.go:291 ⋮ [T1,Vsystem,n3,rnode=1,raddr=‹10.128.0.145:26257›,class=raft,rpc] 70  latency jump (prev avg 0.61ms, current 647.79ms)
W240929 07:20:29.623591 277 2@rpc/clock_offset.go:291 ⋮ [T1,Vsystem,n4,rnode=1,raddr=‹10.128.0.145:26257›,class=system,rpc] 729  latency jump (prev avg 0.56ms, current 1131.96ms)
W240929 07:20:29.622413 477 2@rpc/clock_offset.go:291 ⋮ [T1,Vsystem,n5,rnode=1,raddr=‹10.128.0.145:26257›,class=rangefeed,rpc] 712  latency jump (prev avg 0.59ms, current 916.45ms)
W240929 07:20:29.593994 714 2@rpc/clock_offset.go:291 ⋮ [T1,Vsystem,n6,rnode=1,raddr=‹10.128.0.145:26257›,class=default,rpc] 86  latency jump (prev avg 0.75ms, current 748.68ms)

Which suggest n1 slowed down processing right at the moment throughput dropped. This is supported by raft slow logging and slow heartbeats:

I240929 07:20:29.523266 329 kv/kvserver/store_raft.go:697 ⋮ [T1,Vsystem,n1,s1,r73/1:‹/Table/106/1/-7{94488…-76224…}›,raft] 1013  raft ready handling: 0.51s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.51s], wrote [append-batch=710 B, append-ent=456 B (4), ]; node might be overloaded
W240929 07:20:30.173956 354 kv/kvserver/liveness/liveness.go:758 â‹® [T1,Vsystem,n1,liveness-hb] 1027  slow heartbeat took 1.137388463s; err=<nil>

Sure enough, there's large spike in goroutine scheduling latency on n1 at this time:

Which correlates with the exec latency spike:

Sadly, there's no CPU profile for this period and I can't glean why there was a goroutine spike, aside from saying it may not be replica related based on the recorded CPU (but this may not capture the spike):

We need to capture a CPU profile during the spike, or a runtime trace.

Marking as a bug and assigning P-2 for now. Opened #131622 to profile CPU continuously.