Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

storage: compactions and consistency checks queued over more than a week #21824

Closed
mrtracy opened this issue Jan 26, 2018 · 27 comments · Fixed by #26039
Closed

storage: compactions and consistency checks queued over more than a week #21824

mrtracy opened this issue Jan 26, 2018 · 27 comments · Fixed by #26039
Assignees
Labels
A-kv-distribution Relating to rebalancing and leasing. S-2-temp-unavailability Temp crashes or other availability problems. Can be worked around or resolved by restarting.
Milestone

Comments

@mrtracy
Copy link
Contributor

mrtracy commented Jan 26, 2018

Reported by forums user leokwan:
https://forum.cockroachlabs.com/t/upgrade-to-v2-0-alpha-20180122/1312

"
I’ve a 5 nodes idle cluster running v2.0-alpha.20171218. I shut down all nodes, and do a upgrade to v2.0-alpha.20180122. The upgrade seems to be success; however, the Consistency Checker Queue keeps growing

ccq

And then I may see some nodes become dead on the overview page, but it will come back to normal after a few minutes. However, it will become dead again later.

I check the log on the server, I may see some warnings like this for all nodes

W180126 16:52:57.404974 734198 kv/dist_sender.go:1261 [ts-poll,n1] have been waiting 1m0s sending RPC to r9005 (currently pending: [(n5,s5):3]) for batch: Merge [/System/tsd/cr.store.tscache.skl.write.rotations/1/10s/2018-01-26T16:00:00Z,/Min) 
W180126 16:52:57.405259 228 kv/dist_sender.go:1261 [ts-poll,n1] have been waiting 1m0s sending RPC to r21 (currently pending: [(n3,s3):8]) for batch: Merge [/System/tsd/cr.store.valcount/1/10s/2018-01-26T16:00:00Z,/Min) 
W180126 16:52:57.405306 734199 kv/dist_sender.go:1261 [ts-poll,n1] have been waiting 1m0s sending RPC to r3434 (currently pending: [(n1,s1):4]) for batch: Merge [/System/tsd/cr.store.valbytes/1/10s/2018-01-26T16:00:00Z,/Min) 
W180126 16:53:00.329842 249 storage/node_liveness.go:426 [n1,hb] slow heartbeat took 4.5s 
W180126 16:53:00.329860 249 storage/node_liveness.go:365 [n1,hb] failed node liveness heartbeat: context deadline exceeded
W180126 16:53:00.812591 735175 storage/node_liveness.go:426 [n1,s1,r1028/7:/System/tsd/cr.node.sql.…] slow heartbeat took 6.2s
W180126 16:53:00.812967 735177 storage/node_liveness.go:426 [n1,s1,r344/1:/System/tsd/cr.node.sql.mem.a…] slow heartbeat took 6.2s
W180126 16:53:00.813158 735148 storage/node_liveness.go:426 [n1,s1,r9218/6:/System/tsd/cr.node.sql.mem.a…] slow heartbeat took 6.2s
W180126 16:53:00.813452 735179 storage/node_liveness.go:426 [n1,s1,r72/1:/System/tsd/cr.node.sql.exec.…] slow heartbeat took 6.2s
W180126 16:53:00.813757 735234 storage/node_liveness.go:426 [n1,s1,r1544/6:/System/tsd/cr.node.distsende…] slow heartbeat took 6.2s
W180126 16:53:00.813939 735194 storage/node_liveness.go:426 [n1,s1,r9260/4:/System/tsd/cr.node.sql.dists…] slow heartbeat took 6.2s
W180126 16:53:00.814265 735225 storage/node_liveness.go:426 [n1,s1,r9303/1:/System/tsd/cr.node.sql.exec.…] slow heartbeat took 6.2s
W180126 16:53:00.814507 735238 storage/node_liveness.go:426 [n1,s1,r9025/1:/System/tsd/cr.node.sql.exec.…] slow heartbeat took 6.2s
W180126 16:53:00.814718 735227 storage/node_liveness.go:426 [n1,s1,r9457/4:/System/tsd/cr.node.{di…-ex…}] slow heartbeat took 6.2s
W180126 16:53:00.815050 735100 storage/node_liveness.go:426 [n1,s1,r231/7:/System/tsd/cr.node.sql.mem.a…] slow heartbeat took 6.2s
W180126 16:53:00.815257 735230 storage/node_liveness.go:426 [n1,s1,r3369/1:/System/tsd/cr.node.gossip.…] slow heartbeat took 6.2s
W180126 16:53:00.815521 735243 storage/node_liveness.go:426 [n1,s1,r206/1:/System/tsd/cr.node.gossip.co…] slow heartbeat took 6.2s
W180126 16:53:00.815807 735245 storage/node_liveness.go:426 [n1,s1,r9038/1:/System/tsd/cr.node.round-tri…] slow heartbeat took 6.2s
W180126 16:53:00.816024 735251 storage/node_liveness.go:426 [n1,s1,r3486/1:/System/tsd/cr.node.round-tri…] slow heartbeat took 6.2s
W180126 16:53:00.816294 735104 storage/node_liveness.go:426 [n1,s1,r6147/1:/System/tsd/cr.node.gossip.in…] slow heartbeat took 6.2s
W180126 16:53:00.816585 735253 storage/node_liveness.go:426 [n1,s1,r7446/1:/System/tsd/cr.node.sql.mem.c…] slow heartbeat took 6.2s
W180126 16:53:00.816798 735267 storage/node_liveness.go:426 [n1,s1,r9096/1:/System/tsd/cr.node.sql.dists…] slow heartbeat took 6.2s
W180126 16:53:00.817008 735269 storage/node_liveness.go:426 [n1,s1,r9092/1:/System/tsd/cr.node.sql.mem.c…] slow heartbeat took 6.2s
W180126 16:53:00.817234 735271 storage/node_liveness.go:426 [n1,s1,r204/1:/System/tsd/cr.node.sql.mem.c…] slow heartbeat took 6.2s
I180126 16:53:00.817613 174 storage/replica_proposal.go:196 [n1,s1,r1028/7:/System/tsd/cr.node.sql.…] new range lease repl=(n1,s1):7 seq=0 start=1516977068.248659932,5 epo=126 pro=1516985574.658469514,0 following repl=(n1,s1):7 seq=0 start=1516977068.248659932,5 epo=126 pro=1516984961.125563733,0

From dstat, all nodes have read/write actions constantly , and it looks like one of the CPU thread would keep busy.

fe78b491aad8c59c6fe3d15f71cd8c21f32de626

The cluster become very unstable. I then downgrade to v2.0-alpha.20171218, the Consistency Checker Queue eventually clear and the cluster looks to be back to normal.

Leo
"

@mrtracy mrtracy assigned mrtracy and tbg and unassigned mrtracy Jan 26, 2018
@leomkkwan
Copy link

The full log for a node is attached.

n1.log

@tbg
Copy link
Member

tbg commented Jan 26, 2018

Could you check the Queue Processing Times graph? That there are many replicas due for consistency checking may not mean that that queue in particular has a problem (but if you see that there is a lot of time in that graph processing, then it might be).

@leomkkwan
Copy link

leomkkwan commented Jan 26, 2018

1
2

I did the upgrade between 1400 and 1500. Killed the server around 1730, and roll back to previous version around 19:00

Thanks.

@leomkkwan
Copy link

n3

@tbg tbg changed the title storage: Excessive work in consistency checker queue storage: failed heartbeats after upgrade Jan 26, 2018
@tbg
Copy link
Member

tbg commented Jan 26, 2018

Leo, could you send us the logs for the other nodes as well?

@leomkkwan
Copy link

Sure.

n2.log
n3.log
n5.log
n4.log

@tbg
Copy link
Member

tbg commented Feb 8, 2018

Thanks @leomkkwan. The logs look uninteresting (heartbeats timing out after 16:36, but no more information) with the exception of n4.log (see below). What this tells me is that that node exhibited I/O problems but it doesn't explain why.

