teamcity: failed tests on master: test/TestRemovePlaceholderRace, testrace/TestRemovePlaceholderRace

[cockroach-teamcity]

The following tests appear to have failed:

#672303:

race: limit on 8192 simultaneously alive goroutines is exceeded, dying

[tbg]

I180522 06:41:19.809734 78650 storage/replica_raftstorage.go:520  [s1,r1/1:/M{in-ax}] generated preemptive snapshot 8b4b1248 at index 153
I180522 06:41:19.822314 78650 storage/store_snapshot.go:605  [s1,r1/1:/M{in-ax}] streamed snapshot to (n2,s2):?: kv pairs: 230, log entries: 143, rate-limit: 2.0 MiB/sec, 11ms
I180522 06:41:19.831831 80279 storage/replica_raftstorage.go:730  [s2,r1/25:{-}] applying preemptive snapshot at index 153 (id=8b4b1248, encoded size=61453, 1 rocksdb batches, 143 log entries)
I180522 06:41:20.322512 80279 storage/replica_raftstorage.go:736  [s2,r1/25:/M{in-ax}] applied preemptive snapshot in 490ms [clear=6ms batch=0ms entries=62ms commit=421ms]
I180522 06:41:20.328759 78650 storage/replica_command.go:1777  [s1,r1/1:/M{in-ax}] change replicas (ADD_REPLICA (n2,s2):26): read existing descriptor r1:/M{in-ax} [(n1,s1):1, (n3,s3):3, next=26]
W180522 06:41:20.501099 78931 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:20.621285 79051 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:20.622185 79051 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:20.762150 78665 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:20.765148 78665 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
[06:51:37] :			 [TestRemovePlaceholderRace] [Test Output]
I180522 06:41:20.954342 78931 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:20.955051 78931 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:21.075936 79051 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:21.079483 79051 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:21.218170 78665 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:21.218831 78665 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:21.409254 78931 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:21.409954 78931 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:21.535049 79051 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:21.535912 79051 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:21.672925 78665 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:21.673635 78665 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:21.864157 78931 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:21.864916 78931 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:21.989039 79051 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:21.989983 79051 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:22.127860 78665 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:22.128576 78665 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:22.317945 78931 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:22.318651 78931 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:22.443003 79051 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
W180522 06:41:22.443692 79051 storage/node_liveness.go:465  [hb] failed node liveness heartbeat: context deadline exceeded
I180522 06:41:22.582248 78665 storage/node_liveness.go:773  [hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context finished during distsender send: context deadline exceeded)
[repeat ad absurdum]

[tbg]

This looks like the test got stuck somehow with the liveness range unavailable, and goroutines piled up until the race detector killed us (unfortunately without a stack trace, though that might be for the better).

Something that's interesting here is that it's likely the heartbeat goroutines that were piling up, but they use cancellable contexts. Why don't the cancelled goroutines go away?

@nvanbenschoten do you see any connection here to #25631?

[nvb]

do you see any connection here to #25631?

yes, it looks related, but it doesn't look like liveness is actually caught in a hot loop (which is what #25631 prevents). I think all of these recent failures are fallout from the combination of #24591 and #25281. Specifically, tests are now writing to disk instead of using an in-memory env, so every liveness update now hits disk. Because of how Batch.Commit merges/serializes writes to rocksdb, I think we're seeing slow writes build up and cause a cascading effect.

One datapoint to support this is that @windchan7 said that he only saw the failure in #25430 on TeamCity. My guess is that our TeamCity machines have slow disks. We might not even be running on SSDs.

[tbg]

Don't you think these liveness failures are pretty close together though? Should we increment the liveness duration in this test?

I think the value ultimately comes from here:

	// Use shorter Raft tick settings in order to minimize start up and failover
	// time in tests.
	sc.RaftElectionTimeoutTicks = 3
	sc.RaftTickInterval = 100 * time.Millisecond

It then gets mangled through a labyrinth of computations that I think result in something like a context timeout of 33100ms/4 = 900/4ms = 250ms?

The updates seem much tighter though. This looks a lot like it would be fixed by #25631... which also merged 7 days ago, but unfortunately the failing sha here contains that PR.

[bdarnell]

250ms * 80% = 200ms, which looks like it fits (remember that there are multiple nodes here. We're not logging the node ID).

This is probably due to the move to on-disk rocksdb. I think we should revisit that decision, and add enough of a mock filesystem to in-memory environments to make that work again.

[nvb]

Closing because I strongly suspect that this was fixed by #26435.