zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Dudzinski, Karol" <Karol.Dudzin...@gs.com>
Subject RE: Leader election duration
Date Fri, 01 May 2015 15:51:29 GMT
We're using 3.4.5.

The Goldman Sachs Group, Inc. All rights reserved.
See http://www.gs.com/disclaimer/global_email for important risk disclosures, conflicts of
interest and other terms and conditions relating to this e-mail and your reliance on information
contained in it.  This message may contain confidential or privileged information.  If you
are not the intended recipient, please advise us immediately and delete this message.  See
http://www.gs.com/disclaimer/email for further information on confidentiality and the risks
of non-secure electronic communication.  If you cannot access these links, please notify
us by reply message and we will send the contents to you.


-----Original Message-----
From: Camille Fournier [mailto:cf@renttherunway.com] 
Sent: 01 May 2015 16:26
To: bookkeeper-user@zookeeper.apache.org
Subject: Re: Leader election duration

Which version of ZK is this btw?

On Fri, May 1, 2015 at 10:26 AM, Dudzinski, Karol <Karol.Dudzinski@gs.com>
wrote:

> Unfortunately, I can't reproduce this other than in one production 
> cluster so testing a patch is difficult.
>
> Below are the relevant logs that Camille requested.
>
> For the first issue, the leader selection taking a long time, this is 
> a typical example:
> 2015-04-25 12:01:59,734 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :QuorumPeer@670] - LOOKING
> 2015-04-25 12:01:59,737 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :FileSnap@83] - Reading snapshot <snapshot>
> 2015-04-25 12:02:05,203 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 4 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:05,327 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :FastLeaderElection@740] - New election. My id =  2, proposed
> zxid=0x41d000c7d27
> 2015-04-25 12:02:05,327 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), LOOKING (n.state), 
> 5 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:05,328 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 2 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:05,530 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :FastLeaderElection@774] - Notification time out: 400
> 2015-04-25 12:02:05,940 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :FastLeaderElection@774] - Notification time out: 800
> 2015-04-25 12:02:06,750 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :FastLeaderElection@774] - Notification time out: 1600
> 2015-04-25 12:02:08,359 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :FastLeaderElection@774] - Notification time out: 3200
> 2015-04-25 12:02:08,709 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 4 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:08,756 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), LOOKING (n.state), 
> 5 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:10,320 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 2 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:10,325 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), FOLLOWING 
> (n.state), 4 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:13,539 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :FastLeaderElection@774] - Notification time out: 6400
> 2015-04-25 12:02:13,707 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:13,755 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), LEADING (n.state), 
> 5 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:15,329 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 2 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:15,334 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), FOLLOWING 
> (n.state), 4 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:15,582 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), LEADING (n.state), 
> 5 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:18,709 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 1 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:20,339 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 2 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:20,350 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), FOLLOWING 
> (n.state), 4 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:20,585 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), LEADING (n.state), 
> 5 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:23,723 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 1 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:25,349 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 2 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:25,357 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), FOLLOWING 
> (n.state), 4 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:25,598 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe6 (n.round), LEADING (n.state), 
> 5 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:28,729 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:30,358 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 2 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:31,500 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 4 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 4 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:33,726 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:34,476 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 5 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:35,357 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 4 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 2 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:36,506 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 4 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 4 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:38,726 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:39,473 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 5 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:40,357 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 2 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:41,507 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 4 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 4 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:43,726 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:44,472 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 5 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:46,504 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 4 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 4 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:48,725 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41d (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:49,480 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 5 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:51,504 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 4 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 4 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:53,724 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 1 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:54,488 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 5 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:56,514 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 5 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 4 (n.sid), 0x41e (n.peerEPoch), LOOKING (my state)
> 2015-04-25 12:02:56,734 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :QuorumPeer@738] - FOLLOWING
> 2015-04-25 12:02:56,734 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :ZooKeeperServer@162] - Created server with tickTime 2000 
> minSessionTimeout 4000 maxSessionTimeout 100000 datadir <data dir> 
> snapdir <snap dir>
> 2015-04-25 12:02:56,734 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :Follower@63] - FOLLOWING - LEADER ELECTION TOOK - 56999
>
> These are logs from server with id 2, they are following the reboot of 
> the leader which was sid 3.
>
>
> For the second problem, where the sync'ing doesn't happen, here are 
> the follower logs (immediately after the election shown above):
> 2015-04-25 12:02:56,818 - WARN  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :Learner@232] - Unexpected exception, tries=0, connecting to <host 
> with id 5>/<ip>:2182
> java.net.ConnectException: Connection refused
>         at java.net.PlainSocketImpl.socketConnect(Native Method)
>         at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
>         at
> java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
>         at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
>         at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
>         at java.net.Socket.connect(Socket.java:529)
>         at
> org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:224)
>         at
> org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
>         at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:740)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
> 2015-04-25 12:02:57,906 - WARN  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :Learner@232] - Unexpected exception, tries=1, connecting to <host 
> with id 5>/<ip>:2182
> java.net.ConnectException: Connection refused
>         at java.net.PlainSocketImpl.socketConnect(Native Method)
>         at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
>         at
> java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
>         at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
>         at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
>         at java.net.Socket.connect(Socket.java:529)
>         at
> org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:224)
>         at
> org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
>         at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:740)
>         at java.lang.Thread.run(Thread.java:662)
> 2015-04-25 12:02:58,725 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 4 
> (n.leader), 0x41d000c7d27 (n.zxid), 0xe7 (n.round), LOOKING (n.state), 
> 1 (n.sid), 0x41e (n.peerEPoch), FOLLOWING (my state)
> 2015-04-25 12:02:58,996 - WARN  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :Learner@232] - Unexpected exception, tries=2, connecting to <host 
> with id 5>/<ip>:2182
> java.net.ConnectException: Connection refused
>         at java.net.PlainSocketImpl.socketConnect(Native Method)
>         at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
>         at
> java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
>         at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
>         at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
>         at java.net.Socket.connect(Socket.java:529)
>         at
> org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:224)
>         at
> org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
>         at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:740)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
> 2015-04-25 12:03:00,093 - WARN  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :Learner@232] - Unexpected exception, tries=3, connecting to <host 
> with id 5>/<ip>:2182
> java.net.ConnectException: Connection refused
>         at java.net.PlainSocketImpl.socketConnect(Native Method)
>         at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
>         at
> java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
>         at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
>         at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
>         at java.net.Socket.connect(Socket.java:529)
>         at
> org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:224)
>         at
> org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
>         at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:740)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
>         at java.lang.Thread.run(Thread.java:662)
> 2015-04-25 12:03:01,185 - ERROR [QuorumPeer[myid=2]/0.0.0.0:2181 
> :Learner@229] - Unexpected exception
> java.net.ConnectException: Connection refused
>         at java.net.PlainSocketImpl.socketConnect(Native Method)
>         at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
>         at
> java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
>         at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
>         at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
>         at java.net.Socket.connect(Socket.java:529)
>         at
> org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:224)
>         at
> org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
>         at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:740)
> 2015-04-25 12:03:01,186 - WARN  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :Follower@89] - Exception when following the leader
> java.net.ConnectException: Connection refused
>         at java.net.PlainSocketImpl.socketConnect(Native Method)
>         at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
>         at
> java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
>         at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
>         at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
>         at java.net.Socket.connect(Socket.java:529)
>         at
> org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:224)
>         at
> org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
>         at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:740)
> 2015-04-25 12:03:01,186 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :Follower@166] - shutdown called
> java.lang.Exception: shutdown Follower
>         at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
>         at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:744)
> 2015-04-25 12:03:01,187 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :FollowerZooKeeperServer@139] - Shutting down
> 2015-04-25 12:03:01,187 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :ZooKeeperServer@419] - shutting down
> 2015-04-25 12:03:01,187 - INFO  [QuorumPeer[myid=2]/0.0.0.0:2181 
> :QuorumPeer@670] - LOOKING
>
> I think they get rejected because as far as sid 5 is concerned, it's 
> not the leader yet as shown by these two lines:
> 2015-04-25 12:02:27,247 - INFO  [QuorumPeer[myid=5]/0.0.0.0:2181 
> :QuorumPeer@670] - LOOKING
> 2015-04-25 12:03:01,838 - INFO  [QuorumPeer[myid=5]/0.0.0.0:2181 
> :Leader@345] - LEADING - LEADER ELECTION TOOK - 34591
>
> A short while later the leader times out:
> 2015-04-25 12:03:21,850 - WARN  [QuorumPeer[myid=5]/0.0.0.0:2181 
> :QuorumPeer@756] - Unexpected exception
> java.lang.InterruptedException: Timeout while waiting for epoch from quorum
>         at
> org.apache.zookeeper.server.quorum.Leader.getEpochToPropose(Leader.java:872)
>         at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:364)
>         at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:753)
>
> During another election, the leader sees this:
> 2015-04-25 17:03:55,967 - INFO  [QuorumPeer[myid=5]/0.0.0.0:2181 
> :Leader@345] - LEADING - LEADER ELECTION TOOK - 34114
> 2015-04-25 17:04:06,034 - INFO
> [LearnerHandler-/<ip>:34474:LearnerHandler@263] - Follower sid: 4 : 
> info
> : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@5c4b8582
>
> Sometimes this includes all the expected followers, sometimes just one 
> or two.  The problem doesn't end there, even for the follower for 
> which it prints the line above, it often never gets to the line below 
> which I see in successful elections (this is an example from a clean 
> cluster I just spun up for testing):
> 2015-04-29 11:05:55,941 - INFO
> [LearnerHandler-/<ip>:46737:LearnerHandler@385] - Synchronizing with 
> Follower sid: 1 maxCommittedLog=0x0 minCommittedLog=0x0 
> peerLastZxid=0x0
>
> Karol
>
> The Goldman Sachs Group, Inc. All rights reserved.
> See http://www.gs.com/disclaimer/global_email for important risk 
> disclosures, conflicts of interest and other terms and conditions 
> relating to this e-mail and your reliance on information contained in 
> it.  This message may contain confidential or privileged information.  
> If you are not the intended recipient, please advise us immediately 
> and delete this message.  See http://www.gs.com/disclaimer/email for 
> further information on confidentiality and the risks of non-secure electronic communication.
> If you cannot access these links, please notify us by reply message 
> and we will send the contents to you.
>
>
> -----Original Message-----
> From: Flavio Junqueira [mailto:fpjunqueira@yahoo.com.INVALID]
> Sent: 29 April 2015 22:54
> To: user@zookeeper.apache.org
> Subject: Re: Leader election duration
>
> 170MB isn't that large. I'm thinking that the election might be taking 
> some time because of the issue described in ZK-2164. In that jira, the 
> election was failing, but I can see the blocking call causing the 
> election to take longer as well. You may want to test that fix and see 
> if it makes any difference to you.
>
> -Flavio
>
> > On 29 Apr 2015, at 19:05, Karol Dudzinski <karoldudzinski@gmail.com>
> wrote:
> >
> > The snapshots are a bit larger than I'd like (~170MB) but the bit 
> > that
> takes time is actually before that.
> >
> > On a successful election, on the new leader I see the following:
> > - LEADER ELECTION TOOK: 12345
> > - Synchronizing with Follower...
> > - Sending DIFF or SNAP
> >
> > That last bit will take a long time if the snapshot is large, agreed.
> However, for me it's arriving at the LEADER ELECTION TOOK bit that 
> takes a long time.  And the bit between that and the Synchronizing 
> often times out with the messages I described in my previous email.
> >
> > Karol
> >
> >> On 29 Apr 2015, at 18:46, Flavio Junqueira
> <fpjunqueira@yahoo.com.INVALID> wrote:
> >>
> >> Check the size of your snapshot files. If during election you need 
> >> to
> transfer snapshots and they are large, then recovery is going to take 
> longer. We try to send a diff of the txns when possible, and sending a 
> diff is much faster compared to send a full snapshot. Sending a diff 
> isn't always possible, depending on how far behind followers compared 
> to the leader, so the difference might be due to snapshots and diffs.
> >> -Flavio
> >>
> >>
> >>    On Wednesday, April 29, 2015 6:32 PM, Camille Fournier <
> camille@apache.org> wrote:
> >>
> >>
> >>
> >> Don't suppose you could share some snippets of the log messages 
> >> you're seeing a lot?
> >>
> >> On Wed, Apr 29, 2015 at 1:29 PM, Karol Dudzinski 
> >> <karoldudzinski@gmail.com>
> >> wrote:
> >>
> >>> Did a bit more investigation today though I didn't try the prod 
> >>> snapshot in a test cluster.  I did however find a couple of other 
> >>> strange things which I'd initially missed.
> >>>
> >>> When the leader of this particular cluster goes for a reboot, I 
> >>> see many notification printouts from FastLeaderElection.  On some 
> >>> occasions I've seen nearly 50.  In other clusters I usually see 5 
> >>> or thereabouts.  The number of these notifications seems to 
> >>> correlate with how long election took.  What could cause it to 
> >>> require
> exchanging so many messages?
> >>>
> >>> This cluster also seems to often timeout while syncing after 
> >>> selecting the leader.  On the new leader I see the expected number 
> >>> of
> "Follower sid: ..."
> >>> messages but it doesn't always get to the "Synchronizing with Follower"
> >>> part.  On the leader I then get a "Unexpected exception causing 
> >>> shutdown while sock still open" message followed by a GOODBYE for 
> >>> one of the followers.  At the same time on that follower I see a 
> >>> "Exception when following the leader" caused by a read timeout in 
> >>> Learner.registerWithLeader.  Does anything happen prior to syncing 
> >>> that could take a long time?
> >>>
> >>> Thanks,
> >>> Karol
> >>>
> >>>>> On 28 Apr 2015, at 20:22, Karol Dudzinski 
> >>>>> <karoldudzinski@gmail.com>
> >>>> wrote:
> >>>>
> >>>> Well these are prod clusters so my ability to experiment is 
> >>>> rather
> >>> limited.  I can take a copy of the snapshot and try both 3 node 
> >>> and
> >>> 5 in a test cluster.
> >>>>
> >>>> One thing I forgot to mention is that in most clusters the number 
> >>>> of
> >>> election notification log lines I see is typically, give or take, 
> >>> the same as the number of participants.  In this cluster however, 
> >>> it's typically 2 or 3 times as many notifications as the number of
> participants.
> >>>>
> >>>> My gut feeling is it's more likely to be due to load as the 5 
> >>>> node
> >>> cluster is much busier and the election time has been increasing 
> >>> over time (as has load).  I have no idea exactly what load though, 
> >>> whether it's number of clients, frequency of transactions, total 
> >>> data size, etc.  I don't understand why though but that may just 
> >>> be my limited knowledge of the election protocol.
> >>>>
> >>>> Karol
> >>>>
> >>>>> On 28 Apr 2015, at 19:54, Camille Fournier <camille@apache.org>
> wrote:
> >>>>>
> >>>>> Just out of curiosity, if you start the 5 node cluster up with 
> >>>>> only 3 of the nodes to begin with (like, config 5, but only 
> >>>>> bring up 3 processes), does it speed up the leader election or 
> >>>>> is it still
> slow?
> >>>>>
> >>>>> C
> >>>>>
> >>>>> On Tue, Apr 28, 2015 at 1:41 PM, Karol Dudzinski <
> >>> karoldudzinski@gmail.com>
> >>>>> wrote:
> >>>>>
> >>>>>> Hi,
> >>>>>>
> >>>>>> We're seeing some rather strange leader election in one of our
> >>> clusters.
> >>>>>> The duration reported by the "FOLLOWING - LEADER ELECTION TOOK"
> >>>>>> log
> >>> line
> >>>>>> (and equivalent for the leader) seems to vary hugely.  During