@a-robinson I'm assigning you since I'm not going to be able to look at this too soon and you might have an idea. (I don't see any replicaGC in the logs or I would have suspected the compaction queue).

$ grep -E 'commit took|r3/' n*.log
n1 (1).log:I180126 16:42:18.164210 213 storage/replica_raftstorage.go:540  [raftsnapshot,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated Raft snapshot c5496ba4 at index 3536255
n1 (1).log:I180126 16:42:18.173126 213 storage/store.go:3670  [raftsnapshot,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n4,s4):4: kv pairs: 2149, log entries: 37, rate-limit: 8.0 MiB/sec, 9ms
n1.log:I180126 16:42:18.164210 213 storage/replica_raftstorage.go:540  [raftsnapshot,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated Raft snapshot c5496ba4 at index 3536255
n1.log:I180126 16:42:18.173126 213 storage/store.go:3670  [raftsnapshot,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n4,s4):4: kv pairs: 2149, log entries: 37, rate-limit: 8.0 MiB/sec, 9ms
n4.log:W180126 16:36:59.983641 267 storage/engine/rocksdb.go:1704  batch [28/5095/0] commit took 785.295788ms (>500ms):
n4.log:W180126 16:37:04.455870 663549 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 8811ba64], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:37:05.545778 663583 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 585faefb], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:37:06.324934 663531 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 769f1bb9], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:37:06.872112 663560 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 67dd76c3], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
n4.log:W180126 16:37:09.310998 242 storage/engine/rocksdb.go:1704  batch [30/3501/0] commit took 505.664801ms (>500ms):
n4.log:W180126 16:37:10.344701 254 storage/engine/rocksdb.go:1704  batch [45/7634/0] commit took 976.648057ms (>500ms):
n4.log:W180126 16:37:11.384449 246 storage/engine/rocksdb.go:1704  batch [46/10339/0] commit took 917.362453ms (>500ms):
n4.log:W180126 16:37:13.455854 664331 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 916c3522], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:37:13.951329 282 storage/engine/rocksdb.go:1704  batch [94/12186/0] commit took 998.737815ms (>500ms):
n4.log:W180126 16:37:14.545988 664332 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 5abe88d3], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:37:15.324903 664483 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 1e6a8e68], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:37:15.865954 243 storage/engine/rocksdb.go:1704  batch [238/46613/0] commit took 535.774622ms (>500ms):
n4.log:W180126 16:37:15.872083 664484 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 2f4208e9], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
n4.log:W180126 16:37:16.574680 664334 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: b8e2fd52], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:37:16.786278 244 storage/engine/rocksdb.go:1704  batch [92/14384/0] commit took 919.948822ms (>500ms):
n4.log:W180126 16:37:17.956601 663615 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 15d8e19c], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:37:18.236488 247 storage/engine/rocksdb.go:1704  batch [169/25235/0] commit took 551.450385ms (>500ms):
n4.log:W180126 16:37:19.046455 663617 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: 6b8a4e5e], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:37:19.443554 247 storage/engine/rocksdb.go:1704  batch [167/18507/0] commit took 707.420703ms (>500ms):
n4.log:W180126 16:37:20.741695 226 storage/engine/rocksdb.go:1704  batch [131/19813/0] commit took 589.564371ms (>500ms):
n4.log:W180126 16:37:21.075266 664472 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: ceef360c], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:37:22.080290 241 storage/engine/rocksdb.go:1704  batch [78/8319/0] commit took 847.571926ms (>500ms):
n4.log:W180126 16:37:22.457933 664502 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: a59474ab], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:37:23.450463 276 storage/engine/rocksdb.go:1704  batch [97/16247/0] commit took 546.104517ms (>500ms):
n4.log:W180126 16:37:23.546914 664473 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 3f067c5b], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:37:24.614547 234 storage/engine/rocksdb.go:1704  batch [100/9913/0] commit took 762.121023ms (>500ms):
n4.log:W180126 16:37:25.472915 258 storage/engine/rocksdb.go:1704  batch [375/17052/0] commit took 550.879666ms (>500ms):
n4.log:W180126 16:37:25.575737 664427 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: fac7c328], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:37:26.000312 260 storage/engine/rocksdb.go:1704  batch [138/11290/0] commit took 526.911228ms (>500ms):
n4.log:W180126 16:37:26.958369 664445 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 2175ee6d], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:37:28.047457 664461 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: cac253e1], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:37:29.894434 231 storage/engine/rocksdb.go:1704  batch [4/342/0] commit took 1.539613493s (>500ms):
n4.log:W180126 16:37:30.076208 664491 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: a6da7367], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:37:30.608619 231 storage/engine/rocksdb.go:1704  batch [18/1614/0] commit took 699.54102ms (>500ms):
n4.log:W180126 16:37:31.383474 226 storage/engine/rocksdb.go:1704  batch [5/451/0] commit took 710.411181ms (>500ms):
n4.log:W180126 16:37:31.458822 664475 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: a24878f8], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:37:31.927913 283 storage/engine/rocksdb.go:1704  batch [4/349/0] commit took 525.385392ms (>500ms):
n4.log:W180126 16:37:32.444421 269 storage/engine/rocksdb.go:1704  batch [4/352/0] commit took 501.775487ms (>500ms):
n4.log:W180126 16:37:32.548136 664536 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: c22ad610], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:37:33.404049 260 storage/engine/rocksdb.go:1704  batch [20/6305/0] commit took 730.81275ms (>500ms):
n4.log:W180126 16:37:34.521869 260 storage/engine/rocksdb.go:1704  batch [27/2039/0] commit took 873.574807ms (>500ms):
n4.log:W180126 16:37:34.576610 664448 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 9e62bfb2], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:37:35.661035 285 storage/engine/rocksdb.go:1704  batch [12/914/0] commit took 1.058660351s (>500ms):
n4.log:W180126 16:37:37.847107 260 storage/engine/rocksdb.go:1704  batch [4/322/0] commit took 912.391305ms (>500ms):
n4.log:W180126 16:37:42.636563 266 storage/engine/rocksdb.go:1704  batch [73/20124/0] commit took 3.712927699s (>500ms):
n4.log:W180126 16:37:43.849132 255 storage/engine/rocksdb.go:1704  batch [216/41220/0] commit took 1.212335542s (>500ms):
n4.log:W180126 16:37:46.333129 271 storage/engine/rocksdb.go:1704  batch [58/9742/0] commit took 2.481977095s (>500ms):
n4.log:W180126 16:37:46.930611 261 storage/engine/rocksdb.go:1704  batch [270/63450/0] commit took 595.868534ms (>500ms):
n4.log:W180126 16:37:49.456279 666006 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: ab3bce64], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:37:50.804395 235 storage/engine/rocksdb.go:1704  batch [67/11448/0] commit took 3.873219094s (>500ms):
n4.log:W180126 16:37:51.325496 666050 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 597ac599], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:37:51.505173 272 storage/engine/rocksdb.go:1704  batch [240/40512/0] commit took 700.492547ms (>500ms):
n4.log:W180126 16:37:51.872603 665854 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 798ee1b6], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
n4.log:W180126 16:37:53.956925 666039 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: 28328f32], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:37:53.982932 235 storage/engine/rocksdb.go:1704  batch [93/7918/0] commit took 2.477110217s (>500ms):
n4.log:W180126 16:37:55.046339 666067 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: a58d667c], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:37:55.450503 274 storage/engine/rocksdb.go:1704  batch [99/8668/0] commit took 982.461121ms (>500ms):
n4.log:W180126 16:37:55.827300 666082 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: 8b32cdd4], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:37:55.981692 251 storage/engine/rocksdb.go:1704  batch [192/16766/0] commit took 530.867175ms (>500ms):
n4.log:W180126 16:37:57.007642 271 storage/engine/rocksdb.go:1704  batch [101/8856/0] commit took 1.024299702s (>500ms):
n4.log:W180126 16:37:57.008345 666021 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 17.9s of attempting command [txn: 7f795afb], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:37:57.008543 665981 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 16.6s of attempting command [txn: 49c508ab], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:37:57.008730 665951 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 14.7s of attempting command [txn: ae9d0820], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:37:57.008875 666035 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 14.1s of attempting command [txn: a50bd228], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
n4.log:W180126 16:37:57.008980 666038 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 11.0s of attempting command [txn: f87eef34], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:37:57.550590 280 storage/engine/rocksdb.go:1704  batch [193/18402/0] commit took 542.46447ms (>500ms):
n4.log:W180126 16:37:58.457461 666085 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: a4488bcd], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:37:58.675126 250 storage/engine/rocksdb.go:1704  batch [115/16783/0] commit took 1.124042051s (>500ms):
n4.log:W180126 16:37:59.546855 666052 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: e6cf8976], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:37:59.701493 270 storage/engine/rocksdb.go:1704  batch [208/30426/0] commit took 1.025967305s (>500ms):
n4.log:W180126 16:38:00.326975 666086 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: 9b311027], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:01.508853 666055 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 5f87c2a5], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:38:01.560119 262 storage/engine/rocksdb.go:1704  batch [116/24722/0] commit took 1.858288354s (>500ms):
n4.log:W180126 16:38:02.957915 666108 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: ab4892b5], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:38:03.074106 269 storage/engine/rocksdb.go:1704  batch [211/28343/0] commit took 1.512100834s (>500ms):
n4.log:W180126 16:38:04.067874 666071 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 07a527d7], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:38:04.804928 244 storage/engine/rocksdb.go:1704  batch [91/18189/0] commit took 1.73050301s (>500ms):
n4.log:W180126 16:38:04.827648 666112 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 181d3647], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:05.916803 265 storage/engine/rocksdb.go:1704  batch [219/45865/0] commit took 1.111410246s (>500ms):
n4.log:W180126 16:38:06.009311 666119 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 763a270e], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:38:08.717721 249 storage/engine/rocksdb.go:1704  batch [79/6744/0] commit took 2.800397063s (>500ms):
n4.log:W180126 16:38:09.327908 666046 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: f3c27a83], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:10.336564 228 storage/engine/rocksdb.go:1704  batch [86/7425/0] commit took 1.202529742s (>500ms):
n4.log:W180126 16:38:10.509746 666126 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 65d0809b], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:38:12.082939 273 storage/engine/rocksdb.go:1704  batch [64/5940/0] commit took 1.289930042s (>500ms):
n4.log:W180126 16:38:13.689152 256 storage/engine/rocksdb.go:1704  batch [64/5936/0] commit took 1.242128065s (>500ms):
n4.log:W180126 16:38:13.828928 666013 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: 510dce68], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:15.796276 286 storage/engine/rocksdb.go:1704  batch [60/8188/0] commit took 1.742932381s (>500ms):
n4.log:W180126 16:38:16.297971 254 storage/engine/rocksdb.go:1704  batch [202/30285/0] commit took 501.263528ms (>500ms):
n4.log:W180126 16:38:18.147183 249 storage/engine/rocksdb.go:1704  batch [61/14544/0] commit took 1.848936598s (>500ms):
n4.log:W180126 16:38:18.328890 666132 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: cf3ef847], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:19.036105 254 storage/engine/rocksdb.go:1704  batch [169/17310/0] commit took 888.558691ms (>500ms):
n4.log:W180126 16:38:20.093758 245 storage/engine/rocksdb.go:1704  batch [42/3201/0] commit took 1.057133877s (>500ms):
n4.log:W180126 16:38:21.705855 266 storage/engine/rocksdb.go:1704  batch [45/3950/0] commit took 1.414410647s (>500ms):
n4.log:W180126 16:38:22.829760 666135 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 18464695], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:23.569951 268 storage/engine/rocksdb.go:1704  batch [49/4296/0] commit took 1.620317861s (>500ms):
n4.log:W180126 16:38:25.191600 273 storage/engine/rocksdb.go:1704  batch [256/13904/0] commit took 1.356531261s (>500ms):
n4.log:W180126 16:38:26.042030 287 storage/engine/rocksdb.go:1704  batch [109/9824/0] commit took 850.136164ms (>500ms):
n4.log:W180126 16:38:26.642852 260 storage/engine/rocksdb.go:1704  batch [104/9227/0] commit took 600.324133ms (>500ms):
n4.log:W180126 16:38:27.207210 231 storage/engine/rocksdb.go:1704  batch [61/5326/0] commit took 563.983257ms (>500ms):
n4.log:W180126 16:38:27.330252 666216 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 2bc9b137], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:28.778781 275 storage/engine/rocksdb.go:1704  batch [7/522/0] commit took 599.274892ms (>500ms):
n4.log:W180126 16:38:30.375688 250 storage/engine/rocksdb.go:1704  batch [22/1141/0] commit took 1.562914826s (>500ms):
n4.log:W180126 16:38:31.306844 280 storage/engine/rocksdb.go:1704  batch [4/307/0] commit took 541.153114ms (>500ms):
n4.log:W180126 16:38:31.830829 666231 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: f0f13cf5], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:32.143927 294 storage/store.go:1404  [n4,s4,r3/4:/System/NodeLiveness{-Max}] could not gossip node liveness: [NotLeaseHolderError] r3: replica (n4,s4):4 not lease holder; lease holder unknown
n4.log:W180126 16:38:36.985504 230 storage/engine/rocksdb.go:1704  batch [2/374/0] commit took 1.203631365s (>500ms):
n4.log:W180126 16:38:38.332495 230 storage/engine/rocksdb.go:1704  batch [7/403/0] commit took 1.073203005s (>500ms):
n4.log:W180126 16:38:39.281666 273 storage/engine/rocksdb.go:1704  batch [4/322/0] commit took 540.815456ms (>500ms):
n4.log:W180126 16:38:42.832771 666584 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 93efe6d9], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:38:43.455861 666598 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 5f1404b9], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:38:45.930007 273 storage/engine/rocksdb.go:1704  batch [5/760/0] commit took 6.626910042s (>500ms):
n4.log:W180126 16:38:47.263919 273 storage/engine/rocksdb.go:1704  batch [21/3048/0] commit took 821.617337ms (>500ms):
n4.log:W180126 16:38:47.956404 666645 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: bc8e4830], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:38:49.046305 666630 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: a2419fbc], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:38:49.825438 666545 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 8dac6a85], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:50.372731 666632 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 320e044f], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
n4.log:W180126 16:38:52.457051 666606 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 3d3a4959], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:38:53.546899 666636 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 1550c213], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:38:53.946251 273 storage/engine/rocksdb.go:1704  batch [19/1275/0] commit took 6.494761816s (>500ms):
n4.log:W180126 16:38:53.946688 666496 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 13.9s of attempting command [txn: 857fbded], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:38:53.946861 666574 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 13.1s of attempting command [txn: 3d6e3aae], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:53.946994 666575 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 12.6s of attempting command [txn: 308824ee], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
n4.log:W180126 16:38:54.326109 666615 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 8b15ca01], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:54.772697 232 storage/engine/rocksdb.go:1704  batch [18/2413/0] commit took 747.284809ms (>500ms):
n4.log:W180126 16:38:56.162366 269 storage/engine/rocksdb.go:1704  batch [22/1623/0] commit took 1.240129811s (>500ms):
n4.log:W180126 16:38:56.957800 666620 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: d5ae146e], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:38:57.531971 273 storage/engine/rocksdb.go:1704  batch [18/1591/0] commit took 1.267748911s (>500ms):
n4.log:W180126 16:38:58.047438 666662 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: ee75eb2b], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:38:58.826632 666624 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 6f0b1ff8], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:38:58.895783 273 storage/engine/rocksdb.go:1704  batch [23/2228/0] commit took 1.263758285s (>500ms):
n4.log:W180126 16:39:00.315319 244 storage/engine/rocksdb.go:1704  batch [44/3782/0] commit took 1.281350388s (>500ms):
n4.log:W180126 16:39:01.446047 273 storage/engine/rocksdb.go:1704  batch [16/826/0] commit took 897.691387ms (>500ms):
n4.log:W180126 16:39:01.458378 666650 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: b0646c3b], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:39:02.548125 666654 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 82210c24], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:39:02.578143 256 storage/engine/rocksdb.go:1704  batch [3/237/0] commit took 676.702164ms (>500ms):
n4.log:W180126 16:39:03.638291 273 storage/engine/rocksdb.go:1704  batch [58/18503/0] commit took 794.460255ms (>500ms):
n4.log:W180126 16:39:04.769423 260 storage/engine/rocksdb.go:1704  batch [148/47520/0] commit took 1.130828656s (>500ms):
n4.log:W180126 16:39:07.674235 273 storage/engine/rocksdb.go:1704  batch [43/4837/0] commit took 2.904641459s (>500ms):
n4.log:W180126 16:39:09.349285 253 storage/engine/rocksdb.go:1704  batch [96/18216/0] commit took 1.023340812s (>500ms):
n4.log:W180126 16:39:10.465280 265 storage/engine/rocksdb.go:1704  batch [199/48676/0] commit took 1.115629811s (>500ms):
n4.log:W180126 16:39:13.437714 252 storage/engine/rocksdb.go:1704  batch [149/37114/0] commit took 2.972117827s (>500ms):
n4.log:W180126 16:39:15.704565 265 storage/engine/rocksdb.go:1704  batch [165/16554/0] commit took 2.266494173s (>500ms):
n4.log:W180126 16:39:16.720022 259 storage/engine/rocksdb.go:1704  batch [118/9549/0] commit took 1.014948597s (>500ms):
n4.log:W180126 16:39:17.304088 285 storage/engine/rocksdb.go:1704  batch [167/14449/0] commit took 583.734086ms (>500ms):
n4.log:W180126 16:39:18.187207 270 storage/engine/rocksdb.go:1704  batch [124/10913/0] commit took 882.842064ms (>500ms):
n4.log:W180126 16:39:18.858094 240 storage/engine/rocksdb.go:1704  batch [175/18381/0] commit took 670.470424ms (>500ms):
n4.log:W180126 16:39:19.981165 243 storage/engine/rocksdb.go:1704  batch [127/14422/0] commit took 1.122703767s (>500ms):
n4.log:W180126 16:39:20.862791 240 storage/engine/rocksdb.go:1704  batch [179/35864/0] commit took 881.275542ms (>500ms):
n4.log:W180126 16:39:23.053575 287 storage/engine/rocksdb.go:1704  batch [135/19479/0] commit took 2.190438022s (>500ms):
n4.log:W180126 16:39:24.247095 258 storage/engine/rocksdb.go:1704  batch [153/12648/0] commit took 1.192885059s (>500ms):
n4.log:W180126 16:39:25.020607 236 storage/engine/rocksdb.go:1704  batch [124/13851/0] commit took 773.246332ms (>500ms):
n4.log:W180126 16:39:25.869029 282 storage/engine/rocksdb.go:1704  batch [311/53669/0] commit took 846.968824ms (>500ms):
n4.log:W180126 16:39:29.146239 262 storage/engine/rocksdb.go:1704  batch [34/2842/0] commit took 3.276867415s (>500ms):
n4.log:W180126 16:39:33.468990 259 storage/engine/rocksdb.go:1704  batch [24/2036/0] commit took 4.143549516s (>500ms):
n4.log:W180126 16:39:35.324977 266 storage/engine/rocksdb.go:1704  batch [29/2506/0] commit took 1.722629517s (>500ms):
n4.log:W180126 16:39:37.412510 283 storage/engine/rocksdb.go:1704  batch [33/2852/0] commit took 1.932062249s (>500ms):
n4.log:W180126 16:39:39.468672 283 storage/engine/rocksdb.go:1704  batch [98/19463/0] commit took 1.876511382s (>500ms):
n4.log:W180126 16:39:40.658200 264 storage/engine/rocksdb.go:1704  batch [239/39694/0] commit took 1.189048776s (>500ms):
n4.log:W180126 16:39:43.088283 237 storage/engine/rocksdb.go:1704  batch [65/6945/0] commit took 2.429808366s (>500ms):
n4.log:W180126 16:39:45.086307 237 storage/engine/rocksdb.go:1704  batch [182/23990/0] commit took 1.570649391s (>500ms):
n4.log:W180126 16:39:46.555926 144 storage/engine/rocksdb.go:1704  batch [99/8385/0] commit took 1.469241538s (>500ms):
n4.log:W180126 16:39:47.072241 226 storage/engine/rocksdb.go:1704  batch [131/13325/0] commit took 515.998939ms (>500ms):
n4.log:W180126 16:39:47.888612 260 storage/engine/rocksdb.go:1704  batch [125/10633/0] commit took 814.21769ms (>500ms):
n4.log:W180126 16:39:48.539231 237 storage/engine/rocksdb.go:1704  batch [110/7998/0] commit took 650.240623ms (>500ms):
n4.log:W180126 16:39:49.659615 267 storage/engine/rocksdb.go:1704  batch [57/5138/0] commit took 630.252122ms (>500ms):
n4.log:W180126 16:39:50.837146 273 storage/engine/rocksdb.go:1704  batch [55/4754/0] commit took 858.561274ms (>500ms):
n4.log:W180126 16:39:51.715824 262 storage/engine/rocksdb.go:1704  batch [318/8500/0] commit took 585.859987ms (>500ms):
n4.log:W180126 16:39:52.235762 249 storage/engine/rocksdb.go:1704  batch [47/4063/2] commit took 519.513926ms (>500ms):
n4.log:W180126 16:39:55.022853 266 storage/engine/rocksdb.go:1704  batch [14/940/0] commit took 516.223213ms (>500ms):
n4.log:W180126 16:39:55.758330 227 storage/engine/rocksdb.go:1704  batch [10/668/0] commit took 676.805552ms (>500ms):
n4.log:W180126 16:39:56.602063 247 storage/engine/rocksdb.go:1704  batch [8/1150/0] commit took 800.846686ms (>500ms):
n4.log:W180126 16:39:57.179590 227 storage/engine/rocksdb.go:1704  batch [7/407/0] commit took 505.720945ms (>500ms):
n4.log:W180126 16:39:57.953408 285 storage/engine/rocksdb.go:1704  batch [39/6284/0] commit took 746.528272ms (>500ms):
n4.log:W180126 16:39:59.945814 257 storage/engine/rocksdb.go:1704  batch [19/1646/0] commit took 579.56502ms (>500ms):
n4.log:W180126 16:40:04.338849 284 storage/engine/rocksdb.go:1704  batch [39/13247/0] commit took 1.589614029s (>500ms):
n4.log:W180126 16:40:05.152532 245 storage/engine/rocksdb.go:1704  batch [132/17413/0] commit took 813.246306ms (>500ms):
n4.log:W180126 16:40:06.216332 263 storage/engine/rocksdb.go:1704  batch [25/1825/0] commit took 1.063389003s (>500ms):
n4.log:W180126 16:40:07.194511 233 storage/engine/rocksdb.go:1704  batch [81/8742/0] commit took 864.262326ms (>500ms):
n4.log:W180126 16:40:07.730566 265 storage/engine/rocksdb.go:1704  batch [175/16536/0] commit took 535.074613ms (>500ms):
n4.log:W180126 16:40:08.744084 261 storage/engine/rocksdb.go:1704  batch [170/4898/0] commit took 1.013114084s (>500ms):
n4.log:W180126 16:40:10.168418 265 storage/engine/rocksdb.go:1704  batch [88/7746/0] commit took 1.12284481s (>500ms):
n4.log:W180126 16:40:11.403343 228 storage/engine/rocksdb.go:1704  batch [73/10906/0] commit took 760.493457ms (>500ms):
n4.log:W180126 16:40:12.069640 233 storage/engine/rocksdb.go:1704  batch [39/2869/0] commit took 666.016482ms (>500ms):
n4.log:W180126 16:40:14.148413 236 storage/engine/rocksdb.go:1704  batch [29/1433/0] commit took 1.233504551s (>500ms):
n4.log:W180126 16:40:17.302092 277 storage/engine/rocksdb.go:1704  batch [42/6926/0] commit took 632.350256ms (>500ms):
n4.log:W180126 16:40:18.463989 285 storage/engine/rocksdb.go:1704  batch [49/6326/0] commit took 736.909357ms (>500ms):
n4.log:W180126 16:40:19.456132 229 storage/engine/rocksdb.go:1704  batch [37/2622/0] commit took 603.831492ms (>500ms):
n4.log:W180126 16:40:20.860197 234 storage/engine/rocksdb.go:1704  batch [73/12606/0] commit took 817.579558ms (>500ms):
n4.log:W180126 16:40:21.632066 270 storage/engine/rocksdb.go:1704  batch [131/17492/0] commit took 770.286471ms (>500ms):
n4.log:W180126 16:40:22.704416 275 storage/engine/rocksdb.go:1704  batch [37/2674/0] commit took 1.072020924s (>500ms):
n4.log:W180126 16:40:23.604633 269 storage/engine/rocksdb.go:1704  batch [27/2765/0] commit took 735.81483ms (>500ms):
n4.log:W180126 16:40:24.905462 239 storage/engine/rocksdb.go:1704  batch [21/1505/0] commit took 1.130579609s (>500ms):
n4.log:W180126 16:40:25.502295 271 storage/engine/rocksdb.go:1704  batch [139/8395/0] commit took 503.52273ms (>500ms):
n4.log:W180126 16:40:26.016269 267 storage/engine/rocksdb.go:1704  batch [118/11862/0] commit took 513.562615ms (>500ms):
n4.log:W180126 16:40:26.744225 236 storage/engine/rocksdb.go:1704  batch [27/1765/0] commit took 727.674327ms (>500ms):
n4.log:W180126 16:40:27.608167 236 storage/engine/rocksdb.go:1704  batch [25/2035/0] commit took 754.948845ms (>500ms):
n4.log:W180126 16:40:28.647360 270 storage/engine/rocksdb.go:1704  batch [122/11974/0] commit took 513.550039ms (>500ms):
n4.log:W180126 16:40:29.380375 234 storage/engine/rocksdb.go:1704  batch [65/4671/0] commit took 732.36739ms (>500ms):
n4.log:W180126 16:40:30.278910 144 storage/engine/rocksdb.go:1704  batch [71/6697/0] commit took 611.796917ms (>500ms):
n4.log:W180126 16:40:40.699652 265 storage/engine/rocksdb.go:1704  batch [14/1606/0] commit took 1.525269501s (>500ms):
n4.log:W180126 16:40:43.880578 265 storage/engine/rocksdb.go:1704  batch [15/2935/0] commit took 3.081614598s (>500ms):
n4.log:W180126 16:40:46.519716 265 storage/engine/rocksdb.go:1704  batch [20/4208/0] commit took 2.455270215s (>500ms):
n4.log:W180126 16:40:48.373908 228 storage/engine/rocksdb.go:1704  batch [50/10809/0] commit took 1.594511129s (>500ms):
n4.log:W180126 16:40:49.038684 262 storage/engine/rocksdb.go:1704  batch [300/101118/0] commit took 664.389861ms (>500ms):
n4.log:W180126 16:40:55.211387 272 storage/engine/rocksdb.go:1704  batch [54/9164/0] commit took 6.172389752s (>500ms):
n4.log:W180126 16:40:55.776347 268 storage/engine/rocksdb.go:1704  batch [263/36063/0] commit took 564.440019ms (>500ms):
n4.log:W180126 16:40:57.978741 254 storage/engine/rocksdb.go:1704  batch [35/3033/0] commit took 2.20211129s (>500ms):
n4.log:W180126 16:41:00.068367 252 storage/engine/rocksdb.go:1704  batch [36/4768/0] commit took 1.897736112s (>500ms):
n4.log:W180126 16:41:02.998122 266 storage/engine/rocksdb.go:1704  batch [40/3509/0] commit took 2.636299709s (>500ms):
n4.log:W180126 16:41:03.041316 294 storage/replica.go:1533  [n4,s4,r3/4:/System/NodeLiveness{-Max}] have been waiting 1m0s attempting to acquire lease
n4.log:W180126 16:41:04.739988 258 storage/engine/rocksdb.go:1704  batch [39/7968/0] commit took 1.522754274s (>500ms):
n4.log:W180126 16:41:07.204114 667907 storage/replica.go:2798  [n4,s4,r3/4:/System/NodeLiveness{-Max}] have been waiting 1m0s for proposing command RequestLease [/System/NodeLiveness,/Min)
n4.log:W180126 16:41:07.460706 238 storage/engine/rocksdb.go:1704  batch [40/12299/0] commit took 2.231324701s (>500ms):
n4.log:W180126 16:41:08.216281 286 storage/engine/rocksdb.go:1704  batch [263/52253/0] commit took 755.203106ms (>500ms):
n4.log:W180126 16:41:11.406575 268 storage/engine/rocksdb.go:1704  batch [38/2527/0] commit took 3.189944845s (>500ms):
n4.log:W180126 16:41:13.555109 252 storage/engine/rocksdb.go:1704  batch [32/2851/0] commit took 1.988886077s (>500ms):
n4.log:W180126 16:41:15.613742 252 storage/engine/rocksdb.go:1704  batch [37/7803/0] commit took 1.882925253s (>500ms):
n4.log:W180126 16:41:18.508517 238 storage/engine/rocksdb.go:1704  batch [118/10743/0] commit took 2.413102914s (>500ms):
n4.log:W180126 16:41:19.166250 235 storage/engine/rocksdb.go:1704  batch [159/11734/0] commit took 657.381042ms (>500ms):
n4.log:W180126 16:41:19.883888 229 storage/engine/rocksdb.go:1704  batch [113/12411/0] commit took 717.178281ms (>500ms):
n4.log:W180126 16:41:20.645723 235 storage/engine/rocksdb.go:1704  batch [163/22157/0] commit took 761.526133ms (>500ms):
n4.log:W180126 16:41:21.999258 256 storage/engine/rocksdb.go:1704  batch [119/23978/0] commit took 1.353107983s (>500ms):
n4.log:W180126 16:41:23.465055 265 storage/engine/rocksdb.go:1704  batch [174/20847/0] commit took 1.46525678s (>500ms):
n4.log:W180126 16:41:24.739877 229 storage/engine/rocksdb.go:1704  batch [118/15232/0] commit took 1.274121393s (>500ms):
n4.log:W180126 16:41:25.674148 247 storage/engine/rocksdb.go:1704  batch [144/19038/0] commit took 933.749067ms (>500ms):
n4.log:W180126 16:41:26.837347 284 storage/engine/rocksdb.go:1704  batch [107/9653/0] commit took 1.162797434s (>500ms):
n4.log:W180126 16:41:27.428188 264 storage/engine/rocksdb.go:1704  batch [162/14583/0] commit took 590.206132ms (>500ms):
n4.log:W180126 16:41:28.319222 252 storage/engine/rocksdb.go:1704  batch [100/9482/0] commit took 890.655343ms (>500ms):
n4.log:W180126 16:41:28.899359 281 storage/engine/rocksdb.go:1704  batch [134/13115/0] commit took 579.821087ms (>500ms):
n4.log:W180126 16:41:29.704107 260 storage/engine/rocksdb.go:1704  batch [55/4594/0] commit took 804.2923ms (>500ms):
n4.log:W180126 16:41:30.531802 280 storage/engine/rocksdb.go:1704  batch [22/1903/0] commit took 545.548306ms (>500ms):
n4.log:W180126 16:41:31.617017 266 storage/engine/rocksdb.go:1704  batch [16/1148/0] commit took 520.504061ms (>500ms):
n4.log:I180126 16:41:32.454621 279 storage/replica.go:3284  [n4,s4,r3/4:/System/NodeLiveness{-Max}] not quiescing: 1 pending commands
n4.log:W180126 16:41:33.180382 287 storage/engine/rocksdb.go:1704  batch [32/2276/0] commit took 671.902755ms (>500ms):
n4.log:W180126 16:41:34.772127 272 storage/engine/rocksdb.go:1704  batch [66/4643/0] commit took 534.921187ms (>500ms):
n4.log:W180126 16:41:36.840678 256 storage/engine/rocksdb.go:1704  batch [53/3561/0] commit took 1.780393312s (>500ms):
n4.log:W180126 16:41:38.360163 257 storage/engine/rocksdb.go:1704  batch [206/7004/0] commit took 562.642582ms (>500ms):
n4.log:W180126 16:41:40.094091 260 storage/engine/rocksdb.go:1704  batch [29/3221/0] commit took 1.304274016s (>500ms):
n4.log:W180126 16:41:42.393688 253 storage/engine/rocksdb.go:1704  batch [80/14857/0] commit took 971.295014ms (>500ms):
n4.log:W180126 16:41:43.304545 280 storage/engine/rocksdb.go:1704  batch [46/1604/0] commit took 910.553897ms (>500ms):
n4.log:W180126 16:41:44.427595 255 storage/engine/rocksdb.go:1704  batch [21/1838/0] commit took 535.478282ms (>500ms):
n4.log:W180126 16:41:45.698152 237 storage/engine/rocksdb.go:1704  batch [34/2494/0] commit took 551.032429ms (>500ms):
n4.log:W180126 16:41:49.074357 236 storage/engine/rocksdb.go:1704  batch [31/3519/0] commit took 686.688337ms (>500ms):
n4.log:W180126 16:41:50.101452 264 storage/engine/rocksdb.go:1704  batch [151/8557/0] commit took 807.417338ms (>500ms):
n4.log:W180126 16:41:50.625786 255 storage/engine/rocksdb.go:1704  batch [50/3385/0] commit took 523.247178ms (>500ms):
n4.log:W180126 16:41:53.230106 269 storage/engine/rocksdb.go:1704  batch [48/4400/0] commit took 889.771439ms (>500ms):
n4.log:W180126 16:41:54.200621 245 storage/engine/rocksdb.go:1704  batch [43/2832/0] commit took 699.723312ms (>500ms):
n4.log:W180126 16:41:55.128374 245 storage/engine/rocksdb.go:1704  batch [46/4565/0] commit took 753.672702ms (>500ms):
n4.log:W180126 16:41:55.987026 252 storage/engine/rocksdb.go:1704  batch [33/2796/0] commit took 578.451835ms (>500ms):
n4.log:W180126 16:41:58.118845 232 storage/engine/rocksdb.go:1704  batch [35/6437/0] commit took 1.002309075s (>500ms):
n4.log:W180126 16:42:00.459970 287 storage/engine/rocksdb.go:1704  batch [59/7685/0] commit took 1.946386626s (>500ms):
n4.log:W180126 16:42:02.934445 256 storage/engine/rocksdb.go:1704  batch [76/9545/0] commit took 1.999893303s (>500ms):
n4.log:W180126 16:42:03.518921 251 storage/engine/rocksdb.go:1704  batch [193/23563/0] commit took 584.055129ms (>500ms):
n4.log:W180126 16:42:04.958363 228 storage/engine/rocksdb.go:1704  batch [228/14123/0] commit took 1.438955113s (>500ms):
n4.log:W180126 16:42:05.825311 248 storage/engine/rocksdb.go:1704  batch [328/33329/0] commit took 866.545923ms (>500ms):
n4.log:W180126 16:42:07.860754 246 storage/engine/rocksdb.go:1704  batch [75/8533/0] commit took 2.034856857s (>500ms):
n4.log:W180126 16:42:08.382898 266 storage/engine/rocksdb.go:1704  batch [161/32581/0] commit took 521.68694ms (>500ms):
n4.log:W180126 16:42:10.372725 279 storage/engine/rocksdb.go:1704  batch [270/14482/0] commit took 1.989415859s (>500ms):
n4.log:W180126 16:42:11.261470 226 storage/engine/rocksdb.go:1704  batch [192/21406/0] commit took 888.04632ms (>500ms):
n4.log:W180126 16:42:12.569133 276 storage/engine/rocksdb.go:1704  batch [64/9753/0] commit took 1.307229485s (>500ms):
n4.log:W180126 16:42:13.167228 274 storage/engine/rocksdb.go:1704  batch [187/35637/0] commit took 597.403903ms (>500ms):
n4.log:W180126 16:42:15.345339 261 storage/engine/rocksdb.go:1704  batch [73/11887/0] commit took 2.176381896s (>500ms):
n4.log:W180126 16:42:16.075740 278 storage/engine/rocksdb.go:1704  batch [154/12725/0] commit took 730.08412ms (>500ms):
n4.log:W180126 16:42:16.854203 276 storage/engine/rocksdb.go:1704  batch [79/6168/0] commit took 778.116261ms (>500ms):
n4.log:W180126 16:42:18.156878 249 storage/engine/rocksdb.go:1704  batch [115/10578/0] commit took 922.692306ms (>500ms):
n4.log:W180126 16:42:18.806828 234 storage/engine/rocksdb.go:1704  batch [74/5511/0] commit took 649.367453ms (>500ms):
n4.log:I180126 16:42:19.145484 669272 storage/replica_raftstorage.go:746  [n4,s4,r3/4:/System/NodeLiveness{-Max}] applying Raft snapshot at index 3536255 (id=c5496ba4, encoded size=112798, 1 rocksdb batches, 37 log entries)
n4.log:W180126 16:42:20.147720 253 storage/engine/rocksdb.go:1704  batch [4731/175916/0] commit took 631.391415ms (>500ms):
n4.log:I180126 16:42:20.152098 669272 storage/replica_raftstorage.go:752  [n4,s4,r3/4:/System/NodeLiveness{-Max}] applied Raft snapshot in 1007ms [clear=37ms batch=1ms entries=0ms commit=968ms]
n4.log:W180126 16:42:29.710157 294 storage/replica.go:1533  [n4,s4,r3/4:/System/NodeLiveness{-Max}] have been waiting 1m0s attempting to acquire lease
n4.log:W180126 16:42:30.886224 236 storage/engine/rocksdb.go:1704  batch [32/2575/0] commit took 10.737973527s (>500ms):
n4.log:W180126 16:42:30.966545 669010 storage/replica.go:2798  [n4,s4,r3/4:/System/NodeLiveness{-Max}] have been waiting 1m0s for proposing command RequestLease [/System/NodeLiveness,/Min)
n4.log:W180126 16:42:33.101216 287 storage/engine/rocksdb.go:1704  batch [9/689/0] commit took 568.929967ms (>500ms):
n4.log:W180126 16:42:34.511428 252 storage/engine/rocksdb.go:1704  batch [2/115/0] commit took 569.780774ms (>500ms):
n4.log:W180126 16:42:35.170327 252 storage/engine/rocksdb.go:1704  batch [9/544/0] commit took 649.960382ms (>500ms):
n4.log:W180126 16:42:35.755766 252 storage/engine/rocksdb.go:1704  batch [12/830/0] commit took 550.679049ms (>500ms):
n4.log:W180126 16:42:36.459459 282 storage/engine/rocksdb.go:1704  batch [45/4755/0] commit took 651.70709ms (>500ms):
n4.log:W180126 16:42:39.397185 231 storage/engine/rocksdb.go:1704  batch [28/3951/0] commit took 505.086669ms (>500ms):
n4.log:W180126 16:42:41.955761 669379 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: ab102471], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:42:42.552398 238 storage/engine/rocksdb.go:1704  batch [178/6500/0] commit took 692.069944ms (>500ms):
n4.log:W180126 16:42:43.045998 669371 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 3bde33ae], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:42:43.473146 266 storage/engine/rocksdb.go:1704  batch [58/6384/0] commit took 522.088636ms (>500ms):
n4.log:W180126 16:42:43.824990 669351 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 589bc5e8], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:42:44.372191 669296 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: f700b0b5], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
n4.log:W180126 16:42:47.264775 239 storage/engine/rocksdb.go:1704  batch [9/2363/0] commit took 928.039854ms (>500ms):
n4.log:W180126 16:42:49.622224 239 storage/engine/rocksdb.go:1704  batch [60/19441/0] commit took 2.211439815s (>500ms):
n4.log:W180126 16:42:50.813787 257 storage/engine/rocksdb.go:1704  batch [192/26350/0] commit took 1.190945114s (>500ms):
n4.log:W180126 16:42:52.428242 245 storage/engine/rocksdb.go:1704  batch [50/4166/0] commit took 1.608786303s (>500ms):
n4.log:W180126 16:42:55.627699 234 storage/engine/rocksdb.go:1704  batch [137/32033/0] commit took 2.236898513s (>500ms):
n4.log:W180126 16:42:56.546513 670096 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: 7de107fb], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:42:57.587276 283 storage/engine/rocksdb.go:1704  batch [142/22556/0] commit took 1.959190225s (>500ms):
n4.log:W180126 16:42:57.872116 670253 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: eb163aa0], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
n4.log:W180126 16:42:58.969451 239 storage/engine/rocksdb.go:1704  batch [120/13930/0] commit took 1.381392625s (>500ms):
n4.log:W180126 16:42:59.824286 267 storage/engine/rocksdb.go:1704  batch [165/15899/0] commit took 851.191093ms (>500ms):
n4.log:W180126 16:42:59.955772 670309 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 681557df], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:43:00.797155 144 storage/engine/rocksdb.go:1704  batch [161/14520/0] commit took 971.895515ms (>500ms):
n4.log:W180126 16:43:01.046330 670287 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 7d988871], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:43:01.686212 253 storage/engine/rocksdb.go:1704  batch [84/9462/0] commit took 888.817172ms (>500ms):
n4.log:W180126 16:43:01.824915 670256 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: 677b13b7], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:43:02.265659 269 storage/engine/rocksdb.go:1704  batch [165/23414/0] commit took 579.014542ms (>500ms):
n4.log:W180126 16:43:02.266452 670055 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 14.7s of attempting command [txn: e7a2c294], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:43:02.266653 670280 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 13.4s of attempting command [txn: a65961f1], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
n4.log:W180126 16:43:02.266791 669998 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 12.6s of attempting command [txn: 0569d022], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:43:02.266981 670060 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 11.3s of attempting command [txn: 3410123e], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:43:02.267304 670061 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 9.4s of attempting command [txn: b86d4fb8], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:43:03.697176 262 storage/engine/rocksdb.go:1704  batch [119/25764/0] commit took 1.429747314s (>500ms):
n4.log:W180126 16:43:05.274551 272 storage/engine/rocksdb.go:1704  batch [188/31333/0] commit took 1.577001522s (>500ms):
n4.log:W180126 16:43:05.546803 670001 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: 9d7540e1], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:43:06.325481 670339 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: 2123c08d], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:43:06.767408 670289 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: e7de92f9], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:43:07.188785 264 storage/engine/rocksdb.go:1704  batch [121/12164/0] commit took 1.913892404s (>500ms):
n4.log:W180126 16:43:07.933506 252 storage/engine/rocksdb.go:1704  batch [174/14940/0] commit took 744.243977ms (>500ms):
n4.log:W180126 16:43:08.846778 227 storage/engine/rocksdb.go:1704  batch [116/17175/0] commit took 912.730331ms (>500ms):
n4.log:W180126 16:43:09.897514 239 storage/engine/rocksdb.go:1704  batch [180/27651/0] commit took 1.050303951s (>500ms):
n4.log:W180126 16:43:10.047479 670344 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 0e860dd3], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:43:10.825906 670348 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: 011c7d86], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:43:11.267875 670351 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: a08fc994], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:43:11.587050 259 storage/engine/rocksdb.go:1704  batch [134/24654/0] commit took 1.689136189s (>500ms):
n4.log:W180126 16:43:13.096430 254 storage/engine/rocksdb.go:1704  batch [184/31639/0] commit took 1.509083729s (>500ms):
n4.log:W180126 16:43:14.547869 670386 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: e054ed73], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:43:15.029863 246 storage/engine/rocksdb.go:1704  batch [142/22760/0] commit took 1.932915866s (>500ms):
n4.log:W180126 16:43:15.326446 670388 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 3d7fdb02], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:43:15.768345 670403 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: d414bc5f], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:43:16.421323 283 storage/engine/rocksdb.go:1704  batch [174/20472/0] commit took 1.390894577s (>500ms):
n4.log:W180126 16:43:17.672983 253 storage/engine/rocksdb.go:1704  batch [127/14201/0] commit took 1.251222496s (>500ms):
n4.log:W180126 16:43:18.541648 244 storage/engine/rocksdb.go:1704  batch [210/36424/0] commit took 867.964035ms (>500ms):
n4.log:W180126 16:43:19.826954 670112 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 12f03de9], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:43:20.268840 670392 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: a186e799], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:43:20.766333 237 storage/engine/rocksdb.go:1704  batch [121/20379/0] commit took 2.224353564s (>500ms):
n4.log:W180126 16:43:22.012014 235 storage/engine/rocksdb.go:1704  batch [177/20776/0] commit took 1.245355883s (>500ms):
n4.log:W180126 16:43:23.281597 274 storage/engine/rocksdb.go:1704  batch [104/11095/0] commit took 1.269301391s (>500ms):
n4.log:W180126 16:43:23.960943 235 storage/engine/rocksdb.go:1704  batch [199/22877/0] commit took 678.694453ms (>500ms):
n4.log:W180126 16:43:24.327451 670373 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 60da4811], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:43:24.769281 670396 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: c3bf0c8f], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:43:25.359266 256 storage/engine/rocksdb.go:1704  batch [107/16568/0] commit took 1.39792356s (>500ms):
n4.log:W180126 16:43:26.372121 237 storage/engine/rocksdb.go:1704  batch [352/38018/0] commit took 1.012409348s (>500ms):
n4.log:W180126 16:43:28.694095 240 storage/engine/rocksdb.go:1704  batch [98/10344/0] commit took 2.321409805s (>500ms):
n4.log:W180126 16:43:28.828080 670418 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: da64a561], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:43:29.269756 670420 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: bd5b00a5], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:43:29.327653 227 storage/engine/rocksdb.go:1704  batch [197/20523/0] commit took 633.069542ms (>500ms):
n4.log:W180126 16:43:30.585711 240 storage/engine/rocksdb.go:1704  batch [187/18367/0] commit took 1.25370251s (>500ms):
n4.log:W180126 16:43:31.707709 265 storage/engine/rocksdb.go:1704  batch [55/4443/0] commit took 1.121680334s (>500ms):
n4.log:W180126 16:43:32.847095 253 storage/engine/rocksdb.go:1704  batch [38/3236/0] commit took 866.14136ms (>500ms):
n4.log:W180126 16:43:33.328636 670397 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: a8bd44bf], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:43:33.770220 670408 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: a6a14f39], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:43:33.903267 268 storage/engine/rocksdb.go:1704  batch [36/3909/0] commit took 857.244508ms (>500ms):
n4.log:W180126 16:43:34.763846 268 storage/engine/rocksdb.go:1704  batch [59/4497/0] commit took 620.287908ms (>500ms):
n4.log:W180126 16:43:36.181816 250 storage/engine/rocksdb.go:1704  batch [3/237/0] commit took 519.091446ms (>500ms):
n4.log:W180126 16:43:37.405403 230 storage/engine/rocksdb.go:1704  batch [3/237/0] commit took 512.81047ms (>500ms):
n4.log:W180126 16:43:37.829078 670427 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context canceled while in command queue: [txn: 27b91554], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:43:38.082923 251 storage/engine/rocksdb.go:1704  batch [3/237/0] commit took 658.250585ms (>500ms):
n4.log:W180126 16:43:40.125206 294 storage/store.go:1404  [n4,s4,r3/4:/System/NodeLiveness{-Max}] could not gossip node liveness: [NotLeaseHolderError] r3: replica (n4,s4):4 not lease holder; lease holder unknown
n4.log:W180126 16:43:41.788876 242 storage/engine/rocksdb.go:1704  batch [21/5946/0] commit took 719.453269ms (>500ms):
n4.log:W180126 16:43:44.542969 261 storage/engine/rocksdb.go:1704  batch [4/281/0] commit took 739.949378ms (>500ms):
n4.log:W180126 16:43:47.209698 241 storage/engine/rocksdb.go:1704  batch [3/237/0] commit took 2.647549703s (>500ms):
n4.log:W180126 16:43:50.509537 145 storage/engine/rocksdb.go:1704  batch [3/233/0] commit took 3.284040638s (>500ms):
n4.log:W180126 16:43:51.703680 145 storage/engine/rocksdb.go:1704  batch [86/18499/0] commit took 1.174475935s (>500ms):
n4.log:W180126 16:43:52.834444 283 storage/engine/rocksdb.go:1704  batch [108/29777/0] commit took 1.130547636s (>500ms):
n4.log:W180126 16:43:54.656254 286 storage/engine/rocksdb.go:1704  batch [127/35661/0] commit took 1.821210228s (>500ms):
n4.log:W180126 16:43:56.834317 227 storage/engine/rocksdb.go:1704  batch [131/10395/0] commit took 2.177867665s (>500ms):
n4.log:W180126 16:43:57.471724 261 storage/engine/rocksdb.go:1704  batch [126/6499/0] commit took 635.683242ms (>500ms):
n4.log:W180126 16:43:58.965164 145 storage/engine/rocksdb.go:1704  batch [155/17807/0] commit took 1.091680779s (>500ms):
n4.log:W180126 16:44:00.053227 276 storage/engine/rocksdb.go:1704  batch [107/9127/0] commit took 1.087469977s (>500ms):
n4.log:W180126 16:44:00.612565 267 storage/engine/rocksdb.go:1704  batch [128/11306/0] commit took 558.813545ms (>500ms):
n4.log:W180126 16:44:01.305248 249 storage/engine/rocksdb.go:1704  batch [276/17082/0] commit took 691.737271ms (>500ms):
n4.log:W180126 16:44:02.349501 245 storage/engine/rocksdb.go:1704  batch [62/8971/0] commit took 1.043796484s (>500ms):
n4.log:W180126 16:44:02.901980 266 storage/engine/rocksdb.go:1704  batch [187/22305/0] commit took 551.903316ms (>500ms):
n4.log:W180126 16:44:04.264824 263 storage/engine/rocksdb.go:1704  batch [29/2260/0] commit took 1.362485355s (>500ms):
n4.log:W180126 16:44:05.021508 263 storage/engine/rocksdb.go:1704  batch [40/3221/0] commit took 616.713884ms (>500ms):
n4.log:W180126 16:44:06.059426 237 storage/engine/rocksdb.go:1704  batch [38/8899/0] commit took 839.751378ms (>500ms):
n4.log:W180126 16:44:06.604129 271 storage/engine/rocksdb.go:1704  batch [249/15278/0] commit took 544.377261ms (>500ms):
n4.log:W180126 16:44:07.541360 263 storage/engine/rocksdb.go:1704  batch [25/1567/0] commit took 936.63556ms (>500ms):
n4.log:W180126 16:44:10.420050 247 storage/engine/rocksdb.go:1704  batch [32/3411/0] commit took 577.090617ms (>500ms):
n4.log:W180126 16:44:13.764436 263 storage/engine/rocksdb.go:1704  batch [16/2989/0] commit took 1.418977259s (>500ms):
n4.log:W180126 16:44:16.894879 263 storage/engine/rocksdb.go:1704  batch [29/3998/0] commit took 2.946482696s (>500ms):
n4.log:W180126 16:44:19.983375 263 storage/engine/rocksdb.go:1704  batch [30/4565/0] commit took 2.839124327s (>500ms):
n4.log:W180126 16:44:21.686691 287 storage/engine/rocksdb.go:1704  batch [42/14749/0] commit took 1.419446724s (>500ms):
n4.log:W180126 16:44:22.589248 272 storage/engine/rocksdb.go:1704  batch [300/86499/0] commit took 902.054238ms (>500ms):
n4.log:W180126 16:44:27.870621 263 storage/engine/rocksdb.go:1704  batch [41/3690/0] commit took 5.280985382s (>500ms):
n4.log:W180126 16:44:30.704094 266 storage/engine/rocksdb.go:1704  batch [117/10408/0] commit took 2.602610683s (>500ms):
n4.log:W180126 16:44:31.343849 251 storage/engine/rocksdb.go:1704  batch [190/20177/0] commit took 639.224597ms (>500ms):
n4.log:W180126 16:44:32.577145 242 storage/engine/rocksdb.go:1704  batch [121/26527/0] commit took 1.232791085s (>500ms):
n4.log:W180126 16:44:34.197586 262 storage/engine/rocksdb.go:1704  batch [184/30997/0] commit took 1.620059934s (>500ms):
n4.log:W180126 16:44:36.093713 257 storage/engine/rocksdb.go:1704  batch [108/9683/0] commit took 1.895779788s (>500ms):
n4.log:W180126 16:44:36.686200 226 storage/engine/rocksdb.go:1704  batch [196/24772/0] commit took 592.087453ms (>500ms):
n4.log:W180126 16:44:38.199566 270 storage/engine/rocksdb.go:1704  batch [109/9707/0] commit took 1.512873117s (>500ms):
n4.log:W180126 16:44:38.796731 265 storage/engine/rocksdb.go:1704  batch [188/22833/0] commit took 596.775915ms (>500ms):
n4.log:W180126 16:44:40.192553 231 storage/engine/rocksdb.go:1704  batch [144/36475/0] commit took 1.394930202s (>500ms):
n4.log:W180126 16:44:42.420675 244 storage/engine/rocksdb.go:1704  batch [154/30457/0] commit took 2.227663842s (>500ms):
n4.log:W180126 16:44:44.284967 267 storage/engine/rocksdb.go:1704  batch [146/22525/0] commit took 1.863725787s (>500ms):
n4.log:W180126 16:44:45.661031 238 storage/engine/rocksdb.go:1704  batch [137/20306/0] commit took 1.37578984s (>500ms):
n4.log:W180126 16:44:46.902184 239 storage/engine/rocksdb.go:1704  batch [146/14323/0] commit took 1.240866131s (>500ms):
n4.log:W180126 16:44:47.781216 241 storage/engine/rocksdb.go:1704  batch [131/17733/0] commit took 878.735706ms (>500ms):
n4.log:W180126 16:44:48.864677 239 storage/engine/rocksdb.go:1704  batch [150/17520/0] commit took 1.083034143s (>500ms):
n4.log:W180126 16:44:49.935553 230 storage/engine/rocksdb.go:1704  batch [141/12695/0] commit took 1.070463391s (>500ms):
n4.log:W180126 16:44:50.712434 240 storage/engine/rocksdb.go:1704  batch [182/20995/0] commit took 776.180035ms (>500ms):
n4.log:W180126 16:44:51.996809 248 storage/engine/rocksdb.go:1704  batch [112/13527/0] commit took 1.282559552s (>500ms):
n4.log:W180126 16:44:52.827859 246 storage/engine/rocksdb.go:1704  batch [185/17622/0] commit took 830.461191ms (>500ms):
n4.log:W180126 16:44:53.904587 271 storage/engine/rocksdb.go:1704  batch [106/14629/0] commit took 1.076287643s (>500ms):
n4.log:W180126 16:44:54.799886 275 storage/engine/rocksdb.go:1704  batch [192/44799/0] commit took 894.445218ms (>500ms):
n4.log:W180126 16:44:57.535558 277 storage/engine/rocksdb.go:1704  batch [60/4762/0] commit took 2.735343849s (>500ms):
n4.log:W180126 16:44:58.850772 254 storage/engine/rocksdb.go:1704  batch [67/6929/0] commit took 1.019250983s (>500ms):
n4.log:W180126 16:45:00.931388 264 storage/engine/rocksdb.go:1704  batch [231/23135/0] commit took 1.653893881s (>500ms):
n4.log:W180126 16:45:02.348243 226 storage/engine/rocksdb.go:1704  batch [17/1252/0] commit took 1.416169688s (>500ms):
n4.log:W180126 16:45:03.041317 294 storage/replica.go:1533  [n4,s4,r3/4:/System/NodeLiveness{-Max}] have been waiting 1m0s attempting to acquire lease
n4.log:W180126 16:45:03.047773 243 storage/engine/rocksdb.go:1704  batch [16/1430/0] commit took 621.083037ms (>500ms):
n4.log:W180126 16:45:04.422927 242 storage/engine/rocksdb.go:1704  batch [126/3715/0] commit took 774.077924ms (>500ms):
n4.log:W180126 16:45:07.218713 272 storage/engine/rocksdb.go:1704  batch [9/546/0] commit took 713.192364ms (>500ms):
n4.log:W180126 16:45:09.285500 283 storage/engine/rocksdb.go:1704  batch [15/996/0] commit took 2.031884617s (>500ms):
n4.log:W180126 16:45:10.257613 272 storage/engine/rocksdb.go:1704  batch [16/1120/0] commit took 906.825465ms (>500ms):
n4.log:W180126 16:45:10.979243 283 storage/engine/rocksdb.go:1704  batch [20/3532/0] commit took 650.968325ms (>500ms):
n4.log:W180126 16:45:12.649821 268 storage/engine/rocksdb.go:1704  batch [25/1500/0] commit took 1.453395199s (>500ms):
n4.log:W180126 16:45:13.839091 248 storage/engine/rocksdb.go:1704  batch [5/1752/0] commit took 528.234039ms (>500ms):
n4.log:W180126 16:45:15.813969 240 storage/engine/rocksdb.go:1704  batch [11/1943/0] commit took 1.863041147s (>500ms):
n4.log:W180126 16:45:16.604081 248 storage/engine/rocksdb.go:1704  batch [8/1556/0] commit took 669.78583ms (>500ms):
n4.log:W180126 16:45:17.265799 228 storage/engine/rocksdb.go:1704  batch [47/5666/0] commit took 564.540974ms (>500ms):
n4.log:W180126 16:45:23.551398 227 storage/engine/rocksdb.go:1704  batch [27/1445/0] commit took 596.814515ms (>500ms):
n4.log:W180126 16:45:25.244480 282 storage/engine/rocksdb.go:1704  batch [78/19985/0] commit took 850.530241ms (>500ms):
n4.log:W180126 16:45:26.466190 248 storage/engine/rocksdb.go:1704  batch [227/13704/0] commit took 1.221413095s (>500ms):
n4.log:W180126 16:45:27.303699 280 storage/engine/rocksdb.go:1704  batch [8/488/0] commit took 837.156671ms (>500ms):
n4.log:W180126 16:45:28.077314 282 storage/engine/rocksdb.go:1704  batch [15/1193/0] commit took 738.915951ms (>500ms):
n4.log:W180126 16:45:28.101982 670508 storage/replica.go:2798  [n4,s4,r3/4:/System/NodeLiveness{-Max}] have been waiting 1m0s for proposing command RequestLease [/System/NodeLiveness,/Min)
n4.log:W180126 16:45:28.986064 282 storage/engine/rocksdb.go:1704  batch [30/2443/0] commit took 833.804299ms (>500ms):
n4.log:W180126 16:45:29.375015 102 storage/replica.go:1533  [gc,n4,s4,r3/4:/System/NodeLiveness{-Max}] have been waiting 1m0s attempting to acquire lease
n4.log:W180126 16:45:30.314840 270 storage/engine/rocksdb.go:1704  batch [33/2504/0] commit took 1.177721364s (>500ms):
n4.log:W180126 16:45:38.047295 278 storage/engine/rocksdb.go:1704  batch [23/3611/0] commit took 1.319163012s (>500ms):
n4.log:W180126 16:45:41.172434 241 storage/engine/rocksdb.go:1704  batch [34/4449/0] commit took 2.902419251s (>500ms):
n4.log:W180126 16:45:43.329781 282 storage/engine/rocksdb.go:1704  batch [56/8376/0] commit took 1.880610718s (>500ms):
n4.log:W180126 16:45:43.842567 255 storage/engine/rocksdb.go:1704  batch [224/21832/0] commit took 512.410195ms (>500ms):
n4.log:W180126 16:45:45.176702 227 storage/engine/rocksdb.go:1704  batch [79/26127/0] commit took 1.333784602s (>500ms):
n4.log:W180126 16:45:46.776050 250 storage/engine/rocksdb.go:1704  batch [257/80523/0] commit took 1.598906672s (>500ms):
n4.log:W180126 16:45:51.691956 248 storage/engine/rocksdb.go:1704  batch [102/18504/0] commit took 4.91546951s (>500ms):
n4.log:W180126 16:45:52.827158 251 storage/engine/rocksdb.go:1704  batch [334/49282/0] commit took 1.134667708s (>500ms):
n4.log:W180126 16:45:55.836912 249 storage/engine/rocksdb.go:1704  batch [90/16397/0] commit took 3.00953151s (>500ms):
n4.log:W180126 16:45:56.842773 251 storage/engine/rocksdb.go:1704  batch [235/28391/0] commit took 1.005309459s (>500ms):
n4.log:W180126 16:45:58.577097 243 storage/engine/rocksdb.go:1704  batch [69/6119/0] commit took 1.733926284s (>500ms):
n4.log:W180126 16:46:00.310505 252 storage/engine/rocksdb.go:1704  batch [66/6983/0] commit took 1.358238709s (>500ms):
n4.log:W180126 16:46:02.622851 234 storage/engine/rocksdb.go:1704  batch [56/7039/0] commit took 1.884410195s (>500ms):
n4.log:W180126 16:46:05.109624 260 storage/engine/rocksdb.go:1704  batch [46/8468/0] commit took 2.054434003s (>500ms):
n4.log:W180126 16:46:05.631732 257 storage/engine/rocksdb.go:1704  batch [269/50610/0] commit took 521.652605ms (>500ms):
n4.log:W180126 16:46:08.721582 269 storage/engine/rocksdb.go:1704  batch [54/8543/0] commit took 3.089397881s (>500ms):
n4.log:W180126 16:46:09.247939 281 storage/engine/rocksdb.go:1704  batch [237/44113/0] commit took 525.935046ms (>500ms):
n4.log:W180126 16:46:11.941523 260 storage/engine/rocksdb.go:1704  batch [60/4954/0] commit took 2.693241914s (>500ms):
n4.log:W180126 16:46:13.353795 241 storage/engine/rocksdb.go:1704  batch [52/6348/0] commit took 1.104414507s (>500ms):
n4.log:W180126 16:46:15.364227 271 storage/engine/rocksdb.go:1704  batch [60/6886/0] commit took 1.620812955s (>500ms):
n4.log:W180126 16:46:17.868528 253 storage/engine/rocksdb.go:1704  batch [39/3536/0] commit took 2.082061626s (>500ms):
n4.log:W180126 16:46:19.979745 253 storage/engine/rocksdb.go:1704  batch [38/5995/0] commit took 1.89040824s (>500ms):
n4.log:W180126 16:46:22.391654 281 storage/engine/rocksdb.go:1704  batch [115/13864/0] commit took 2.043221358s (>500ms):
n4.log:W180126 16:46:23.242923 252 storage/engine/rocksdb.go:1704  batch [132/11116/0] commit took 851.032986ms (>500ms):
n4.log:W180126 16:46:23.923594 247 storage/engine/rocksdb.go:1704  batch [154/16074/0] commit took 679.938052ms (>500ms):
n4.log:W180126 16:46:24.905793 287 storage/engine/rocksdb.go:1704  batch [85/9120/0] commit took 981.88835ms (>500ms):
n4.log:W180126 16:46:25.464040 283 storage/engine/rocksdb.go:1704  batch [188/22146/0] commit took 557.806072ms (>500ms):
n4.log:W180126 16:46:26.817456 242 storage/engine/rocksdb.go:1704  batch [60/5153/0] commit took 1.353162564s (>500ms):
n4.log:W180126 16:46:28.004411 286 storage/engine/rocksdb.go:1704  batch [35/2788/0] commit took 867.000969ms (>500ms):
n4.log:W180126 16:46:28.786441 238 storage/engine/rocksdb.go:1704  batch [41/3375/0] commit took 609.941985ms (>500ms):
n4.log:W180126 16:46:29.800421 145 storage/engine/rocksdb.go:1704  batch [142/5112/0] commit took 806.028969ms (>500ms):
n4.log:W180126 16:46:33.105338 282 storage/engine/rocksdb.go:1704  batch [58/3827/0] commit took 962.108635ms (>500ms):
n4.log:W180126 16:46:35.799114 259 storage/engine/rocksdb.go:1704  batch [64/7820/0] commit took 1.335511686s (>500ms):
n4.log:W180126 16:46:36.981211 267 storage/engine/rocksdb.go:1704  batch [93/8705/0] commit took 700.796826ms (>500ms):
n4.log:W180126 16:46:37.514276 249 storage/engine/rocksdb.go:1704  batch [100/6324/0] commit took 532.675638ms (>500ms):
n4.log:W180126 16:46:38.876945 231 storage/engine/rocksdb.go:1704  batch [61/5486/0] commit took 513.926198ms (>500ms):
n4.log:W180126 16:46:39.848656 226 storage/engine/rocksdb.go:1704  batch [54/4490/0] commit took 635.548547ms (>500ms):
n4.log:W180126 16:46:41.152229 247 storage/engine/rocksdb.go:1704  batch [60/13429/0] commit took 630.577066ms (>500ms):
n4.log:W180126 16:46:41.974042 267 storage/engine/rocksdb.go:1704  batch [42/4668/0] commit took 821.015357ms (>500ms):
n4.log:W180126 16:46:48.069098 286 storage/engine/rocksdb.go:1704  batch [63/7901/0] commit took 640.905258ms (>500ms):
n4.log:W180126 16:46:50.835614 248 storage/engine/rocksdb.go:1704  batch [16/1475/0] commit took 1.190198204s (>500ms):
n4.log:W180126 16:46:52.247429 271 storage/engine/rocksdb.go:1704  batch [36/3402/0] commit took 754.56874ms (>500ms):
n4.log:W180126 16:46:53.850029 144 storage/engine/rocksdb.go:1704  batch [262/12465/0] commit took 553.202423ms (>500ms):
n4.log:W180126 16:46:54.612137 263 storage/engine/rocksdb.go:1704  batch [82/6135/0] commit took 761.477046ms (>500ms):
n4.log:W180126 16:46:57.386485 254 storage/engine/rocksdb.go:1704  batch [70/10303/0] commit took 801.400285ms (>500ms):
n4.log:W180126 16:46:58.020344 282 storage/engine/rocksdb.go:1704  batch [107/16136/0] commit took 633.494466ms (>500ms):
n4.log:W180126 16:46:59.006753 280 storage/engine/rocksdb.go:1704  batch [322/21249/0] commit took 986.031075ms (>500ms):
n4.log:W180126 16:47:00.305217 242 storage/engine/rocksdb.go:1704  batch [112/19842/0] commit took 1.297991572s (>500ms):
n4.log:W180126 16:47:01.517667 270 storage/engine/rocksdb.go:1704  batch [114/21218/0] commit took 1.211880252s (>500ms):
n4.log:W180126 16:47:02.814124 231 storage/engine/rocksdb.go:1704  batch [128/15232/0] commit took 1.295917608s (>500ms):
n4.log:W180126 16:47:03.748824 236 storage/engine/rocksdb.go:1704  batch [140/14655/0] commit took 934.347407ms (>500ms):
n4.log:W180126 16:47:04.645617 234 storage/engine/rocksdb.go:1704  batch [318/32521/0] commit took 895.99236ms (>500ms):
n4.log:W180126 16:47:06.631877 228 storage/engine/rocksdb.go:1704  batch [55/6527/0] commit took 1.985865995s (>500ms):
n4.log:W180126 16:47:09.185071 241 storage/engine/rocksdb.go:1704  batch [33/3310/0] commit took 2.149688513s (>500ms):
n4.log:W180126 16:47:10.815420 245 storage/engine/rocksdb.go:1704  batch [35/8758/0] commit took 1.426429671s (>500ms):
n4.log:W180126 16:47:11.354397 263 storage/engine/rocksdb.go:1704  batch [178/20919/0] commit took 538.669816ms (>500ms):
n4.log:W180126 16:47:12.632985 279 storage/engine/rocksdb.go:1704  batch [51/7357/0] commit took 1.278049321s (>500ms):
n4.log:W180126 16:47:14.913955 269 storage/engine/rocksdb.go:1704  batch [57/4762/0] commit took 1.82970803s (>500ms):
n4.log:W180126 16:47:16.288331 269 storage/engine/rocksdb.go:1704  batch [32/5449/0] commit took 1.081523509s (>500ms):
n4.log:W180126 16:47:17.515794 249 storage/engine/rocksdb.go:1704  batch [45/3205/0] commit took 892.481978ms (>500ms):
n4.log:W180126 16:47:19.084412 284 storage/engine/rocksdb.go:1704  batch [31/3162/0] commit took 865.920893ms (>500ms):
n4.log:W180126 16:47:21.286032 227 storage/engine/rocksdb.go:1704  batch [54/7160/0] commit took 617.622339ms (>500ms):
n4.log:W180126 16:47:22.406380 227 storage/engine/rocksdb.go:1704  batch [105/19706/0] commit took 682.305155ms (>500ms):
n4.log:W180126 16:47:23.610104 251 storage/engine/rocksdb.go:1704  batch [33/5330/0] commit took 1.203408972s (>500ms):
n4.log:W180126 16:47:24.629480 267 storage/engine/rocksdb.go:1704  batch [112/20901/0] commit took 692.26887ms (>500ms):
n4.log:W180126 16:47:25.910031 265 storage/engine/rocksdb.go:1704  batch [118/15294/0] commit took 1.280232238s (>500ms):
n4.log:W180126 16:47:26.845819 276 storage/engine/rocksdb.go:1704  batch [124/12240/0] commit took 934.828755ms (>500ms):
n4.log:W180126 16:47:27.595085 237 storage/engine/rocksdb.go:1704  batch [288/11962/0] commit took 748.839099ms (>500ms):
n4.log:W180126 16:47:28.326337 264 storage/engine/rocksdb.go:1704  batch [139/24693/0] commit took 730.921611ms (>500ms):
n4.log:W180126 16:47:29.835010 242 storage/engine/rocksdb.go:1704  batch [62/6634/0] commit took 1.508339792s (>500ms):
n4.log:W180126 16:47:31.292009 294 storage/replica.go:1533  [n4,s4,r3/4:/System/NodeLiveness{-Max}] have been waiting 1m0s attempting to acquire lease
n4.log:W180126 16:47:31.336127 259 storage/engine/rocksdb.go:1704  batch [149/19663/0] commit took 1.091286264s (>500ms):
n4.log:W180126 16:47:32.536998 236 storage/engine/rocksdb.go:1704  batch [80/11205/0] commit took 1.200663504s (>500ms):
n4.log:W180126 16:47:33.221990 234 storage/engine/rocksdb.go:1704  batch [131/19020/0] commit took 684.686367ms (>500ms):
n4.log:W180126 16:47:34.387253 229 storage/engine/rocksdb.go:1704  batch [81/7229/0] commit took 1.164994735s (>500ms):
n4.log:W180126 16:47:35.885311 229 storage/engine/rocksdb.go:1704  batch [129/11438/0] commit took 1.054579549s (>500ms):
n4.log:W180126 16:47:36.585276 145 storage/engine/rocksdb.go:1704  batch [289/16286/0] commit took 699.654171ms (>500ms):
n4.log:W180126 16:47:37.580697 229 storage/engine/rocksdb.go:1704  batch [110/13927/0] commit took 995.175129ms (>500ms):
n4.log:W180126 16:47:38.434911 285 storage/engine/rocksdb.go:1704  batch [99/7752/0] commit took 853.829778ms (>500ms):
n4.log:W180126 16:47:39.876199 236 storage/engine/rocksdb.go:1704  batch [95/7315/0] commit took 544.143919ms (>500ms):
n4.log:W180126 16:47:45.815802 280 storage/engine/rocksdb.go:1704  batch [59/10452/0] commit took 1.26281279s (>500ms):
n4.log:W180126 16:47:46.455688 264 storage/engine/rocksdb.go:1704  batch [98/12245/0] commit took 639.528522ms (>500ms):
n4.log:W180126 16:47:46.637266 676841 storage/replica.go:2798  [n4,s4,r3/4:/System/NodeLiveness{-Max}] have been waiting 1m0s for proposing command RequestLease [/System/NodeLiveness,/Min)
n4.log:W180126 16:47:47.204679 244 storage/engine/rocksdb.go:1704  batch [43/4679/0] commit took 748.686652ms (>500ms):
n4.log:W180126 16:47:48.063628 248 storage/engine/rocksdb.go:1704  batch [70/7794/0] commit took 568.337149ms (>500ms):
n4.log:W180126 16:47:50.346989 242 storage/engine/rocksdb.go:1704  batch [49/9077/0] commit took 728.94059ms (>500ms):
n4.log:W180126 16:47:50.902760 239 storage/engine/rocksdb.go:1704  batch [66/10793/0] commit took 555.402208ms (>500ms):
n4.log:W180126 16:47:51.562327 226 storage/engine/rocksdb.go:1704  batch [192/8913/0] commit took 659.255009ms (>500ms):
n4.log:W180126 16:47:52.111117 259 storage/engine/rocksdb.go:1704  batch [106/28923/0] commit took 548.103911ms (>500ms):
n4.log:W180126 16:47:53.878367 242 storage/engine/rocksdb.go:1704  batch [32/2852/0] commit took 1.766663386s (>500ms):
n4.log:W180126 16:47:54.671807 226 storage/engine/rocksdb.go:1704  batch [86/20461/0] commit took 617.854209ms (>500ms):
n4.log:W180126 16:47:55.921903 281 storage/engine/rocksdb.go:1704  batch [115/10571/0] commit took 1.249829812s (>500ms):
n4.log:W180126 16:47:56.570954 265 storage/engine/rocksdb.go:1704  batch [24/2177/0] commit took 648.546939ms (>500ms):
n4.log:W180126 16:47:57.480741 253 storage/engine/rocksdb.go:1704  batch [35/4670/0] commit took 774.474846ms (>500ms):
n4.log:W180126 16:47:59.093776 253 storage/engine/rocksdb.go:1704  batch [202/14653/0] commit took 1.325335362s (>500ms):
n4.log:W180126 16:47:59.989398 287 storage/engine/rocksdb.go:1704  batch [120/11966/0] commit took 895.272739ms (>500ms):
n4.log:W180126 16:48:00.721360 279 storage/engine/rocksdb.go:1704  batch [77/6785/0] commit took 731.554352ms (>500ms):
n4.log:W180126 16:48:02.053012 279 storage/engine/rocksdb.go:1704  batch [33/4196/0] commit took 912.173581ms (>500ms):
n4.log:W180126 16:48:03.048547 226 storage/engine/rocksdb.go:1704  batch [259/12559/0] commit took 738.198068ms (>500ms):
n4.log:W180126 16:48:03.816643 278 storage/engine/rocksdb.go:1704  batch [98/9226/0] commit took 767.768757ms (>500ms):
n4.log:W180126 16:48:04.380637 287 storage/engine/rocksdb.go:1704  batch [61/5807/0] commit took 563.524139ms (>500ms):
n4.log:W180126 16:48:05.906781 272 storage/engine/rocksdb.go:1704  batch [61/12263/0] commit took 1.169424753s (>500ms):
n4.log:W180126 16:48:06.656431 238 storage/engine/rocksdb.go:1704  batch [133/12304/0] commit took 749.357322ms (>500ms):
n4.log:W180126 16:48:07.409315 248 storage/engine/rocksdb.go:1704  batch [111/9637/0] commit took 752.543538ms (>500ms):
n4.log:W180126 16:48:07.998276 144 storage/engine/rocksdb.go:1704  batch [24/3173/0] commit took 588.696023ms (>500ms):
n4.log:W180126 16:48:09.072885 252 storage/engine/rocksdb.go:1704  batch [46/3211/0] commit took 713.645561ms (>500ms):
n4.log:W180126 16:48:09.962409 248 storage/engine/rocksdb.go:1704  batch [48/3453/0] commit took 687.913256ms (>500ms):
n4.log:W180126 16:48:11.217782 258 storage/engine/rocksdb.go:1704  batch [2/115/0] commit took 763.082904ms (>500ms):
n4.log:W180126 16:48:12.343077 258 storage/engine/rocksdb.go:1704  batch [8/567/0] commit took 1.122948026s (>500ms):
n4.log:W180126 16:48:13.385838 261 storage/engine/rocksdb.go:1704  batch [13/795/0] commit took 621.346894ms (>500ms):
n4.log:W180126 16:48:14.857750 255 storage/engine/rocksdb.go:1704  batch [11/1110/0] commit took 711.835412ms (>500ms):
n4.log:W180126 16:48:17.862661 263 storage/engine/rocksdb.go:1704  batch [30/2980/0] commit took 518.367184ms (>500ms):
n4.log:W180126 16:48:18.604835 272 storage/engine/rocksdb.go:1704  batch [31/4467/0] commit took 555.550831ms (>500ms):
n4.log:W180126 16:48:20.339517 251 storage/engine/rocksdb.go:1704  batch [28/2405/0] commit took 1.456808464s (>500ms):
n4.log:W180126 16:48:21.357044 246 storage/engine/rocksdb.go:1704  batch [100/7060/0] commit took 551.714527ms (>500ms):
n4.log:W180126 16:48:22.500005 145 storage/engine/rocksdb.go:1704  batch [42/2990/0] commit took 544.291745ms (>500ms):
n4.log:W180126 16:48:24.314022 263 storage/engine/rocksdb.go:1704  batch [39/2057/0] commit took 921.361035ms (>500ms):
n4.log:W180126 16:48:24.947179 272 storage/engine/rocksdb.go:1704  batch [43/4541/0] commit took 506.486244ms (>500ms):
n4.log:W180126 16:48:35.738941 231 storage/engine/rocksdb.go:1704  batch [399/17307/0] commit took 922.158354ms (>500ms):
n4.log:W180126 16:48:36.798323 251 storage/engine/rocksdb.go:1704  batch [175/25306/0] commit took 1.05783334s (>500ms):
n4.log:W180126 16:48:38.347584 226 storage/engine/rocksdb.go:1704  batch [65/11213/0] commit took 1.54883256s (>500ms):
n4.log:W180126 16:48:39.033633 260 storage/engine/rocksdb.go:1704  batch [149/32483/0] commit took 685.633328ms (>500ms):
n4.log:W180126 16:48:41.017618 236 storage/engine/rocksdb.go:1704  batch [61/10570/0] commit took 1.983699013s (>500ms):
n4.log:W180126 16:48:41.667312 281 storage/engine/rocksdb.go:1704  batch [311/22361/0] commit took 649.334624ms (>500ms):
n4.log:W180126 16:48:43.033110 256 storage/engine/rocksdb.go:1704  batch [79/9325/0] commit took 1.365453466s (>500ms):
n4.log:W180126 16:48:43.604185 281 storage/engine/rocksdb.go:1704  batch [180/25430/0] commit took 570.715837ms (>500ms):
n4.log:W180126 16:48:45.157743 256 storage/engine/rocksdb.go:1704  batch [74/13686/0] commit took 1.553081085s (>500ms):
n4.log:W180126 16:48:45.997704 267 storage/engine/rocksdb.go:1704  batch [134/26488/0] commit took 839.583652ms (>500ms):
n4.log:W180126 16:48:47.616200 274 storage/engine/rocksdb.go:1704  batch [76/11866/0] commit took 1.617952338s (>500ms):
n4.log:W180126 16:48:48.341902 275 storage/engine/rocksdb.go:1704  batch [166/19079/0] commit took 725.316374ms (>500ms):
n4.log:W180126 16:48:49.508716 259 storage/engine/rocksdb.go:1704  batch [170/16825/0] commit took 1.165748004s (>500ms):
n4.log:W180126 16:48:50.536666 283 storage/engine/rocksdb.go:1704  batch [58/6730/0] commit took 1.027390446s (>500ms):
n4.log:W180126 16:48:52.333539 266 storage/engine/rocksdb.go:1704  batch [59/6509/0] commit took 1.381577125s (>500ms):
n4.log:W180126 16:48:53.821060 285 storage/engine/rocksdb.go:1704  batch [53/6629/0] commit took 1.088081767s (>500ms):
n4.log:W180126 16:48:55.223448 283 storage/engine/rocksdb.go:1704  batch [74/9719/0] commit took 996.305712ms (>500ms):
n4.log:W180126 16:48:55.818271 227 storage/engine/rocksdb.go:1704  batch [111/18118/0] commit took 594.360928ms (>500ms):
n4.log:W180126 16:48:56.925803 230 storage/engine/rocksdb.go:1704  batch [97/17547/0] commit took 1.106760372s (>500ms):
n4.log:W180126 16:48:57.999031 254 storage/engine/rocksdb.go:1704  batch [137/15676/0] commit took 1.072642894s (>500ms):
n4.log:W180126 16:48:58.957878 287 storage/engine/rocksdb.go:1704  batch [129/15091/0] commit took 958.393679ms (>500ms):
n4.log:W180126 16:48:59.883653 267 storage/engine/rocksdb.go:1704  batch [215/44800/0] commit took 925.054623ms (>500ms):
n4.log:W180126 16:49:02.619527 241 storage/engine/rocksdb.go:1704  batch [52/7696/0] commit took 2.735415619s (>500ms):
n4.log:W180126 16:49:05.262178 252 storage/engine/rocksdb.go:1704  batch [36/4848/0] commit took 2.171360677s (>500ms):
n4.log:W180126 16:49:07.367609 238 storage/engine/rocksdb.go:1704  batch [78/9722/0] commit took 1.807436604s (>500ms):
n4.log:W180126 16:49:07.963911 268 storage/engine/rocksdb.go:1704  batch [334/23648/0] commit took 595.520673ms (>500ms):
n4.log:W180126 16:49:09.411984 287 storage/engine/rocksdb.go:1704  batch [72/13532/0] commit took 1.447604552s (>500ms):
n4.log:W180126 16:49:10.240160 268 storage/engine/rocksdb.go:1704  batch [207/32945/0] commit took 827.713723ms (>500ms):
n4.log:W180126 16:49:12.252711 241 storage/engine/rocksdb.go:1704  batch [56/8839/0] commit took 2.012081687s (>500ms):
n4.log:W180126 16:49:12.797016 242 storage/engine/rocksdb.go:1704  batch [462/35588/0] commit took 543.911661ms (>500ms):
n4.log:W180126 16:49:14.970354 253 storage/engine/rocksdb.go:1704  batch [59/7144/0] commit took 2.172784341s (>500ms):
n4.log:W180126 16:49:16.991645 248 storage/engine/rocksdb.go:1704  batch [49/5052/0] commit took 1.583415162s (>500ms):
n4.log:W180126 16:49:18.827108 274 storage/engine/rocksdb.go:1704  batch [50/8295/0] commit took 1.5226259s (>500ms):
n4.log:W180126 16:49:19.335274 242 storage/engine/rocksdb.go:1704  batch [179/22878/0] commit took 507.370904ms (>500ms):
n4.log:W180126 16:49:20.732791 231 storage/engine/rocksdb.go:1704  batch [42/6497/0] commit took 1.397224556s (>500ms):
n4.log:W180126 16:49:22.569697 227 storage/engine/rocksdb.go:1704  batch [48/4210/0] commit took 1.438569678s (>500ms):
n4.log:W180126 16:49:24.037765 244 storage/engine/rocksdb.go:1704  batch [37/4643/0] commit took 1.208388098s (>500ms):
n4.log:W180126 16:49:27.273951 252 storage/engine/rocksdb.go:1704  batch [28/2247/0] commit took 2.947670824s (>500ms):
n4.log:W180126 16:49:29.752450 294 storage/store.go:1404  [n4,s4,r3/4:/System/NodeLiveness{-Max}] could not gossip node liveness: [NotLeaseHolderError] r3: replica (n4,s4):4 not lease holder; lease holder unknown
n4.log:W180126 16:49:31.620564 229 storage/engine/rocksdb.go:1704  batch [33/2440/0] commit took 577.950163ms (>500ms):
n4.log:W180126 16:49:32.443470 260 storage/engine/rocksdb.go:1704  batch [31/3669/0] commit took 671.46029ms (>500ms):
n4.log:W180126 16:49:34.003685 257 storage/engine/rocksdb.go:1704  batch [29/3396/0] commit took 1.334259726s (>500ms):
n4.log:W180126 16:49:34.886508 145 storage/engine/rocksdb.go:1704  batch [38/2276/0] commit took 674.056194ms (>500ms):
n4.log:W180126 16:49:35.811124 280 storage/engine/rocksdb.go:1704  batch [42/2793/0] commit took 780.171403ms (>500ms):
n4.log:W180126 16:49:37.296376 249 storage/engine/rocksdb.go:1704  batch [48/3090/0] commit took 648.611911ms (>500ms):
n4.log:W180126 16:49:38.138161 281 storage/engine/rocksdb.go:1704  batch [22/2500/0] commit took 652.299967ms (>500ms):
n4.log:W180126 16:49:39.031778 280 storage/engine/rocksdb.go:1704  batch [27/7639/0] commit took 739.211118ms (>500ms):
n4.log:W180126 16:49:40.029827 280 storage/engine/rocksdb.go:1704  batch [59/5343/0] commit took 529.789343ms (>500ms):
n4.log:W180126 16:49:44.884975 240 storage/engine/rocksdb.go:1704  batch [59/11256/0] commit took 569.243449ms (>500ms):
n4.log:W180126 16:49:45.573008 237 storage/engine/rocksdb.go:1704  batch [116/18314/0] commit took 687.676521ms (>500ms):
n4.log:W180126 16:49:46.692026 255 storage/engine/rocksdb.go:1704  batch [58/8451/0] commit took 1.118661552s (>500ms):
n4.log:W180126 16:49:47.209370 245 storage/engine/rocksdb.go:1704  batch [97/10847/0] commit took 517.042163ms (>500ms):
n4.log:W180126 16:49:47.872524 271 storage/engine/rocksdb.go:1704  batch [39/2541/0] commit took 662.526535ms (>500ms):
n4.log:W180126 16:49:48.669592 268 storage/engine/rocksdb.go:1704  batch [30/4766/0] commit took 640.417323ms (>500ms):
n4.log:W180126 16:49:49.925003 276 storage/engine/rocksdb.go:1704  batch [45/10495/0] commit took 790.972524ms (>500ms):
n4.log:W180126 16:49:50.569861 254 storage/engine/rocksdb.go:1704  batch [51/3954/0] commit took 644.485005ms (>500ms):
n4.log:W180126 16:49:53.761452 245 storage/engine/rocksdb.go:1704  batch [72/5030/0] commit took 618.633419ms (>500ms):
n4.log:W180126 16:49:54.661524 253 storage/engine/rocksdb.go:1704  batch [66/4640/0] commit took 590.873085ms (>500ms):
n4.log:W180126 16:49:59.502853 252 storage/engine/rocksdb.go:1704  batch [95/8066/0] commit took 834.549892ms (>500ms):
n4.log:W180126 16:50:00.979725 273 storage/engine/rocksdb.go:1704  batch [65/4722/0] commit took 645.750357ms (>500ms):
n4.log:W180126 16:50:01.847400 236 storage/engine/rocksdb.go:1704  batch [50/6476/0] commit took 577.870774ms (>500ms):
n4.log:W180126 16:50:02.918478 246 storage/engine/rocksdb.go:1704  batch [24/1484/0] commit took 671.031955ms (>500ms):
n4.log:W180126 16:50:05.043434 263 storage/engine/rocksdb.go:1704  batch [92/14022/0] commit took 582.214524ms (>500ms):
n4.log:W180126 16:50:05.901131 281 storage/engine/rocksdb.go:1704  batch [93/9291/0] commit took 857.278438ms (>500ms):
n4.log:W180126 16:50:06.470077 258 storage/engine/rocksdb.go:1704  batch [126/11349/0] commit took 568.59994ms (>500ms):
n4.log:W180126 16:50:07.166622 275 storage/engine/rocksdb.go:1704  batch [90/12673/0] commit took 696.222395ms (>500ms):
n4.log:W180126 16:50:07.941882 273 storage/engine/rocksdb.go:1704  batch [79/14402/0] commit took 774.98094ms (>500ms):
n4.log:W180126 16:50:08.822322 283 storage/engine/rocksdb.go:1704  batch [89/10106/0] commit took 880.114203ms (>500ms):
n4.log:W180126 16:50:09.441015 266 storage/engine/rocksdb.go:1704  batch [121/13118/0] commit took 618.207987ms (>500ms):
n4.log:W180126 16:50:10.242871 270 storage/engine/rocksdb.go:1704  batch [142/19836/0] commit took 801.405749ms (>500ms):
n4.log:W180126 16:50:11.455708 240 storage/engine/rocksdb.go:1704  batch [90/17696/0] commit took 1.212404231s (>500ms):
n4.log:W180126 16:50:12.540313 259 storage/engine/rocksdb.go:1704  batch [151/42552/0] commit took 1.084210604s (>500ms):
n4.log:W180126 16:50:15.139237 257 storage/engine/rocksdb.go:1704  batch [103/18948/0] commit took 2.598631658s (>500ms):
n4.log:W180126 16:50:16.300373 266 storage/engine/rocksdb.go:1704  batch [193/27850/0] commit took 1.160792589s (>500ms):
n4.log:W180126 16:50:18.002638 245 storage/engine/rocksdb.go:1704  batch [219/32764/0] commit took 1.701396041s (>500ms):
n4.log:W180126 16:50:20.004196 280 storage/engine/rocksdb.go:1704  batch [142/15228/0] commit took 2.000912336s (>500ms):
n4.log:W180126 16:50:20.938571 277 storage/engine/rocksdb.go:1704  batch [147/24972/0] commit took 934.08604ms (>500ms):
n4.log:W180126 16:50:22.464107 280 storage/engine/rocksdb.go:1704  batch [160/36175/0] commit took 1.525128294s (>500ms):
n4.log:W180126 16:50:24.673164 276 storage/engine/rocksdb.go:1704  batch [146/22188/0] commit took 2.208700108s (>500ms):
n4.log:W180126 16:50:26.032261 287 storage/engine/rocksdb.go:1704  batch [118/13946/0] commit took 1.358744928s (>500ms):
n4.log:W180126 16:50:26.885123 258 storage/engine/rocksdb.go:1704  batch [266/26036/0] commit took 852.481943ms (>500ms):
n4.log:W180126 16:50:28.476089 266 storage/engine/rocksdb.go:1704  batch [131/16083/0] commit took 1.590651965s (>500ms):
n4.log:W180126 16:50:29.459088 254 storage/engine/rocksdb.go:1704  batch [136/17147/0] commit took 982.637102ms (>500ms):
n4.log:W180126 16:50:29.803401 294 storage/replica.go:1533  [n4,s4,r3/4:/System/NodeLiveness{-Max}] have been waiting 1m0s attempting to acquire lease
n4.log:W180126 16:50:30.510396 266 storage/engine/rocksdb.go:1704  batch [133/20195/0] commit took 1.050941913s (>500ms):
n4.log:W180126 16:50:31.745295 254 storage/engine/rocksdb.go:1704  batch [165/18085/0] commit took 1.234484952s (>500ms):
n4.log:W180126 16:50:32.850276 282 storage/engine/rocksdb.go:1704  batch [122/11412/0] commit took 1.104666873s (>500ms):
n4.log:W180126 16:50:33.548269 280 storage/engine/rocksdb.go:1704  batch [174/18160/0] commit took 697.520854ms (>500ms):
n4.log:W180126 16:50:34.661693 259 storage/engine/rocksdb.go:1704  batch [126/14773/0] commit took 1.113098252s (>500ms):
n4.log:W180126 16:50:35.565182 238 storage/engine/rocksdb.go:1704  batch [177/36541/0] commit took 903.079958ms (>500ms):
n4.log:W180126 16:50:37.796839 277 storage/engine/rocksdb.go:1704  batch [125/25166/0] commit took 2.231392605s (>500ms):
n4.log:W180126 16:50:39.337842 247 storage/engine/rocksdb.go:1704  batch [176/34074/0] commit took 1.540482878s (>500ms):
n4.log:W180126 16:50:41.418648 246 storage/engine/rocksdb.go:1704  batch [113/14567/0] commit took 2.080473333s (>500ms):
n4.log:W180126 16:50:42.309514 243 storage/engine/rocksdb.go:1704  batch [200/20375/0] commit took 890.342825ms (>500ms):
n4.log:W180126 16:50:43.557512 265 storage/engine/rocksdb.go:1704  batch [73/7823/0] commit took 1.247689461s (>500ms):
n4.log:W180126 16:50:45.513948 244 storage/engine/rocksdb.go:1704  batch [24/1764/0] commit took 1.476688433s (>500ms):
n4.log:W180126 16:50:47.022850 280 storage/engine/rocksdb.go:1704  batch [188/31909/0] commit took 1.396575099s (>500ms):
n4.log:W180126 16:50:48.975337 281 storage/engine/rocksdb.go:1704  batch [84/19170/0] commit took 1.951840146s (>500ms):
n4.log:W180126 16:50:50.146791 261 storage/engine/rocksdb.go:1704  batch [288/26416/0] commit took 1.170988484s (>500ms):
n4.log:W180126 16:50:51.760311 276 storage/engine/rocksdb.go:1704  batch [79/7171/0] commit took 1.6132358s (>500ms):
n4.log:W180126 16:50:53.448478 243 storage/engine/rocksdb.go:1704  batch [74/7958/0] commit took 1.245109019s (>500ms):
n4.log:W180126 16:50:55.104466 284 storage/engine/rocksdb.go:1704  batch [40/4160/0] commit took 1.167782321s (>500ms):
n4.log:W180126 16:50:55.950255 250 storage/engine/rocksdb.go:1704  batch [21/1850/0] commit took 590.119509ms (>500ms):
n4.log:W180126 16:50:56.717583 257 storage/engine/rocksdb.go:1704  batch [3/138/0] commit took 649.252182ms (>500ms):
n4.log:W180126 16:50:57.596438 270 storage/engine/rocksdb.go:1704  batch [4/356/0] commit took 554.721891ms (>500ms):
n4.log:W180126 16:50:58.949691 236 storage/engine/rocksdb.go:1704  batch [7/506/0] commit took 505.606755ms (>500ms):
n4.log:W180126 16:50:59.918758 279 storage/engine/rocksdb.go:1704  batch [3/237/0] commit took 936.553423ms (>500ms):
n4.log:W180126 16:51:01.167878 258 storage/engine/rocksdb.go:1704  batch [1/62/0] commit took 1.233179435s (>500ms):
n4.log:W180126 16:51:02.227013 258 storage/engine/rocksdb.go:1704  batch [2/112/0] commit took 1.057740621s (>500ms):
n4.log:W180126 16:51:03.584182 258 storage/engine/rocksdb.go:1704  batch [6/321/0] commit took 1.354650469s (>500ms):
n4.log:W180126 16:51:04.397165 145 storage/engine/rocksdb.go:1704  batch [14/1015/0] commit took 791.498585ms (>500ms):
n4.log:W180126 16:51:05.841413 258 storage/engine/rocksdb.go:1704  batch [21/1227/0] commit took 1.380100574s (>500ms):
n4.log:W180126 16:51:06.804580 280 storage/engine/rocksdb.go:1704  batch [25/1857/0] commit took 883.779602ms (>500ms):
n4.log:W180126 16:51:08.495176 228 storage/engine/rocksdb.go:1704  batch [15/6807/0] commit took 1.575544358s (>500ms):
n4.log:W180126 16:51:10.583017 228 storage/engine/rocksdb.go:1704  batch [26/1628/0] commit took 918.915056ms (>500ms):
n4.log:W180126 16:51:17.556614 280 storage/engine/rocksdb.go:1704  batch [52/11203/0] commit took 1.205586613s (>500ms):
n4.log:W180126 16:51:18.241724 278 storage/engine/rocksdb.go:1704  batch [34/3572/0] commit took 684.820508ms (>500ms):
n4.log:W180126 16:51:19.036180 267 storage/engine/rocksdb.go:1704  batch [48/6529/0] commit took 572.541178ms (>500ms):
n4.log:W180126 16:51:20.142810 265 storage/engine/rocksdb.go:1704  batch [158/6359/0] commit took 706.360158ms (>500ms):
n4.log:W180126 16:51:22.212120 231 storage/engine/rocksdb.go:1704  batch [41/3153/0] commit took 1.135947315s (>500ms):
n4.log:W180126 16:51:23.794174 253 storage/engine/rocksdb.go:1704  batch [61/4451/0] commit took 587.388753ms (>500ms):
n4.log:W180126 16:51:25.077860 282 storage/engine/rocksdb.go:1704  batch [55/4306/0] commit took 1.010312312s (>500ms):
n4.log:W180126 16:51:25.876585 271 storage/engine/rocksdb.go:1704  batch [46/3495/0] commit took 533.472448ms (>500ms):
n4.log:I180126 16:51:27.543102 680357 storage/replica_raftstorage.go:746  [n4,s4,r3/4:/System/NodeLiveness{-Max}] applying Raft snapshot at index 3536938 (id=111407ed, encoded size=140113, 1 rocksdb batches, 236 log entries)
n4.log:I180126 16:51:28.275563 680357 storage/replica_raftstorage.go:752  [n4,s4,r3/4:/System/NodeLiveness{-Max}] applied Raft snapshot in 732ms [clear=44ms batch=0ms entries=1ms commit=687ms]
n4.log:W180126 16:51:41.812488 268 storage/engine/rocksdb.go:1704  batch [52/4987/0] commit took 13.540130857s (>500ms):
n4.log:W180126 16:51:44.269745 282 storage/engine/rocksdb.go:1704  batch [55/7085/0] commit took 505.568444ms (>500ms):
n4.log:W180126 16:51:45.707622 241 storage/engine/rocksdb.go:1704  batch [45/2687/0] commit took 503.746603ms (>500ms):
n4.log:I180126 16:51:45.913219 680434 storage/replica_raftstorage.go:746  [n4,s4,r3/4:/System/NodeLiveness{-Max}] applying Raft snapshot at index 3536962 (id=d4da6540, encoded size=44429, 1 rocksdb batches, 19 log entries)
n4.log:I180126 16:51:46.254005 680434 storage/replica_raftstorage.go:752  [n4,s4,r3/4:/System/NodeLiveness{-Max}] applied Raft snapshot in 341ms [clear=39ms batch=0ms entries=0ms commit=300ms]
n4.log:W180126 16:51:50.693883 267 storage/engine/rocksdb.go:1704  batch [50/3460/0] commit took 4.441965305s (>500ms):
n4.log:W180126 16:51:50.954560 680421 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 5bd0de47], BeginTransaction [/System/NodeLiveness/3,/Min), ConditionalPut [/System/NodeLiveness/3,/Min), EndTransaction [/System/NodeLiveness/3,/Min)
n4.log:W180126 16:51:52.044307 680435 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 86ce62e4], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:51:52.620855 274 storage/engine/rocksdb.go:1704  batch [43/2650/0] commit took 502.55179ms (>500ms):
n4.log:W180126 16:51:52.823829 680364 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 0ff0ab81], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
n4.log:W180126 16:51:53.370829 680424 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 37446a18], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
n4.log:W180126 16:51:54.074640 680365 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: f4833906], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:51:55.671420 286 storage/engine/rocksdb.go:1704  batch [55/4103/0] commit took 561.350936ms (>500ms):
n4.log:W180126 16:51:56.544900 680427 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 8228ba1e], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
n4.log:W180126 16:51:59.105505 243 storage/engine/rocksdb.go:1704  batch [3/237/0] commit took 1.564807786s (>500ms):
n4.log:W180126 16:52:00.434151 263 storage/engine/rocksdb.go:1704  batch [1/364/0] commit took 1.312241705s (>500ms):
n4.log:W180126 16:52:02.372106 681417 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: bf3ad2c6], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
n4.log:W180126 16:52:03.075896 681699 storage/replica.go:2810  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context cancellation after 4.5s of attempting command [txn: 953b0f09], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:52:07.576407 681909 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 479e10a9], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:52:11.500235 263 storage/engine/rocksdb.go:1704  batch [64/21364/0] commit took 11.041257992s (>500ms):
n4.log:W180126 16:52:12.076926 681884 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 9de61d00], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:52:12.805423 234 storage/engine/rocksdb.go:1704  batch [258/62837/0] commit took 1.30495311s (>500ms):
n4.log:W180126 16:52:16.577345 681927 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 42401bbd], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:52:16.641455 263 storage/engine/rocksdb.go:1704  batch [18/1452/0] commit took 3.835732412s (>500ms):
n4.log:W180126 16:52:17.734225 263 storage/engine/rocksdb.go:1704  batch [133/10055/0] commit took 997.731988ms (>500ms):
n4.log:W180126 16:52:18.349800 235 storage/engine/rocksdb.go:1704  batch [74/7852/0] commit took 614.449379ms (>500ms):
n4.log:W180126 16:52:21.077821 681932 storage/replica.go:2252  [n4,s4,r3/4:/System/NodeLiveness{-Max}] context deadline exceeded while in command queue: [txn: 6aea1682], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
n4.log:W180126 16:52:21.218729 267 storage/engine/rocksdb.go:1704  batch [162/20221/0] commit took 2.382938003s (>500ms):
n4.log:W180126 16:52:22.454344 272 storage/engine/rocksdb.go:1704  batch [70/5288/0] commit took 1.235356676s (>500ms):
n4.log:W180126 16:52:29.341690 281 storage/engine/rocksdb.go:1704  batch [195/37812/0] commit took 6.555156423s (>500ms):
n4.log:W180126 16:52:31.651484 235 storage/engine/rocksdb.go:1704  batch [283/71825/0] commit took 2.308841471s (>500ms):
n4.log:W180126 16:52:36.038048 252 storage/engine/rocksdb.go:1704  batch [92/6720/0] commit took 4.385384337s (>500ms):
n4.log:W180126 16:52:37.886731 241 storage/engine/rocksdb.go:1704  batch [99/6799/0] commit took 501.173482ms (>500ms):
n4.log:W180126 16:52:38.911004 262 storage/engine/rocksdb.go:1704  batch [71/5091/0] commit took 605.32135ms (>500ms):
n4.log:W180126 16:52:39.801557 226 storage/engine/rocksdb.go:1704  batch [81/5710/0] commit took 577.709414ms (>500ms):
n4.log:W180126 16:52:40.900141 269 storage/engine/rocksdb.go:1704  batch [75/5461/0] commit took 746.038374ms (>500ms):
n4.log:W180126 16:52:41.851046 229 storage/engine/rocksdb.go:1704  batch [72/5236/0] commit took 616.074777ms (>500ms):
n4.log:W180126 16:52:42.775674 229 storage/engine/rocksdb.go:1704  batch [73/5279/0] commit took 603.651993ms (>500ms):
n4.log:W180126 16:52:43.775296 248 storage/engine/rocksdb.go:1704  batch [75/5456/0] commit took 676.09998ms (>500ms):
n4.log:W180126 16:52:44.782583 229 storage/engine/rocksdb.go:1704  batch [60/4356/0] commit took 671.109559ms (>500ms):
n4.log:W180126 16:52:45.775577 231 storage/engine/rocksdb.go:1704  batch [50/3668/0] commit took 723.648699ms (>500ms):
n4.log:W180126 16:52:46.804229 257 storage/engine/rocksdb.go:1704  batch [60/4384/0] commit took 798.80428ms (>500ms):
n4.log:W180126 16:52:47.754023 263 storage/engine/rocksdb.go:1704  batch [53/3846/0] commit took 676.626747ms (>500ms):
n4.log:W180126 16:52:48.790561 258 storage/engine/rocksdb.go:1704  batch [37/2651/0] commit took 796.308097ms (>500ms):
n4.log:W180126 16:52:49.793490 262 storage/engine/rocksdb.go:1704  batch [36/2609/0] commit took 838.726528ms (>500ms):
n4.log:W180126 16:52:50.847859 266 storage/engine/rocksdb.go:1704  batch [35/2567/0] commit took 893.370946ms (>500ms):
n4.log:W180126 16:52:51.953964 246 storage/engine/rocksdb.go:1704  batch [44/3214/0] commit took 946.058421ms (>500ms):
n4.log:W180126 16:52:53.166670 246 storage/engine/rocksdb.go:1704  batch [50/3905/0] commit took 1.013155072s (>500ms):
n4.log:W180126 16:52:54.266303 282 storage/engine/rocksdb.go:1704  batch [82/6228/0] commit took 856.570054ms (>500ms):
n4.log:W180126 16:52:55.162621 258 storage/engine/rocksdb.go:1704  batch [114/9599/0] commit took 511.369221ms (>500ms):
n4.log:W180126 16:52:55.750298 254 storage/engine/rocksdb.go:1704  batch [92/8227/0] commit took 586.433026ms (>500ms):
n4.log:W180126 16:52:56.254900 145 storage/engine/rocksdb.go:1704  batch [122/9169/0] commit took 503.294487ms (>500ms):
n4.log:W180126 16:52:56.815471 254 storage/engine/rocksdb.go:1704  batch [100/8320/0] commit took 560.124729ms (>500ms):
n4.log:W180126 16:52:57.326322 229 storage/engine/rocksdb.go:1704  batch [104/8123/0] commit took 508.114862ms (>500ms):
n4.log:W180126 16:52:59.672584 270 storage/engine/rocksdb.go:1704  batch [75/7549/0] commit took 704.660736ms (>500ms):
n4.log:W180126 16:53:00.757437 286 storage/engine/rocksdb.go:1704  batch [66/6622/0] commit took 621.582201ms (>500ms):
n5.log:I180126 16:51:27.085380 176 storage/replica_raftstorage.go:540  [raftsnapshot,n5,s5,r3/5:/System/NodeLiveness{-Max}] generated Raft snapshot 111407ed at index 3536938
n5.log:I180126 16:51:27.118116 176 storage/store.go:3670  [raftsnapshot,n5,s5,r3/5:/System/NodeLiveness{-Max}] streamed snapshot to (n4,s4):4: kv pairs: 801, log entries: 236, rate-limit: 8.0 MiB/sec, 33ms
n5.log:I180126 16:51:45.874990 176 storage/replica_raftstorage.go:540  [raftsnapshot,n5,s5,r3/5:/System/NodeLiveness{-Max}] generated Raft snapshot d4da6540 at index 3536962
n5.log:I180126 16:51:45.912230 176 storage/store.go:3670  [raftsnapshot,n5,s5,r3/5:/System/NodeLiveness{-Max}] streamed snapshot to (n4,s4):4: kv pairs: 820, log entries: 19, rate-limit: 8.0 MiB/sec, 37ms

