roachtest: kv/contention/nodes=4 failed

[cockroach-teamcity]

(roachtest).kv/contention/nodes=4 failed on provisional_202008261913_v20.2.0-beta.1@eaa939ce6548a54a23970814ff00f30ad87680ac:

The test failed on branch=provisional_202008261913_v20.2.0-beta.1, cloud=gce:
test artifacts and logs in: /home/agent/work/.go/src/github.com/cockroachdb/cockroach/artifacts/kv/contention/nodes=4/run_1
	ts_util.go:116,kv.go:260,cluster.go:2591,errgroup.go:57: average txns per second 93.895596 was under target 100.000000

	cluster.go:2613,kv.go:263,test_runner.go:754: monitor failure: monitor task failed: t.Fatal() was called
		(1) attached stack trace
		  -- stack trace:
		  | main.(*monitor).WaitE
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/cluster.go:2601
		  | main.(*monitor).Wait
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/cluster.go:2609
		  | main.registerKVContention.func1
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/kv.go:263
		  | main.(*testRunner).runTest.func2
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/test_runner.go:754
		Wraps: (2) monitor failure
		Wraps: (3) attached stack trace
		  -- stack trace:
		  | main.(*monitor).wait.func2
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/cluster.go:2657
		Wraps: (4) monitor task failed
		Wraps: (5) attached stack trace
		  -- stack trace:
		  | main.init
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/cluster.go:2571
		  | runtime.doInit
		  | 	/usr/local/go/src/runtime/proc.go:5228
		  | runtime.main
		  | 	/usr/local/go/src/runtime/proc.go:190
		  | runtime.goexit
		  | 	/usr/local/go/src/runtime/asm_amd64.s:1357
		Wraps: (6) t.Fatal() was called
		Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) *withstack.withStack (4) *errutil.withPrefix (5) *withstack.withStack (6) *errutil.leafError

More

Artifacts: /kv/contention/nodes=4
Related:

• roachtest: kv/contention/nodes=4 failed #53403 roachtest: kv/contention/nodes=4 failed C-test-failure O-roachtest O-robot branch-master release-blocker

• roachtest: kv/contention/nodes=4 failed #52878 roachtest: kv/contention/nodes=4 failed C-test-failure O-roachtest O-robot branch-provisional_202008151325_v19.2.10 release-blocker

• roachtest: kv/contention/nodes=4 failed #45698 roachtest: kv/contention/nodes=4 failed C-test-failure O-roachtest O-robot branch-release-19.2 release-blocker

See this test on roachdash
_{powered by pkg/cmd/internal/issues}

[tbg]

@nvanbenschoten can you take a look at this one on Monday as well? Seems less dramatic than the conc mgr panic but it's also on the 20.2-beta list.

[knz]

FWIW the exact error is average txns per second 93.895596 was under target 100.000000

[nvanbenschoten]

I was looking into this last week. There's definitely something real here. About 20% of tests seem to see 10 minute transaction stalls repeatedly, which is what we would expect if transactions end up waiting for someone else to expire. This could be an indication of an abandoned transaction that is not cleaned up eagerly. Or something else.

I also stumbled upon #53677 while looking into this, which is moderately concerning.

[nvanbenschoten]

TL;DR: not a release blocker.

I think I see what's going on here. In #45568, we added the COCKROACH_TXN_HEARTBEAT_DURING_1PC testing knob to ensure that in-flight 1PC transactions never expired while contending with other txns and waiting in wait-queues. The effect of this was that a transaction could create its transaction record through a HeartbeatTxn request and then perform a 1PC transaction. Because the 1PC path doesn't check for a persistent transaction record (because one should never exist without this testing knob), this results in a pretty scary situation - we end up with a committed transaction that still has a PENDING transaction record.