> >>>>>> one
> >>> rolling
> >>>>>> reboot, I saw the number reported as small as 39ms and as large

> >>>>>> as 57 seconds (difference in units is not a typo).  The average

> >>>>>> is just
> >>> about 10
> >>>>>> seconds and std dev also about 10 seconds.  So the time taken

> >>>>>> is not
> >>> only
> >>>>>> quite large, it's also very variable.
> >>>>>>
> >>>>>> We have other clusters but the average election time in those

> >>>>>> is in the hundreds of millis with std dev in a similar 
> >>>>>> ballpark.  I guess one difference is the "slow" cluster is 5

> >>>>>> participants while the others
> >>> are 3,
> >>>>>> which may be a factor but I wouldn't expect it to make two 
> >>>>>> orders of magnitude difference!
> >>>>>>
> >>>>>> So my question is, what factors contribute to the election time
> >>> reported
> >>>>>> by these log lines? And what can we do to speed this up?
> >>>>>>
> >>>>>> As far as I understand from logs and a quick browse through
the 
> >>>>>> code
> >>> that
> >>>>>> time is the time to select a leader.  Syncing up to the leader

> >>>>>> happens after that.  The syncing part I can understand will

> >>>>>> vary depending on
> >>> load
> >>>>>> but I don't see why selecting the leader would.
> >>>>>>
> >>>>>> Thanks,
> >>>>>> Karol
> >>
> >>
> >>
>
>
Mime
View raw message