@tbg tbg assigned a-robinson and unassigned tbg Feb 8, 2018
@petermattis petermattis added this to the 2.0 milestone Feb 21, 2018
@petermattis
Copy link
Collaborator

@nvanbenschoten Didn't you introduce (and later fix) a bug regarding failed heartbeats around this time?

@nvanbenschoten
Copy link
Member

@petermattis are you referring to #22636 (comment)? If so, I don't think this issue is related. Here, the liveness heartbeats are very slow. In that issue, they were all failing with the error heartbeat failed on epoch increment.

@petermattis
Copy link
Collaborator

@nvanbenschoten Yeah, #22636 was the issue I was thinking of.

@a-robinson
Copy link
Contributor

Sorry for letting this slip by!

@leomkkwan by any chance have you upgraded to a more recent alpha release since the issue was reported or seen anything like this again? Also, there isn't much network latency between the nodes, is there?

It looks like there may be a leader-not-leaseholder situation, judging by the fact that n4 has all the messages indicating it's the leaseholder for r3, but both n1 and n5 had to send n4 raft snapshots for r3 at different points in time. It's hard to explain the crazy amount of raft log activity without any additional info about what was going on in the cluster at the time, though.

@a-robinson
Copy link
Contributor

Any interest in providing more detail, @leomkkwan?