What we were seeing in this test is that this situation would occasionally cause issues if an in-flight PushTxn request misses the concurrency.Manager.OnTransactionUpdated notification. When this happens, the PushTxn will enqueue in the txnWaitQueue and begin querying the already-committed transaction's record using QueryTxn requests. Because the record is present and PENDING, the request will stall until the record expires, which the test dramatically delays (COCKROACH_TXN_LIVENESS_HEARTBEAT_MULTIPLIER=600).

So we could fix this by ensuring that we delete any existing transaction record on a 1PC transaction, but this actually seems misguided. Doing so is an added cost that we only need with COCKROACH_TXN_HEARTBEAT_DURING_1PC. Instead, I plan to remove the COCKROACH_TXN_HEARTBEAT_DURING_1PC knob entirely. It was misguided and the test will still fail on any deadlocks even without this now that we increased the txn expiration from 2m to 10m in 3956bb6.

I'll also make a note that heartbeating a transaction that is attempting a 1PC batch is not only unnecessary, but is also unsafe. I don't think it could actually cause correctness problems because a 1PC txn leaves no intents, but it opens the door to all kinds of weird issues like this.

[nvanbenschoten]

TL;DR: not a release blocker.

I take this back. As of #53132, we actually begin heartbeating before the 1PC batch in this test. This is because we acquire unreplicated locks during the initial Scan batch and so COCKROACH_TXN_HEARTBEAT_DURING_1PC isn't even applicable to the test anymore.

For the same reason we need to inform the concurrency manager of an updated txn on 1PC transactions, we'll also need to handle the case where a 1PC transaction already has a PENDING record:

cockroach/pkg/kv/kvserver/replica_write.go

Lines 485 to 498 in e8fe416

	// Even though the transaction is 1PC and hasn't written any intents, it may
	// have acquired unreplicated locks, so inform the concurrency manager that
	// it is finalized and than any unreplicated locks that it has acquired can
	// be released.
	res.Local.UpdatedTxns = []*roachpb.Transaction{clonedTxn}
	res.Local.ResolvedLocks = make([]roachpb.LockUpdate, len(etArg.LockSpans))
	for i, sp := range etArg.LockSpans {
	res.Local.ResolvedLocks[i] = roachpb.LockUpdate{
	Span: sp,
	Txn: clonedTxn.TxnMeta,
	Status: clonedTxn.Status,
	IgnoredSeqNums: clonedTxn.IgnoredSeqNums,
	}
	}

This is an important optimization that allows us to acquire unreplicated locks and then remove them during a 1PC batch. It's the only reason we perform decently well on YCSB these days.

But as mentioned above, this isn't really safe. So what we could do is perform a read for a transaction record in evaluate1PC and delete it if necessary. Or we could bail back to the non-1PC path if one exists. But I'd like to avoid adding in a new disk read on most 1PC transactions just to protect against a rare case.

So to avoid a new disk read for 1PC transactions that have not previously acquired unreplicated locks, my plan is:

1. stop using the COCKROACH_TXN_HEARTBEAT_DURING_1PC env var in this test, it's useless
2. add a new TxnHeartbeating flag to EndTxnRequest that is set by the txnHeartbeater
3. consult this flag in Replica.canAttempt1PCEvaluation. If it is set, look for a transaction record
4. if a transaction record exists, don't attempt a 1PC evaluation
5. as a bonus, gate the UpdatedTxns and ResolvedLocks handling referenced above on the TxnHeartbeating flag
   6. as a bonus in the future, avoid reading the transaction record when evaluating an EndTxn request with the TxnHeartbeating flag set to false. not safe for non-1PC batches

Luckily, this is all an optimization to avoid waiting out a transaction's expiration, so we can introduce it and backport it without a migration.

cc. @andreimatei in case you have any thoughts here.

[andreimatei]

Not attempting 1PC evaluation if we've created the txn record sounds right to me. What's the alternative? Some bastardized 1PC evaluation that also deletes the txn record? Seems weird to me.

[tbg]

SGTM as well.