search

cockroachdb / cockroach

CockroachDB - the open source, cloud-native distributed SQL database.
https://www.cockroachlabs.com
Other
29.59k stars 3.71k forks source link

kv/kvserver: TestStoreRangeMergeWithData failed #126249

Closed cockroach-teamcity closed 1 week ago

cockroach-teamcity commented 4 weeks ago

kv/kvserver.TestStoreRangeMergeWithData failed on master @ 361f58bdb476e76fd3c6c9a2f54a48b7c74e9797:

Fatal error:

panic: test timed out after 1h16m37s
running tests:
    TestStoreRangeMergeWithData (1h16m37s)
    TestStoreRangeMergeWithData/retries=0 (1h16m37s)

Stack: 

goroutine 921659 [running]:
testing.(*M).startAlarm.func1()
    GOROOT/src/testing/testing.go:2366 +0x265
created by time.goFunc
    GOROOT/src/time/sleep.go:177 +0x45
Log preceding fatal error

``` === RUN TestStoreRangeMergeWithData test_log_scope.go:170: test logs captured to: outputs.zip/logTestStoreRangeMergeWithData2661097904 test_log_scope.go:81: use -show-logs to present logs inline === RUN TestStoreRangeMergeWithData/retries=0 ```

Parameters:

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

Same failure on other branches

- #125779 kv/kvserver: TestStoreRangeMergeWithData failed [A-testing C-bug C-test-failure O-robot P-3 T-kv branch-release-24.1.2-rc]

/cc @cockroachdb/kv

This test on roachdash | Improve this report!

Jira issue: CRDB-39820

arulajmani commented 4 weeks ago

Thanks to the logging @nvanbenschoten added, we can confirm that the merge transaction is indeed spinning. The logs are littered with:

W240626 12:47:43.130670 28 kv/kvserver/replica_command.go:960 ⋮ [T1,Vsystem,n1,s1,r69/1:‹/System?aaa-testing{-\x00\x00}›,*kvpb.AdminMergeRequest] 28880  merge txn failed (attempt 12365): TransactionRetryWithProtoRefreshError: TransactionAbortedError(ABORT_REASON_TIMESTAMP_CACHE_REJECTED): "merge" meta={id=ee3591bd key=/Local/Range/System‹/›‹"aaa-testing›‹"›/‹RangeDescriptor› iso=Serializable pri=0.01508323 epo=0 ts=1719566794.578285532,0 min=1719566794.578285532,0 seq=5} lock=true stat=PENDING rts=1719566794.578285532,0 wto=false gul=1719566795.078285532,0
I240626 12:47:43.155019 28 kv/kvserver/replica_command.go:849 ⋮ [T1,Vsystem,n1,s1,r69/1:‹/System?aaa-testing{-\x00\x00}›,*kvpb.AdminMergeRequest] 28881  initiating a merge of r70:‹/System{\x00aaa-testing\x00\x00-/NodeLiveness}› [(n1,s1):1, next=2, gen=2, sticky=9223372036.854775807,2147483647] into this range (manual)
W240626 12:47:43.615552 28 kv/kvserver/replica_command.go:960 ⋮ [T1,Vsystem,n1,s1,r69/1:‹/System?aaa-testing{-\x00\x00}›,*kvpb.AdminMergeRequest] 28882  merge txn failed (attempt 12366): TransactionRetryWithProtoRefreshError: TransactionAbortedError(ABORT_REASON_TIMESTAMP_CACHE_REJECTED): "merge" meta={id=4a806099 key=/Local/Range/System‹/›‹"aaa-testing›‹"›/‹RangeDescriptor› iso=Serializable pri=0.03137873 epo=0 ts=1719566808.135986107,0 min=1719566808.135986107,0 seq=5} lock=true stat=PENDING rts=1719566808.135986107,0 wto=false gul=1719566808.635986107,0
I240626 12:47:43.650410 28 kv/kvserver/replica_command.go:849 ⋮ [T1,Vsystem,n1,s1,r69/1:‹/System?aaa-testing{-\x00\x00}›,*kvpb.AdminMergeRequest] 28883  initiating a merge of r70:‹/System{\x00aaa-testing\x00\x00-/NodeLiveness}› [(n1,s1):1, next=2, gen=2, sticky=9223372036.854775807,2147483647] into this range (manual)
W240626 12:47:44.342121 28 kv/kvserver/replica_command.go:960 ⋮ [T1,Vsystem,n1,s1,r69/1:‹/System?aaa-testing{-\x00\x00}›,*kvpb.AdminMergeRequest] 28884  merge txn failed (attempt 12367): TransactionRetryWithProtoRefreshError: TransactionAbortedError(ABORT_REASON_TIMESTAMP_CACHE_REJECTED): "merge" meta={id=fa89842c key=/Local/Range/System‹/›‹"aaa-testing›‹"›/‹RangeDescriptor› iso=Serializable pri=0.02738480 epo=0 ts=1719566821.626367241,0 min=1719566821.626367241,0 seq=5} lock=true stat=PENDING rts=1719566821.626367241,0 wto=false gul=1719566822.126367241,0
I240626 12:47:44.370516 28 kv/kvserver/replica_command.go:849 ⋮ [T1,Vsystem,n1,s1,r69/1:‹/System?aaa-testing{-\x00\x00}›,*kvpb.AdminMergeRequest] 28885  initiating a merge of r70:‹/System{\x00aaa-testing\x00\x00-/NodeLiveness}› [(n1,s1):1, next=2, gen=2, sticky=9223372036.854775807,2147483647] into this range (manual)

We see from the log lines that the transaction keeps failing because of ABORT_REASON_TIMESTAMP_CACHE_REJECTED. Seems like we're losing resolution in the timestamp cache's read summary. This can happen if we're either compressing the read summary for some reason or we're loading the read summary from the RangePriorReadSummaryKey key.

The compression budget is set to 4MB for local keys by default, so it's likely not that.

The only place where we use the persisted read summary is in applySnapshot. Give this is a single server test, that also seems surprising.

msbutler commented 3 weeks ago

I hit this in a kvserver race build that timed out. In the tmp logs, the cockroach cluster running this test was up for 20 minutes. https://teamcity.cockroachdb.com/viewLog.html?buildId=15874939&buildTypeId=Cockroach_Ci_Tests_Testrace&tab=artifacts#%2Ftmp;%2Fbazel-testlogs%2Fpkg%2Fkv%2Fkvclient%2Frangefeed