@leomkkwan
Copy link

The cluster was destroyed the morning.
The latest status for that cluster

  • Upgraded to v2.0-beta.20180305.
  • The constant CPU load and read/write action was fixed.
  • The Consistnecy Checker Queue was stuck. There was 32K pending action in queue, and 0 action/seconds for last week.
  • The Compaction Queue was stuck. The is pending bytes in queue, but no action.

Because there is a few withdraw in the alpha and we did upgraded for all versions, therefore we decided that the cluster was broken and start from scratch from Beta.

We are rebuilding the clusters and if we see this issue again, I will update this ticket.

Thanks,

Leo

@a-robinson a-robinson modified the milestones: 2.0, 2.1 Mar 13, 2018
@leomkkwan
Copy link

Just an update here. The cluster was rebuilt using v2.0, and reload all data into the cluster.

The Consistency Checker Queue and Compaction Queue are stuck. There was pending action in queue, but 0 action/seconds.

Am I broke the cluster (again)? How can I un-stuck the queue?

queue stuck

@tbg
Copy link
Member

tbg commented Apr 19, 2018

@leomkkwan sorry about letting this sit. How did these graphs change since your message?

@leomkkwan
Copy link

No change. Consistency Checker Queue and Compaction Queue are flat for the last week.

A little history about this clusters..
5 nodes cluster from group up with v2.0-beta.20180305. After import around 400GB of data, I did an upgrade to v2.0. The problem exists in 20180305 beta, and getting worst? or stablize once upgrade to v2.0.

