tbg
commented
6 years ago Hmm. This is new, right @nvanbenschoten? Last I saw this we didn't have nobarrier set (?).
Closed cockroach-teamcity closed 5 years ago
tbg
commented
6 years ago Hmm. This is new, right @nvanbenschoten? Last I saw this we didn't have nobarrier set (?).
nvanbenschoten
commented
6 years ago I think we've seen this a few times recently. For instance, https://github.com/cockroachdb/cockroach/issues/30745.
It's pretty worrying, so I'm prioritizing it.
nvanbenschoten
commented
6 years ago The logs don't show a lot. Everything was moving along fine until around 12:17:13, when all three nodes started experiencing node liveness failures. These are the logs around that time on node1:
... lots of new range lease logs
I181001 12:17:12.446855 175 storage/replica_proposal.go:211 [n1,s1,r369521/1:/Table/53/1/6688{4993…-5362…}] new range lease repl=(n1,s1):1 seq=9 start=1538396226.439144511,0 epo=1 pro=1538396226.439548049,0 following repl=(n3,s3):3 seq=8 start=1538393729.489096306,0 epo=1 pro=1538393729.489097748,0
I181001 12:17:12.655041 170 storage/replica_proposal.go:211 [n1,s1,r369527/1:/Table/53/1/54386{2423…-6112…}] new range lease repl=(n1,s1):1 seq=10 start=1538396226.720070150,0 epo=1 pro=1538396226.720072218,0 following repl=(n3,s3):3 seq=9 start=1538393842.949011334,0 epo=1 pro=1538393842.949013381,0
E181001 12:17:13.015685 6712456 storage/replica_range_lease.go:301 [n1,s1,r279515/1:/Table/53/1/671{89363…-90101…}] mismatch incrementing epoch for {NodeID:3 Epoch:1 Expiration:1538396227.881482031,0 Draining:false Decommissioning:false}; actual is {NodeID:3 Epoch:1 Expiration:1538396232.380737449,0 Draining:false Decommissioning:false}
I181001 12:17:14.630589 6715838 storage/node_liveness.go:769 [n1,s1,r279515/1:/Table/53/1/671{89363…-90101…}] incremented n3 liveness epoch to 2
E181001 12:17:14.630774 6715936 storage/replica_range_lease.go:301 [n1,s1,r279580/1:/Table/53/1/5404{5716…-6453…}] mismatch incrementing epoch for {NodeID:2 Epoch:1 Expiration:1538396232.384500884,0 Draining:false Decommissioning:false}; actual is {NodeID:2 Epoch:1 Expiration:1538396241.384544493,0 Draining:false Decommissioning:false}
E181001 12:17:14.634945 6715945 storage/replica_range_lease.go:301 [n1,s1,r279574/1:/Table/53/1/6020{8760…-9498…}] mismatch incrementing epoch for {NodeID:2 Epoch:1 Expiration:1538396232.384500884,0 Draining:false Decommissioning:false}; actual is {NodeID:2 Epoch:1 Expiration:1538396241.384544493,0 Draining:false Decommissioning:false}
I181001 12:17:15.970915 226 server/status/runtime.go:465 [n1] runtime stats: 9.0 GiB RSS, 849 goroutines, 8.0 GiB/38 MiB/8.7 GiB GO alloc/idle/total, 253 MiB/310 MiB CGO alloc/total, 16810.3 CGO/sec, 296.1/4.2 %(u/s)time, 0.0 %gc (1x), 5.3 MiB/7.7 MiB (r/w)net
I181001 12:17:16.340638 112 storage/replica_proposal.go:211 [n1,s1,r369616/1:/Table/53/1/6568{1898…-2267…}] new range lease repl=(n1,s1):1 seq=9 start=1538396229.352316664,0 epo=1 pro=1538396229.352322551,0 following repl=(n3,s3):3 seq=8 start=1538394902.041204727,0 epo=1 pro=1538394902.041206466,0
W181001 12:17:17.316790 233 storage/node_liveness.go:558 [n1,hb] slow heartbeat took 2.1s
I181001 12:17:20.759340 171 storage/replica_proposal.go:211 [n1,s1,r279515/1:/Table/53/1/671{89363…-90101…}] new range lease repl=(n1,s1):1 seq=11 start=1538396233.018741631,0 epo=1 pro=1538396233.018747811,0 following repl=(n3,s3):3 seq=10 start=1538395358.690700226,0 epo=1 pro=1538395358.690702811,0
I181001 12:17:24.257944 233 storage/node_liveness.go:830 [n1,hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W181001 12:17:24.257967 233 storage/node_liveness.go:558 [n1,hb] slow heartbeat took 4.5s
W181001 12:17:24.257998 233 storage/node_liveness.go:494 [n1,hb] failed node liveness heartbeat: context deadline exceeded
W181001 12:17:24.597082 155 storage/closedts/provider/provider.go:144 [ct-closer] unable to move closed timestamp forward: not live
I181001 12:17:25.975911 226 server/status/runtime.go:465 [n1] runtime stats: 9.0 GiB RSS, 786 goroutines, 5.6 GiB/1.7 GiB/8.7 GiB GO alloc/idle/total, 261 MiB/319 MiB CGO alloc/total, 3553.7 CGO/sec, 205.8/5.3 %(u/s)time, 0.0 %gc (0x), 4.3 MiB/5.0 MiB (r/w)net
W181001 12:17:26.292736 233 storage/node_liveness.go:558 [n1,hb] slow heartbeat took 2.0s
W181001 12:17:26.292844 6717238 storage/node_liveness.go:558 [n1,s1,r279654/1:/Table/53/1/6568{0792…-1530…}] slow heartbeat took 1.5s
W181001 12:17:26.293065 6717239 storage/node_liveness.go:558 [n1,s1,r279354/1:/Table/53/1/6893{7373…-8111…}] slow heartbeat took 1.5s
W181001 12:17:27.189458 104 gossip/gossip.go:1501 [n1] first range unavailable; trying remaining resolvers
I181001 12:17:27.196781 6717299 gossip/client.go:129 [n1] started gossip client to teamcity-934753-kv-splits-nodes-3-0003:26257
I181001 12:17:28.731630 6717364 gossip/client.go:129 [n1] started gossip client to teamcity-934753-kv-splits-nodes-3-0002:26257
W181001 12:17:33.259255 233 storage/node_liveness.go:558 [n1,hb] slow heartbeat took 4.5s
W181001 12:17:33.259304 233 storage/node_liveness.go:494 [n1,hb] failed node liveness heartbeat: context deadline exceeded
I181001 12:17:35.979246 226 server/status/runtime.go:465 [n1] runtime stats: 9.0 GiB RSS, 776 goroutines, 6.6 GiB/894 MiB/8.7 GiB GO alloc/idle/total, 261 MiB/319 MiB CGO alloc/total, 3676.4 CGO/sec, 201.3/6.1 %(u/s)time, 0.0 %gc (0x), 4.2 MiB/4.4 MiB (r/w)net
W181001 12:17:37.534545 6712147 storage/intent_resolver.go:745 [n1,s1] failed to cleanup transaction intents: failed to resolve intents: the batch experienced mixed success and failure
W181001 12:17:37.760144 233 storage/node_liveness.go:558 [n1,hb] slow heartbeat took 4.5s
W181001 12:17:37.760202 233 storage/node_liveness.go:494 [n1,hb] failed node liveness heartbeat: context deadline exceeded
W181001 12:17:37.946429 6717525 storage/replica.go:3582 [n1,s1,r344398/1:/Table/1{3/1/2018…-4}] context canceled before proposing: 1 RequestLease
W181001 12:17:42.275915 233 storage/node_liveness.go:558 [n1,hb] slow heartbeat took 4.5s
W181001 12:17:42.275966 233 storage/node_liveness.go:494 [n1,hb] failed node liveness heartbeat: context deadline exceeded
I181001 12:17:44.339205 162 storage/replica_proposal.go:211 [n1,s1,r369638/1:/Table/53/1/47923{6229…-9918…}] new range lease repl=(n1,s1):1 seq=8 start=1538396231.705554528,0 epo=1 pro=1538396231.705558107,0 following repl=(n2,s2):2 seq=7 start=1538394902.205830683,0 epo=1 pro=1538394902.205832255,0
W181001 12:17:45.172442 195 storage/store.go:1651 [n1,s1,r1/1:/{Min-System/}] could not gossip first range descriptor: [NotLeaseHolderError] r1: replica (n1,s1):1 not lease holder; lease holder unknown
I181001 12:17:45.982060 226 server/status/runtime.go:465 [n1] runtime stats: 9.3 GiB RSS, 749 goroutines, 7.7 GiB/22 MiB/8.9 GiB GO alloc/idle/total, 262 MiB/319 MiB CGO alloc/total, 5135.8 CGO/sec, 284.1/9.7 %(u/s)time, 0.0 %gc (1x), 4.1 MiB/4.2 MiB (r/w)net
W181001 12:17:46.776957 233 storage/node_liveness.go:558 [n1,hb] slow heartbeat took 4.5s
W181001 12:17:46.776993 233 storage/node_liveness.go:494 [n1,hb] failed node liveness heartbeat: context deadline exceeded
W181001 12:17:51.277402 233 storage/node_liveness.go:558 [n1,hb] slow heartbeat took 4.5s
W181001 12:17:51.277434 233 storage/node_liveness.go:494 [n1,hb] failed node liveness heartbeat: context deadline exceeded
W181001 12:17:54.255791 202 storage/store_rebalancer.go:212 [n1,s1,store-rebalancer] StorePool missing descriptor for local store
I181001 12:17:54.257530 62 gossip/gossip.go:555 [n1] gossip status (stalled, 3 nodes)
gossip client (2/3 cur/max conns)
2: teamcity-934753-kv-splits-nodes-3-0003:26257 (27s: infos 66/81 sent/received, bytes 23548B/12564B sent/received)
3: teamcity-934753-kv-splits-nodes-3-0002:26257 (26s: infos 90/82 sent/received, bytes 26286B/16260B sent/received)
gossip server (0/3 cur/max conns, infos 388835/215832 sent/received, bytes 183546738B/110078836B sent/received)
gossip connectivity
n1 -> n2; n1 -> n3; n2 -> n3;
W181001 12:17:55.420554 195 storage/store.go:1651 [n1,s1,r1/1:/{Min-System/}] could not gossip first range descriptor: [NotLeaseHolderError] r1: replica (n1,s1):1 not lease holder; lease holder unknown
W181001 12:17:55.778463 233 storage/node_liveness.go:558 [n1,hb] slow heartbeat took 4.5sAfter that point, all three nodes began having serious trouble with their liveness updates which persists for the rest of the test:
W181001 12:18:07.495467 6717420 storage/node_liveness.go:558 [n1,s1,r279203/1:/Table/53/1/6421{1696…-2434…}] slow heartbeat took 34.7s
E181001 12:18:07.495479 6717420 storage/replica_range_lease.go:287 [n1,s1,r279203/1:/Table/53/1/6421{1696…-2434…}] heartbeat failed on epoch increment
W181001 12:18:07.495616 6717421 storage/node_liveness.go:558 [n1,s1,r279134/1:/Table/53/1/64220{1819…-9197…}] slow heartbeat took 34.6s
E181001 12:18:07.495624 6717421 storage/replica_range_lease.go:287 [n1,s1,r279134/1:/Table/53/1/64220{1819…-9197…}] heartbeat failed on epoch increment
W181001 12:18:07.495754 6717383 storage/node_liveness.go:558 [n1,s1,r279532/1:/Table/53/1/629{19320…-20057…}] slow heartbeat took 34.6s
E181001 12:18:07.495765 6717383 storage/replica_range_lease.go:287 [n1,s1,r279532/1:/Table/53/1/629{19320…-20057…}] heartbeat failed on epoch incrementThe interesting thing we see in those logs is that gossip appears to have issues at the same time that node liveness grinds to a halt.
One thing that catches my eye is that all three nodes log first range unavailable; trying remaining resolvers at the same time and then get stuck logging first range unavailable; resolvers exhausted for the rest of the test. @petermattis do you know anything about this? What does it mean for gossip to be stalled, and what effects do we expect this to have on a cluster?
petermattis
commented
6 years ago Gossip is stalled (for logging purposes) if a node does not have the sentinel key. The sentinel key now expires quite rapidly so that a gossip partition will be repaired quickly. I'm not familiar with that first range unavailable message. Looking right now, it seems to be indicating that the sentinel key is not present and has nothing to do with the first range. The sentinel key is gossiped by the leaseholder of the first range, so the log message might be a historic artifact. If there is no leaseholder for the first range I can imagine all of the nodes simultaneously deciding the gossip is stalled.
nvanbenschoten
commented
6 years ago Got it, thanks for the explanation.
I was just able to reproduce this after stressing it on three clusters for a few hours, so it's not terribly rare.
nvanbenschoten
commented
6 years ago The split attempts are all stuck on:
github.com/cockroachdb/cockroach/pkg/storage/idalloc.(*Allocator).Allocate(0xc4204b84d0, 0x3094bc0, 0xc4febbbbc0, 0x3094bc0, 0xc4febbbbc0, 0x100)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/idalloc/id_alloc.go:87 +0x129
github.com/cockroachdb/cockroach/pkg/storage.(*Store).NewRangeDescriptor(0xc4202a5b80, 0x3094bc0, 0xc4febbbbc0, 0xc5373bd6a0, 0xb, 0x10, 0xc514c5d050, 0xb, 0x10, 0xc534f6d410, ...)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:2318 +0x4a
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).adminSplitWithDescriptor(0xc49ba95500, 0x3094bc0, 0xc4febbbbc0, 0xc5373bd680, 0xb, 0x10, 0x0, 0x0, 0x0, 0x0, ...)Which is waiting on idalloc/id_alloc.go:112.
nvanbenschoten
commented
6 years ago The idalloc.Allocator's block allocation is stuck in the command queue on r4. I can see logs like:
I181002 02:21:41.329185 2669993 storage/replica.go:2370 [n2,s2,r4/3:/System/{NodeLive…-tsd}] waiting for 1 overlapping requests: {write/global: [1 Inc]}so one of the increments must be stuck beneath the command queue.
r4 contains the key range [/System/NodeLivenessMax, /System/tsd) and currently has an invalid lease. The range starts after the expiration-based lease cut-off because its start key is not less than /System/NodeLivenessMax, so it is presumably trying to acquire an epoch-based lease, which requires a healthy liveness range.
nvanbenschoten
commented
6 years ago n2 (the leaseholder of r4) just crashed with an OOM error after I poked it a little too agressively with logspy. Hopefully there's some more we can learn from its heap dumps.
nvanbenschoten
commented
6 years ago As suspected, the lease request to acquire the lease for r4 was stuck at https://github.com/cockroachdb/cockroach/blob/0f5a289d49105cd317a2713b71546d84c25547f6/pkg/storage/replica_range_lease.go#L290
nvanbenschoten
commented
6 years ago The memory blowup was in the statusServer. It had some call to JSONPb.Marshal. I'm going to assume that I caused that by poking at the admin ui.
nvanbenschoten
commented
6 years ago I traced the requestLeaseAsync's call into (*NodeLiveness).Heartbeat and up to beginCmds. Luckily it looks like the NodeLiveness range is also on n2. This gave me the following stack-frame:
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).beginCmds(0xc42022e300, 0x3094bc0, 0xc551eed350, 0xc5ec037b80, 0xc4bee6aba0, 0xb, 0x10, 0xc425355320)The first argument here is the NodeLiveness Replica's memory address.
Searching for other stack frames with this argument reveals that NodeLiveness itself is struggling to acquire a lease (this time, expiration-based). At least one tryExecuteWriteBatch call on the range is blocked in redirectOnOrAcquireLease.
I also see a call to getLeaseForGossip, which is stuck in the same place. That call is starting from https://github.com/cockroachdb/cockroach/blob/0f5a289d49105cd317a2713b71546d84c25547f6/pkg/storage/store.go#L1624-L1629
nvanbenschoten
commented
6 years ago Aha! I also see the stuck NodeLiveness lease request, which has been waiting on Raft for 6 mintues:
goroutine 2672554 [select, 6 minutes]:
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).tryExecuteWriteBatch(0xc42022e300, 0x3094b00, 0xc76b15a600, 0x1559a98647992a2f, 0x0, 0x0, 0x0, 0x3, 0x0, 0x0, ...)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:3258 +0x961
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).executeWriteBatch(0xc42022e300, 0x3094b00, 0xc76b15a600, 0x1559a98647992a2f, 0x0, 0x0, 0x0, 0x3, 0x0, 0x0, ...)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:3075 +0xab
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).sendWithRangeID(0xc42022e300, 0x3094b00, 0xc76b15a600, 0x3, 0x1559a98647992a2f, 0x0, 0x0, 0x0, 0x3, 0x0, ...)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:2024 +0x6f3
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).Send(0xc42022e300, 0x3094b00, 0xc76b15a600, 0x1559a98647992a2f, 0x0, 0x0, 0x0, 0x3, 0x0, 0x0, ...)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:1972 +0x90
github.com/cockroachdb/cockroach/pkg/storage.(*pendingLeaseRequest).requestLeaseAsync.func2(0x3094b00, 0xc76b15a600)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_range_lease.go:321 +0x5c1So why is this stuck?
nvanbenschoten
commented
6 years ago I think I'm going to need another live reproduction for this. I did find some interesting logs on n2 though:
W181002 02:25:38.275112 177 storage/replica.go:1553 [n2,s2,r3/2:/System/NodeLiveness{-Max}] have been waiting 1m0s attempting to acquire lease
W181002 02:25:38.275167 2671869 storage/replica.go:3282 [n2,s2,r3/2:/System/NodeLiveness{-Max}] have been waiting 1m0s for proposing command RequestLease [/System/NodeLiveness,/Min)
I181002 02:25:41.846915 2671869 storage/replica.go:3291 [n2,s2,r3/2:/System/NodeLiveness{-Max}] slow command RequestLease [/System/NodeLiveness,/Min) finished after 1m3.604019832s
I181002 02:25:41.847052 177 storage/replica.go:1558 [n2,s2,r3/2:/System/NodeLiveness{-Max}] slow lease acquisition finished after 1m3.604430509s with error [NotLeaseHolderError] r3: replica (n2,s2):2 not lease holder; lease holder unknown after 1 attempts
W181002 02:25:41.847083 177 storage/store.go:1651 [n2,s2,r3/2:/System/NodeLiveness{-Max}] could not gossip node liveness: [NotLeaseHolderError] r3: replica (n2,s2):2 not lease holder; lease holder unknown
W181002 02:28:19.422663 2672554 storage/replica.go:3282 [n2,s2,r3/2:/System/NodeLiveness{-Max}] have been waiting 1m0s for proposing command RequestLease [/System/NodeLiveness,/Min)
W181002 02:28:47.277546 177 storage/replica.go:1553 [n2,s2,r3/2:/System/NodeLiveness{-Max}] have been waiting 1m0s attempting to acquire leaseI was able to reproduce this again and tracked the issue up to problems with lease acquisition in r1.
All three replicas have pending commands and keep logging I181002 05:37:52.204846 151 storage/replica.go:4628 [n2,s2,r1/3:/M{in-eta2/Table/…}] not quiescing: 1 pending commands.
All three replicas also keep proposing a command with 1 RequestLease.
The interesting thing is that I see leases continually getting rejected with errors like:
I181002 05:37:52.216711 151 storage/replica.go:5205 [n2,s2,r1/3:/M{in-eta2/Table/…}] command proposed from replica (n1,s1):1 with lease #3 incompatible to repl=(n2,s2):3 seq=3 start=1538448219.495057052,0 exp=1538458659.106336434,0 pro=1538458650.106341768,0
I181002 05:37:52.216740 151 storage/replica.go:5345 [n2,s2,r1/3:/M{in-eta2/Table/…}] applying command with forced error: cannot replace lease repl=(n2,s2):3 seq=3 start=1538448219.495057052,0 exp=1538458659.106336434,0 pro=1538458650.106341768,0 with repl=(n1,s1):1 seq=4 start=1538458625.064248657,1 exp=1538458647.320924838,0 pro=1538458638.320939183,0: proposed under invalid leaseand
I181002 05:38:01.506964 49 storage/replica.go:5205 [n2,s2,r1/3:/M{in-eta2/Table/…}] command proposed from replica (n3,s3):2 with lease #3 incompatible to repl=(n2,s2):3 seq=3 start=1538448219.495057052,0 exp=1538458659.106336434,0 pro=1538458650.106341768,0
I181002 05:38:01.506993 49 storage/replica.go:5345 [n2,s2,r1/3:/M{in-eta2/Table/…}] applying command with forced error: cannot replace lease repl=(n2,s2):3 seq=3 start=1538448219.495057052,0 exp=1538458659.106336434,0 pro=1538458650.106341768,0 with repl=(n3,s3):2 seq=4 start=1538458640.984601682,1 exp=1538458664.287062629,0 pro=1538458655.287069407,0: proposed under invalid leaseI'm starting to see a lot of similarities between this issue and #30064. I think there's actually a good chance they're the same. What do you think @tschottdorf?
From what I can tell, this must be running into the check added in 5c7b7705f90a17469c71dada2d2dc155bac92978. That's the only way for leaseMismatch to be true when the proposer lease and the current lease have seq num 3 and the proposed lease has seq num 4. This check should only protect against concurrent lease extensions, it should fire indefinitely, so something seems off with that.
I'm also confused where the RequestLease proposal from n2 is going. It certainly shouldn't have the wrong previous lease proposal ts since n2 was the owner of the previous lease. Perhaps two different things are going wrong and only their combination causes this full stall.
nvanbenschoten
commented
6 years ago Never mind, I actually do see n2's lease extension get applied:
exp=1538460769.440352196,0 pro=1538460760.440376406,0 following repl=(n2,s2):3 seq=3 start=1538448219.495057052,0 exp=1538460762.688870621,0 pro=1538460753.688877340,0
I181002 06:13:11.121996 158 storage/replica.go:6623 [n2,s2,r1/3:/M{in-eta2/Table/…}] not gossiping system config because the replica doesn't contain the system config's start keyBut new lease requests are proposed on all three replicas immediately afterwards.
nvanbenschoten
commented
6 years ago Perhaps the proposal was so slow that the lease is expired by the time it's applied.
tbg
commented
6 years ago I'm looking at logspy to confirm this right now, but I get the impression that you're right and that these lease errors are a red herring. n2 holds the lease steadily and n1s and n3s proposals always seem to be proposed under a past incarnation of n2s lease. The real question is why it takes so long to get through a Raft cycle.
tbg
commented
6 years ago For example, logspying via
we can see the following two lease extensions (note how the proposed_ts of the first matches the proposed ts of the prev_lease of the second line):
cockroach-teamcity
SHA: https://github.com/cockroachdb/cockroach/commits/4e80b4a591764fa75c43b3cb29f384e1c9842a49
Parameters:
To repro, try:
Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=934753&tab=buildLog