From commits-return-7900-archive-asf-public=cust-asf.ponee.io@zookeeper.apache.org Fri Aug 2 18:09:07 2019 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [207.244.88.153]) by mx-eu-01.ponee.io (Postfix) with SMTP id 86E02180654 for ; Fri, 2 Aug 2019 20:09:07 +0200 (CEST) Received: (qmail 94929 invoked by uid 500); 2 Aug 2019 18:09:02 -0000 Mailing-List: contact commits-help@zookeeper.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@zookeeper.apache.org Delivered-To: mailing list commits@zookeeper.apache.org Received: (qmail 94837 invoked by uid 99); 2 Aug 2019 18:09:02 -0000 Received: from ec2-52-202-80-70.compute-1.amazonaws.com (HELO gitbox.apache.org) (52.202.80.70) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 02 Aug 2019 18:09:02 +0000 Received: by gitbox.apache.org (ASF Mail Server at gitbox.apache.org, from userid 33) id 357E2854E0; Fri, 2 Aug 2019 18:09:02 +0000 (UTC) Date: Fri, 02 Aug 2019 18:09:02 +0000 To: "commits@zookeeper.apache.org" Subject: [zookeeper] branch master updated: ZOOKEEPER-3479: Logging false leader election times MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit Message-ID: <156476934207.25754.3354711148713218245@gitbox.apache.org> From: hanm@apache.org X-Git-Host: gitbox.apache.org X-Git-Repo: zookeeper X-Git-Refname: refs/heads/master X-Git-Reftype: branch X-Git-Oldrev: 104e78e008f84ab2d350b68db5a8a46297135faa X-Git-Newrev: 3882a0171f91280bf1adbbd4ffaeb17cb5131316 X-Git-Rev: 3882a0171f91280bf1adbbd4ffaeb17cb5131316 X-Git-NotificationType: ref_changed_plus_diff X-Git-Multimail-Version: 1.5.dev Auto-Submitted: auto-generated This is an automated email from the ASF dual-hosted git repository. hanm pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/zookeeper.git The following commit(s) were added to refs/heads/master by this push: new 3882a01 ZOOKEEPER-3479: Logging false leader election times 3882a01 is described below commit 3882a0171f91280bf1adbbd4ffaeb17cb5131316 Author: Karolos Antoniadis AuthorDate: Fri Aug 2 11:08:47 2019 -0700 ZOOKEEPER-3479: Logging false leader election times See https://issues.apache.org/jira/browse/ZOOKEEPER-3479 here for the issue. The problem is that the logged leader election times are much smaller than in reality. For example, we have log files that contain the following lines: ``` 2019-07-31 00:57:31,852 [myid:1] - WARN [QuorumPeer[myid=1](plain=/0.0.0.0:2791)(secure=disabled):QuorumPeer1318] - PeerState set to LOOKING 2019-07-31 00:57:31,853 [myid:1] - INFO [QuorumPeer[myid=1](plain=/0.0.0.0:2791)(secure=disabled):QuorumPeer1193] - LOOKING 2019-07-31 00:57:31,853 [myid:1] - INFO [QuorumPeer[myid=1](plain=/0.0.0.0:2791)(secure=disabled):FastLeaderElection885] - New election. My id = 1, proposed zxid=0x100000001 [...] 2019-07-31 00:57:32,272 [myid:1] - INFO [QuorumPeer[myid=1](plain=/0.0.0.0:2791)(secure=disabled):Follower69] - FOLLOWING - LEADER ELECTION TOOK - 1 MS ``` Leader election took more than 400ms, not 1ms! The reason this logging bug exists has to do with this [line](https://github.com/apache/zookeeper/blob/master/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java#L1402) in `QuorumPeer`. The computation of the leader election time starts inside [`FastLeaderElection.lookForLeader` ](https://github.com/apache/zookeeper/blob/master/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/FastLeaderElection.java#L915) where `start_fle` is set. After a [...] Furthermore, if we remove the problematic [line](https://github.com/apache/zookeeper/blob/master/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java#L1402), then there is no reason to check whether `start_fle == 0` in [`FastLeaderElection`](https://github.com/apache/zookeeper/blob/master/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/FastLeaderElection.java#L914), since `start_fle` is always `0` at that point. I'm not sure if this `if` [...] Author: foo bar Reviewers: Michael Han , Allan Lyu Closes #1031 from insumity/ZOOKEEPER-3479 --- .../java/org/apache/zookeeper/server/quorum/FastLeaderElection.java | 5 ++--- .../src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java | 1 - 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/FastLeaderElection.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/FastLeaderElection.java index 6dacc49..42fed41 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/FastLeaderElection.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/FastLeaderElection.java @@ -911,9 +911,8 @@ public class FastLeaderElection implements Election { LOG.warn("Failed to register with JMX", e); self.jmxLeaderElectionBean = null; } - if (self.start_fle == 0) { - self.start_fle = Time.currentElapsedTime(); - } + + self.start_fle = Time.currentElapsedTime(); try { Map recvset = new HashMap(); diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java index 521f6d4..ce794d1 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java @@ -1399,7 +1399,6 @@ public class QuorumPeer extends ZooKeeperThread implements QuorumStats.Provider } break; } - start_fle = Time.currentElapsedTime(); } } finally { LOG.warn("QuorumPeer main thread exited");