queue stuck 0419-1month

Also include log file for all nodes, the only one looks interesting to me is in n5.log which it spam with the line
[n5,ts-srv] stopper throttling task from ts.Server: query due to semaphore

n3.log
n4.log
n1.log
n2.log
n5.log

Hope this help. I am not a enterprise customer yet and I spent three weeks to import data back to the cluster. If there is anyway I can recovery from this without needing to rebuild the data will be appreciated.

@a-robinson
Copy link
Contributor

The query due to semaphore log is meaningless. See #24512 for details, but it has since been removed.

The compaction queue having a large number of pending bytes does not mean anything is wrong. The compaction queue can happily queue up a large amount of potential bytes without acting on them if they don't meet certain conditions around having large contiguous chunks of reclaimable space or the node being low on disk space.

The consistency checker queue being stuck is weirder. I can't think of any occasions in which we've seen something like that before. I have a few follow-up questions and things for you to check:

  • Are you seeing any actual behavioral problems with your cluster or is it just these two graphs that look weird?
  • Would you mind checking out these couple graphs in the per-node views (by clicking on the "Graph: Cluster" dropdown) to see if there are pending replicas on all nodes or just on one?
  • Could you grab a stack dump on one or more of the nodes with a lot of pending consistency queue replicas? You can get it from the /debug/pprof/goroutine?debug=2 HTTP endpoint.
  • Could you grab verbose logs about the consistency checker on one or more of the nodes with a lot of pending consistency queue replicas? You can get them from the /debug/logspy?count=10000&duration=60s&grep=replica%20consistency%20checker HTTP endpoint, but you'll have to wait for the specified duration of 60s for all the output to stream back to you.

