estimated_pending_compaction_bytes: 0 B
W180929 07:53:42.777245 38380 storage/node_liveness.go:504 [n1,s1,r602/1:/System/tsd/cr.store.{re…-va…}] slow heartbeat took 37.6s
W180929 07:53:42.931409 38441 storage/node_liveness.go:504 [n1,s1,r621/1:/System/tsd/cr.node.sql.mem.…] slow heartbeat took 37.4s
W180929 07:53:42.969618 38440 vendor/google.golang.org/grpc/server.go:961 grpc: Server.processUnaryRPC failed to write status connection error: desc = “transport is closing”
W180929 07:53:42.971897 369 storage/raft_transport.go:465 [n1] raft transport stream to node 2 failed: EOF
W180929 07:53:43.112798 38377 vendor/google.golang.org/grpc/server.go:961 grpc: Server.processUnaryRPC failed to write status connection error: desc = “transport is closing”
I180929 07:53:43.313318 38475 cli/start.go:730 15 running tasks
I180929 07:53:44.556683 38378 storage/node_liveness.go:716 [n1,s1,r601/1:/System/ts{d/cr.st…-e}] retrying liveness update after storage.errRetryLiveness: result is ambiguous (error=context canceled [exhausted])
W180929 07:53:46.103982 197 storage/engine/rocksdb.go:1805 batch [1/51/0] commit took 1.415596536s (>500ms):
goroutine 197 [running]:
runtime/debug.Stack(0x3a43cbd0, 0xed3412687, 0x0)
/usr/local/go/src/runtime/debug/stack.go:24 +0xa7
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0xc428f91200, 0xc425db6800, 0xc, 0x400)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1806 +0x128
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0xc428f91200, 0xed3412601, 0x0, 0x0)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1724 +0x7c0
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).handleRaftReadyRaftMuLocked(0xc42078ee00, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, …)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:3623 +0x5ae
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processRequestQueue.func1(0x27840c0, 0xc425b7ec30, 0xc42078ee00, 0x27840c0)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:3868 +0x109
github.com/cockroachdb/cockroach/pkg/storage.(*Store).withReplicaForRequest(0xc4204a2800, 0x27840c0, 0xc425b7ec30, 0xc425826888, 0xc427afded0, 0x0)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:3190 +0x135
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processRequestQueue(0xc4204a2800, 0x27840c0, 0xc4207855f0, 0x2a9)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:3856 +0x229
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc420a6e000, 0x27840c0, 0xc4207855f0)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:226 +0x21b
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2(0x27840c0, 0xc4207855f0)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:166 +0x3e
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc420522960, 0xc4201d6a20, 0xc420522950)
/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:196 +0xe9
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:189 +0xad
E180929 07:53:46.224798 38380 storage/replica_range_lease.go:282 [n1,s1,r602/1:/System/tsd/cr.store.{re…-va…}] context canceled
E180929 07:53:47.333065 38441 storage/replica_range_lease.go:282 [n1,s1,r621/1:/System/tsd/cr.node.sql.mem.…] context canceled
W180929 07:53:48.155558 265 storage/node_liveness.go:504 [n1,hb] slow heartbeat took 4.4s
I180929 07:53:48.158036 80 server/status/runtime.go:219 [n1] runtime stats: 955 MiB RSS, 227 goroutines, 122 MiB/35 MiB/185 MiB GO alloc/idle/total, 746 MiB/887 MiB CGO alloc/total, 9.11cgo/sec, 0.00/0.16 %(u/s)time, 0.00 %gc (0x)
I180929 07:53:49.411696 38475 cli/start.go:730 14 running tasks
W180929 07:53:49.799874 38378 storage/node_liveness.go:504 [n1,s1,r601/1:/System/ts{d/cr.st…-e}] slow heartbeat took 44.7s
W180929 07:53:51.146397 199 storage/store.go:3926 [n1,s1] handle raft ready: 12.1s [processed=0]
W180929 07:53:51.209300 178 storage/store.go:3926 [n1,s1] handle raft ready: 10.9s [processed=0]
W180929 07:53:51.209599 201 storage/store.go:3926 [n1,s1] handle raft ready: 10.4s [processed=0]
W180929 07:53:51.238634 228 storage/store.go:3926 [n1,s1] handle raft ready: 10.4s [processed=0]
W180929 07:53:51.327258 185 storage/store.go:3926 [n1,s1] handle raft ready: 12.2s [processed=0]
W180929 07:53:51.327352 211 storage/store.go:3926 [n1,s1] handle raft ready: 11.8s [processed=0]
W180929 07:53:51.522320 196 storage/store.go:3926 [n1,s1] handle raft ready: 12.4s [processed=0]
I180929 07:53:52.818008 38475 cli/start.go:730 12 running tasks
W180929 07:53:52.837556 208 storage/store.go:3926 [n1,s1] handle raft ready: 11.3s [processed=0]
W180929 07:53:52.846110 221 storage/store.go:3926 [n1,s1] handle raft ready: 11.1s [processed=0]
W180929 07:53:52.846403 205 storage/store.go:3926 [n1,s1] handle raft ready: 19.0s [processed=0]
W180929 07:53:52.864946 195 storage/store.go:3926 [n1,s1] handle raft ready: 13.8s [processed=0]
W180929 07:53:52.877117 265 storage/node_liveness.go:441 [n1,hb] failed node liveness heartbeat: context deadline exceeded
W180929 07:53:52.878366 183 storage/store.go:3926 [n1,s1] handle raft ready: 2.0s [processed=0]
E180929 07:53:53.311032 38378 storage/replica_range_lease.go:282 [n1,s1,r601/1:/System/ts{d/cr.st…-e}] context canceled
I180929 07:53:53.854333 38508 storage/raft_transport.go:459 [n1] raft transport stream to node 2 established
W180929 07:53:54.483819 212 storage/engine/rocksdb.go:1805 batch [1/61/0] commit took 1.01623909s (>500ms):
goroutine 212 [running]:
runtime/debug.Stack(0x165edc18, 0xed3412691, 0x0)
/usr/local/go/src/runtime/debug/stack.go:24 +0xa7
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0xc42614e480, 0x0, 0x1, 0xc42520e6f8)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1806 +0x128
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0xc42614e480, 0xed3412601, 0x0, 0x0)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1724 +0x7c0
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).handleRaftReadyRaftMuLocked(0xc420905500, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, …)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:3623 +0x5ae
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processRequestQueue.func1(0x27840c0, 0xc42508c480, 0xc420905500, 0x27840c0)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:3868 +0x109
github.com/cockroachdb/cockroach/pkg/storage.(*Store).withReplicaForRequest(0xc4204a2800, 0x27840c0, 0xc42508c480, 0xc4297f24e0, 0xc425a9ded0, 0x0)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:3190 +0x135
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processRequestQueue(0xc4204a2800, 0x27840c0, 0xc420a87dd0, 0x259)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:3856 +0x229
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc420a6e000, 0x27840c0, 0xc420a87dd0)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:226 +0x21b
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2(0x27840c0, 0xc420a87dd0)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:166 +0x3e
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc420522b40, 0xc4201d6a20, 0xc420522b30)
/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:196 +0xe9
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:189 +0xad
I180929 07:53:55.502223 80 server/status/runtime.go:219 [n1] runtime stats: 955 MiB RSS, 228 goroutines, 123 MiB/34 MiB/185 MiB GO alloc/idle/total, 747 MiB/887 MiB CGO alloc/total, 34.80cgo/sec, 0.00/0.13 %(u/s)time, 0.00 %gc (0x)
W180929 07:53:56.536483 38394 kv/dist_sender.go:1305 [ts-poll,n1] have been waiting 1m0s sending RPC to r604 (currently pending: [(n2,s2):3]) for batch: Merge [/System/tsd/cr.node.txn.aborts/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.commits/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.commits1PC/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.autoretries/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.abandons/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.durations-max/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.durations-p99.999/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.durations-p99.99/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.durations-p99.9/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.durations-p99/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.durations-p90/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.durations-p75/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.durations-p50/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.restarts-max/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.restarts-p99.999/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.restarts-p99.99/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.restarts-p99.9/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.restarts-p99/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.restarts-p90/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.node.txn.restarts-p75/1/10s/2018-09-29T07:00:00Z,/Min), … 31 skipped …, Merge [/System/tsd/cr.store.compactor.suggestionbytes.skipped/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.store.compactor.suggestionbytes.compacted/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.store.compactor.compactions.success/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.store.compactor.compactions.failure/1/10s/2018-09-29T07:00:00Z,/Min), Merge [/System/tsd/cr.store.compactor.compactingnanos/1/10s/2018-09-29T07:00:00Z,/Min)
I180929 07:53:57.452103 38475 cli/start.go:730 13 running tasks
W180929 07:54:00.390559 266 sql/jobs/registry.go:300 canceling all jobs due to liveness failure
W180929 07:54:03.233120 259 kv/dist_sender.go:1305 [txn=658f8a8c,n1] have been waiting 1m0s sending RPC to r7 (currently pending: [(n3,s3):2]) for batch: [txn: 658f8a8c], Get [/Table/3/1/108/2/1,/Min)