mirror of https://github.com/etcd-io/dbtester.git
README: add more logs
This commit is contained in:
Gyu-Ho Lee
parent
6c6ab8c19b
commit
092ce1d6e1
81
README.md
81
README.md
|
|
@ -21,6 +21,87 @@ All logs and results can be found at https://github.com/coreos/dbtester/tree/mas
|
|||
|
||||
|
||||
|
||||
<br><br><hr>
|
||||
##### Noticeable Warnings: Zookeeper
|
||||
|
||||
Snapshot, when writing 1-million entries (256-byte key, 1KB value value), with 300 concurrent clients
|
||||
|
||||
```
|
||||
# snapshot warnings
|
||||
grep -r -i fsync-ing\ the zookeeper-r3.4.9-java8-* | less
|
||||
|
||||
...
|
||||
java.lang.InterruptedException
|
||||
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
|
||||
at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
|
||||
at java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:339)
|
||||
at org.apache.zookeeper.server.quorum.LearnerHandler.shutdown(LearnerHandler.java:654)
|
||||
at org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:647)
|
||||
2017-02-06 22:02:19,388 [myid:2] - WARN [SyncThread:2:FileTxnLog@338] - fsync-ing the write ahead log in SyncThread:2 took 1083ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide
|
||||
2017-02-06 22:02:20,000 [myid:2] - INFO [SessionTracker:ZooKeeperServer@358] - Expiring session 0x15a15722a570038, timeout of 4000ms exceeded
|
||||
2017-02-06 22:02:20,526 [myid:2] - INFO [SessionTracker:ZooKeeperServer@358] - Expiring session 0x15a15722a570024, timeout of 4000ms exceeded
|
||||
2017-02-06 22:02:20,526 [myid:2] - INFO [SessionTracker:ZooKeeperServer@358] - Expiring session 0x15a15722a570051, timeout of 4000ms exceeded
|
||||
2017-02-06 22:02:20,526 [myid:2] - INFO [SessionTracker:ZooKeeperServer@358] - Expiring session 0x15a15722a570044, timeout of 4000ms exceeded
|
||||
2017-02-06 22:02:20,526 [myid:2] - INFO [SessionTracker:ZooKeeperServer@358] - Expiring session 0x15a15722a570037, timeout of 4000ms exceeded
|
||||
2017-02-06 22:02:20,526 [myid:2] - INFO [SessionTracker:ZooKeeperServer@358] - Expiring session 0x15a15722a570059, timeout of 4000ms exceeded
|
||||
2017-02-06 22:02:20,526 [myid:2] - INFO [SessionTracker:ZooKeeperServer@358] - Expiring session 0x15a15722a570039, timeout of 4000ms exceeded
|
||||
2017-02-06 22:02:20,526 [myid:2] - INFO [SessionTracker:ZooKeeperServer@358] - Expiring session 0x15a15722a570026, timeout of 4000ms exceeded
|
||||
2017-02-06 22:02:20,526 [myid:2] - INFO [SessionTracker:ZooKeeperServer@358] - Expiring session 0x15a15722a570013, timeout of 4000ms exceeded
|
||||
2017-02-06 22:02:20,526 [myid:2] - INFO [SessionTracker:ZooKeeperServer@358] - Expiring session 0x15a15722a57004f, timeout of 4000ms exceeded
|
||||
2017-02-06 22:02:20,527 [myid:2] - INFO [SessionTracker:ZooKeeperServer@358] - Expiring session 0x15a15722a57005b, timeout of 4000ms exceeded
|
||||
2017-02-06 22:02:20,527 [myid:2] - WARN [SyncThread:2:FileTxnLog@338] - fsync-ing the write ahead log in SyncThread:2 took 1023ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide
|
||||
...
|
||||
```
|
||||
|
||||
When writing more than 2-million entries (256-byte key, 1KB value value) with 300 concurrent clients
|
||||
|
||||
```
|
||||
# leader election
|
||||
grep -r -i election\ took zookeeper-r3.4.9-java8-* | less
|
||||
|
||||
...
|
||||
zookeeper-r3.4.9-java8-1-database.log:2017-02-06 15:15:50,966 [myid:1] - INFO [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@61] - FOLLOWING - LEADER ELECTION TOOK - 15202
|
||||
zookeeper-r3.4.9-java8-1-database.log:2017-02-06 15:16:14,346 [myid:1] - INFO [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@61] - FOLLOWING - LEADER ELECTION TOOK - 13354
|
||||
zookeeper-r3.4.9-java8-1-database.log:2017-02-06 15:16:24,781 [myid:1] - INFO [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@61] - FOLLOWING - LEADER ELECTION TOOK - 6426
|
||||
zookeeper-r3.4.9-java8-1-database.log:2017-02-06 15:16:48,327 [myid:1] - INFO [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@61] - FOLLOWING - LEADER ELECTION TOOK - 12808
|
||||
zookeeper-r3.4.9-java8-1-database.log:2017-02-06 15:16:55,542 [myid:1] - INFO [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@61] - FOLLOWING - LEADER ELECTION TOOK - 3207
|
||||
zookeeper-r3.4.9-java8-1-database.log:2017-02-06 15:17:19,225 [myid:1] - INFO [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@61] - FOLLOWING - LEADER ELECTION TOOK - 13652
|
||||
zookeeper-r3.4.9-java8-1-database.log:2017-02-06 15:17:37,581 [myid:1] - INFO [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@61] - FOLLOWING - LEADER ELECTION TOOK - 15147
|
||||
zookeeper-r3.4.9-java8-1-database.log:2017-02-06 15:18:01,784 [myid:1] - INFO [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@61] - FOLLOWING - LEADER ELECTION TOOK - 13368
|
||||
zookeeper-r3.4.9-java8-1-database.log:2017-02-06 15:18:20,758 [myid:1] - INFO [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@61] - FOLLOWING - LEADER ELECTION TOOK - 15025
|
||||
zookeeper-r3.4.9-java8-1-database.log:2017-02-06 15:18:43,963 [myid:1] - INFO [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@61] - FOLLOWING - LEADER ELECTION TOOK - 13176
|
||||
...
|
||||
```
|
||||
|
||||
|
||||
<br><br><hr>
|
||||
##### Noticeable Warnings: Consul
|
||||
|
||||
Snapshot, when writing 1-million entries (256-byte key, 1KB value value), with 500 concurrent clients
|
||||
|
||||
```
|
||||
# snapshot warnings
|
||||
grep -r -i installed\ remote consul-v0.7.3-go1.7.4-* | less
|
||||
|
||||
2017/02/06 22:04:23 [ERR] raft-net: Failed to flush response: write tcp 10.240.0.31:8300->10.240.0.30:46032: write: connection reset by peer
|
||||
2017/02/06 22:04:24 [INFO] snapshot: Creating new snapshot at /home/gyuho/consul.data/raft/snapshots/2-740201-1486418664486.tmp
|
||||
2017/02/06 22:04:26 [INFO] snapshot: reaping snapshot /home/gyuho/consul.data/raft/snapshots/2-688951-1486418642600
|
||||
2017/02/06 22:04:26 [INFO] raft: Copied 1005637598 bytes to local snapshot
|
||||
2017/02/06 22:04:34 [INFO] raft: Compacting logs from 724865 to 725120
|
||||
2017/02/06 22:04:34 [INFO] raft: Installed remote snapshot
|
||||
2017/02/06 22:04:35 [INFO] snapshot: Creating new snapshot at /home/gyuho/consul.data/raft/snapshots/2-756515-1486418675363.tmp
|
||||
2017/02/06 22:04:37 [INFO] snapshot: reaping snapshot /home/gyuho/consul.data/raft/snapshots/2-734528-1486418655488
|
||||
2017/02/06 22:04:37 [INFO] raft: Copied 1027808324 bytes to local snapshot
|
||||
2017/02/06 22:04:45 [INFO] consul.fsm: snapshot created in 18.935µs
|
||||
2017/02/06 22:04:45 [INFO] raft: Compacting logs from 725121 to 725120
|
||||
2017/02/06 22:04:46 [INFO] raft: Installed remote snapshot
|
||||
2017/02/06 22:04:46 [INFO] raft: Starting snapshot up to 756515
|
||||
```
|
||||
|
||||
Logs do not tell much but average latency spikes (e.g. from 258.28656 ms to 6265.185836 ms)
|
||||
|
||||
|
||||
|
||||
<br><br><hr>
|
||||
##### Write 1M keys, 256-byte key, 1KB value value, clients 1 to 1,000
|
||||
|
||||
|
|
|
|||
Loading…
Reference in New Issue