@tbg
Copy link
Member

tbg commented Apr 24, 2018

Hi @leomkkwan, the logs look... actually really good, which is unfortunate since I was hoping to zero in on a root cause.

Could you send me a ./cockroach debug zip of the nodes? This may leak some information about the ranges such as range boundaries, etc, as well as your schema, so you could send it (or a link to it) to [email protected]. If you have concerns about sharing this data, I could also start looking at only these URLs:

  • /debug/requests?fam=tracing&b=-1&exp=1
  • /debug/pprof/goroutine?debug=2

@tbg tbg assigned tbg and unassigned a-robinson Apr 24, 2018
tbg added a commit to tbg/cockroach that referenced this issue May 13, 2018
When `CheckConsistency` returns an error, the queue checks whether the
store is draining to decide whether the error is worth logging.

Unfortunately this check was incorrect and would block until the store
actually started draining.

A toy example of this problem is below (this will deadlock). The dual
return form of chan receive isn't non-blocking -- the second parameter
indicates whether the received value corresponds to a closing of the
channel.

Switch to a `select` instead.

```
package main

import (
	"fmt"
)

func main() {
	ch := make(chan struct{})
	_, ok := <-ch
	fmt.Println(ok)
}
```

Touches cockroachdb#21824.

Release note (bug fix): Prevent the consistency checker from
deadlocking. This would previously manifest itself as a steady number of
replicas queued for consistency checking on one or more nodes and would
resolve by restarting the affected nodes.
@tbg tbg added the S-2-temp-unavailability Temp crashes or other availability problems. Can be worked around or resolved by restarting. label May 13, 2018
tbg added a commit to tbg/cockroach that referenced this issue May 14, 2018
When `CheckConsistency` returns an error, the queue checks whether the
store is draining to decide whether the error is worth logging.

Unfortunately this check was incorrect and would block until the store
actually started draining.

A toy example of this problem is below (this will deadlock). The dual
return form of chan receive isn't non-blocking -- the second parameter
indicates whether the received value corresponds to a closing of the
channel.

Switch to a `select` instead.

```
package main

import (
	"fmt"
)

func main() {
	ch := make(chan struct{})
	_, ok := <-ch
	fmt.Println(ok)
}
```

Touches cockroachdb#21824.

Release note (bug fix): Prevent the consistency checker from
deadlocking. This would previously manifest itself as a steady number of
replicas queued for consistency checking on one or more nodes and would
resolve by restarting the affected nodes.
tbg added a commit to tbg/cockroach that referenced this issue May 14, 2018
When `CheckConsistency` returns an error, the queue checks whether the
store is draining to decide whether the error is worth logging.

Unfortunately this check was incorrect and would block until the store
actually started draining.

A toy example of this problem is below (this will deadlock). The dual
return form of chan receive isn't non-blocking -- the second parameter
indicates whether the received value corresponds to a closing of the
channel.

Switch to a `select` instead.

```
package main

import (
	"fmt"
)

func main() {
	ch := make(chan struct{})
	_, ok := <-ch
	fmt.Println(ok)
}
```

Touches cockroachdb#21824.

Release note (bug fix): Prevent the consistency checker from
deadlocking. This would previously manifest itself as a steady number of
replicas queued for consistency checking on one or more nodes and would
resolve by restarting the affected nodes.
tbg added a commit to tbg/cockroach that referenced this issue May 14, 2018
When `CheckConsistency` returns an error, the queue checks whether the
store is draining to decide whether the error is worth logging.

Unfortunately this check was incorrect and would block until the store
actually started draining.

A toy example of this problem is below (this will deadlock). The dual
return form of chan receive isn't non-blocking -- the second parameter
indicates whether the received value corresponds to a closing of the
channel.

Switch to a `select` instead.

```
package main

import (
	"fmt"
)

func main() {
	ch := make(chan struct{})
	_, ok := <-ch
	fmt.Println(ok)
}
```

Touches cockroachdb#21824.

Release note (bug fix): Prevent the consistency checker from
deadlocking. This would previously manifest itself as a steady number of
replicas queued for consistency checking on one or more nodes and would
resolve by restarting the affected nodes.
craig bot pushed a commit that referenced this issue May 14, 2018
25297: build: add roachtests to be run on every PR r=benesch,petermattis a=danhhz

Release note: None

25434: opt: Change how Any operator is represented and flattened r=andy-kimball a=andy-kimball

The Any operator currently takes a single input rowset, and expects
it to return a single boolean column. The hoister flattens the Any
operator by testing and projecting that boolean column. The problem
is that this representation cannot easily be decorrelated. Example:

   z = ANY(SELECT x FROM xy)

This is currently represented as:

  (Any (Project xy [ z=x ]))

The z=x projection field cannot easily be hoisted over a left join.
This commit uses an alternate representation:

  (Any xy z EqOp)

The new representation keeps the input, scalar, and comparison op
components separate, so they can be combined in ways that it easier
to decorrelate.

25456: storage: fix deadlock in consistency queue r=bdarnell,a-robinson a=tschottdorf

When `CheckConsistency` returns an error, the queue checks whether the
store is draining to decide whether the error is worth logging.

Unfortunately this check was incorrect and would block until the store
actually started draining.

A toy example of this problem is below (this will deadlock). The dual
return form of chan receive isn't non-blocking -- the second parameter
indicates whether the received value corresponds to a closing of the
channel.

Switch to a `select` instead.

```go
package main

import (
	"fmt"
)

func main() {
	ch := make(chan struct{})
	_, ok := <-ch
	fmt.Println(ok)
}
```

Touches #21824.

Release note (bug fix): Prevent the consistency checker from
deadlocking. This would previously manifest itself as a steady number of
replicas queued for consistency checking on one or more nodes and would
resolve by restarting the affected nodes.

Co-authored-by: Daniel Harrison <[email protected]>
Co-authored-by: Andrew Kimball <[email protected]>
Co-authored-by: Tobias Schottdorf <[email protected]>
tbg added a commit to tbg/cockroach that referenced this issue May 14, 2018
When `CheckConsistency` returns an error, the queue checks whether the
store is draining to decide whether the error is worth logging.

Unfortunately this check was incorrect and would block until the store
actually started draining.

A toy example of this problem is below (this will deadlock). The dual
return form of chan receive isn't non-blocking -- the second parameter
indicates whether the received value corresponds to a closing of the
channel.

Switch to a `select` instead.

```
package main

import (
	"fmt"
)

func main() {
	ch := make(chan struct{})
	_, ok := <-ch
	fmt.Println(ok)
}
```

Touches cockroachdb#21824.

Release note (bug fix): Prevent the consistency checker from
deadlocking. This would previously manifest itself as a steady number of
replicas queued for consistency checking on one or more nodes and would
resolve by restarting the affected nodes.
craig bot pushed a commit that referenced this issue May 14, 2018
25471: backport-2.0: rocksdb: use max_manifest_file_size option r=bdarnell a=tschottdorf

Backport 1/1 commits from #25341.

/cc @cockroachdb/release

---

Cockroach uses a single long running rocksdb instance for the entire
process lifetime, which could be many months. By default, rocksdb tracks
filesystem state changes in a log file called the MANIFEST, which grows
without bound until the instance is re-opened. We should bound the
maximum file size of rocksdb MANIFEST using the corresponding rocksdb
option to prevent unbounded growth.

The MANIFEST file grew to several GBs in size in a customer bug report
but that was probably because of some other bad behavior in rocksdb
state management. We do want to bound the MANIFEST size in such cases as
well.

Release note: None


25474: backport-2.0: storage: fix deadlock in consistency queue r=bdarnell a=tschottdorf

Backport 1/1 commits from #25456.

/cc @cockroachdb/release

---

When `CheckConsistency` returns an error, the queue checks whether the
store is draining to decide whether the error is worth logging.

Unfortunately this check was incorrect and would block until the store
actually started draining.

A toy example of this problem is below (this will deadlock). The dual
return form of chan receive isn't non-blocking -- the second parameter
indicates whether the received value corresponds to a closing of the
channel.

Switch to a `select` instead.

```go
package main

import (
	"fmt"
)

func main() {
	ch := make(chan struct{})
	_, ok := <-ch
	fmt.Println(ok)
}
```

Touches #21824.

Release note (bug fix): Prevent the consistency checker from
deadlocking. This would previously manifest itself as a steady number of
replicas queued for consistency checking on one or more nodes and would
resolve by restarting the affected nodes.


Co-authored-by: Garvit Juniwal <[email protected]>
Co-authored-by: Tobias Schottdorf <[email protected]>
@tbg
Copy link
Member

tbg commented May 23, 2018

@leomkkwan, are you still seeing the consistency checker problem?
edit: you would only not see this problem any more if you upgraded to at least v2.0.2 (https://www.cockroachlabs.com/docs/releases/v2.0.2.html).

@leomkkwan
Copy link

Updated to v2.0.2 yesterday. Consistency Checker problem is fixed. Woo. Thank you~~

consistency checker queue

Compaction Queue's problem seems to be fixed also once I did another round of rolling restart of each nodes.

Thank you so much!

tbg added a commit to tbg/cockroach that referenced this issue May 24, 2018
The compactor had an optimization that would stop the compactor loop
when no work was to be done.

Unfortunately, the condition to probe this was incorrect. Essentially,
whenever *any* work had been done, the loop stopped and would not
reawaken until the next incoming suggestion. In the absence of such a
suggestion, the skipped existing suggestions would never be revisited,
and thus never discarded. This created confusion as it kept the "queued
bytes" metric up.

Refactor the code so that instead of stopping, the loop waits for the
max age before running again (except if there are further suggestions).

It's hard to use timers correctly, so this commit should be scrutinized.
In particular, whether it's correct to call `t.Reset` in a select that
does not read from the timer's channel.

The test change makes `make test PKG=./pkg/storage/compactor` fail
every time on my machine before the fix.

I would suggest not backporting this, at least not until there is a
follow-up bugfix that needs backporting and doesn't apply cleanly on top
of this diff.

Fixes cockroachdb#21824.

Release note (bug fix): Expired compaction suggestions are now dropped
not too soon after they expire. Previously, this could be delayed
indefinitely.
tbg added a commit to tbg/cockroach that referenced this issue May 28, 2018
The compactor had an optimization that would stop the compactor loop
when no work was to be done.

Unfortunately, the condition to probe this was incorrect. Essentially,
whenever *any* work had been done, the loop stopped and would not
reawaken until the next incoming suggestion. In the absence of such a
suggestion, the skipped existing suggestions would never be revisited,
and thus never discarded. This created confusion as it kept the "queued
bytes" metric up.

Refactor the code so that instead of stopping, the loop waits for the
max age before running again (except if there are further suggestions).

It's hard to use timers correctly, so this commit should be scrutinized.
In particular, whether it's correct to call `t.Reset` in a select that
does not read from the timer's channel.

The test change makes `make test PKG=./pkg/storage/compactor` fail
every time on my machine before the fix.

I would suggest not backporting this, at least not until there is a
follow-up bugfix that needs backporting and doesn't apply cleanly on top
of this diff.

Fixes cockroachdb#21824.

Release note (bug fix): Expired compaction suggestions are now dropped
not too soon after they expire. Previously, this could be delayed
indefinitely.
craig bot pushed a commit that referenced this issue May 28, 2018
26039: compactor: never stop the loop r=bdarnell a=tschottdorf

The compactor had an optimization that would stop the compactor loop when
no work was to be done.

Unfortunately, the condition to probe this was incorrect. Essentially,
whenever *any* work had been done, the loop stopped and would not reawaken
until the next incoming suggestion. In the absence of such a suggestion,
the skipped existing suggestions would never be revisited, and thus never
discarded. This created confusion as it kept the "queued bytes" metric up.

Refactor the code so that instead of stopping, the loop waits for the max
age before running again (except if there are further suggestions).

It's hard to use timers correctly, so this commit should be scrutinized. In
particular, whether it's correct to call `t.Reset` in a select that does
not read from the timer's channel.

The test change makes `make test PKG=./pkg/storage/compactor` fail every
time on my machine before the fix.

I would suggest not backporting this, at least not until there is a
follow-up bugfix that needs backporting and doesn't apply cleanly on top of
this diff.

Fixes #21824.

Release note (bug fix): Expired compaction suggestions are now dropped not
too soon after they expire. Previously, this could be delayed indefinitely.

Co-authored-by: Tobias Schottdorf <[email protected]>
craig bot pushed a commit that referenced this issue May 28, 2018
26039: compactor: never stop the loop r=bdarnell a=tschottdorf

The compactor had an optimization that would stop the compactor loop when
no work was to be done.

Unfortunately, the condition to probe this was incorrect. Essentially,
whenever *any* work had been done, the loop stopped and would not reawaken
until the next incoming suggestion. In the absence of such a suggestion,
the skipped existing suggestions would never be revisited, and thus never
discarded. This created confusion as it kept the "queued bytes" metric up.

Refactor the code so that instead of stopping, the loop waits for the max
age before running again (except if there are further suggestions).

It's hard to use timers correctly, so this commit should be scrutinized. In
particular, whether it's correct to call `t.Reset` in a select that does
not read from the timer's channel.

The test change makes `make test PKG=./pkg/storage/compactor` fail every
time on my machine before the fix.

I would suggest not backporting this, at least not until there is a
follow-up bugfix that needs backporting and doesn't apply cleanly on top of
this diff.

Fixes #21824.

Release note (bug fix): Expired compaction suggestions are now dropped not
too soon after they expire. Previously, this could be delayed indefinitely.

Co-authored-by: Tobias Schottdorf <[email protected]>
@craig craig bot closed this as completed in #26039 May 28, 2018
tbg added a commit to tbg/cockroach that referenced this issue Jun 12, 2018
The compactor had an optimization that would stop the compactor loop
when no work was to be done.

Unfortunately, the condition to probe this was incorrect. Essentially,
whenever *any* work had been done, the loop stopped and would not
reawaken until the next incoming suggestion. In the absence of such a
suggestion, the skipped existing suggestions would never be revisited,
and thus never discarded. This created confusion as it kept the "queued
bytes" metric up.

Refactor the code so that instead of stopping, the loop waits for the
max age before running again (except if there are further suggestions).

It's hard to use timers correctly, so this commit should be scrutinized.
In particular, whether it's correct to call `t.Reset` in a select that
does not read from the timer's channel.

The test change makes `make test PKG=./pkg/storage/compactor` fail
every time on my machine before the fix.

I would suggest not backporting this, at least not until there is a
follow-up bugfix that needs backporting and doesn't apply cleanly on top
of this diff.

Fixes cockroachdb#21824.

Release note (bug fix): Expired compaction suggestions are now dropped
not too soon after they expire. Previously, this could be delayed
indefinitely.
craig bot pushed a commit that referenced this issue Jun 12, 2018
26659: backport-2.0: compactor: never stop the loop r=bdarnell a=tschottdorf

Backport 2/2 commits from #26039.

/cc @cockroachdb/release

---

The compactor had an optimization that would stop the compactor loop when
no work was to be done.

Unfortunately, the condition to probe this was incorrect. Essentially,
whenever *any* work had been done, the loop stopped and would not reawaken
until the next incoming suggestion. In the absence of such a suggestion,
the skipped existing suggestions would never be revisited, and thus never
discarded. This created confusion as it kept the "queued bytes" metric up.

Refactor the code so that instead of stopping, the loop waits for the max
age before running again (except if there are further suggestions).

It's hard to use timers correctly, so this commit should be scrutinized. In
particular, whether it's correct to call `t.Reset` in a select that does
not read from the timer's channel.

The test change makes `make test PKG=./pkg/storage/compactor` fail every
time on my machine before the fix.

I would suggest not backporting this, at least not until there is a
follow-up bugfix that needs backporting and doesn't apply cleanly on top of
this diff.

Fixes #21824.

Release note (bug fix): Expired compaction suggestions are now dropped not
too soon after they expire. Previously, this could be delayed indefinitely.


Co-authored-by: Tobias Schottdorf <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-kv-distribution Relating to rebalancing and leasing. S-2-temp-unavailability Temp crashes or other availability problems. Can be worked around or resolved by restarting.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants