From: Moiz Raja Date: Fri, 13 Mar 2015 10:29:13 +0000 (+0000) Subject: Merge "Reduce/enhance logging in AbstractLeader" X-Git-Tag: release/lithium~403 X-Git-Url: https://git.opendaylight.org/gerrit/gitweb?p=controller.git;a=commitdiff_plain;h=06e889c9c78457590b6a0b62d89a6b9f44242a9f;hp=5ce3f45de1eb4a6f7abd9b02343ef215d06654c3 Merge "Reduce/enhance logging in AbstractLeader" --- diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformation.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformation.java index 73c81afd18..0beccd1b2b 100644 --- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformation.java +++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformation.java @@ -25,10 +25,13 @@ public interface FollowerLogInformation { long decrNextIndex(); /** + * Sets the index of the next log entry for this follower. * * @param nextIndex + * @return true if the new index differed from the current index and the current index was updated, false + * otherwise. */ - void setNextIndex(long nextIndex); + boolean setNextIndex(long nextIndex); /** * Increment the value of the matchIndex @@ -36,7 +39,14 @@ public interface FollowerLogInformation { */ long incrMatchIndex(); - void setMatchIndex(long matchIndex); + /** + * Sets the index of the highest log entry for this follower. + * + * @param matchIndex + * @return true if the new index differed from the current index and the current index was updated, false + * otherwise. + */ + boolean setMatchIndex(long matchIndex); /** * The identifier of the follower diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformationImpl.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformationImpl.java index 90e1282561..288a540344 100644 --- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformationImpl.java +++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformationImpl.java @@ -44,8 +44,13 @@ public class FollowerLogInformationImpl implements FollowerLogInformation { } @Override - public void setNextIndex(long nextIndex) { - this.nextIndex = nextIndex; + public boolean setNextIndex(long nextIndex) { + if(this.nextIndex != nextIndex) { + this.nextIndex = nextIndex; + return true; + } + + return false; } @Override @@ -54,8 +59,13 @@ public class FollowerLogInformationImpl implements FollowerLogInformation { } @Override - public void setMatchIndex(long matchIndex) { - this.matchIndex = matchIndex; + public boolean setMatchIndex(long matchIndex) { + if(this.matchIndex != matchIndex) { + this.matchIndex = matchIndex; + return true; + } + + return false; } @Override diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractLeader.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractLeader.java index 831f8f9e70..a4753a4fe4 100644 --- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractLeader.java +++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractLeader.java @@ -158,8 +158,6 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior { if(LOG.isTraceEnabled()) { LOG.trace("{}: handleAppendEntriesReply: {}", logName(), appendEntriesReply); - } else if(LOG.isDebugEnabled() && !appendEntriesReply.isSuccess()) { - LOG.debug("{}: handleAppendEntriesReply: {}", logName(), appendEntriesReply); } // Update the FollowerLogInformation @@ -174,7 +172,7 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior { if(followerLogInformation.timeSinceLastActivity() > context.getConfigParams().getElectionTimeOutInterval().toMillis()) { - LOG.error("{} : handleAppendEntriesReply delayed beyond election timeout, " + + LOG.warn("{} : handleAppendEntriesReply delayed beyond election timeout, " + "appendEntriesReply : {}, timeSinceLastActivity : {}, lastApplied : {}, commitIndex : {}", logName(), appendEntriesReply, followerLogInformation.timeSinceLastActivity(), context.getLastApplied(), context.getCommitIndex()); @@ -182,12 +180,17 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior { followerLogInformation.markFollowerActive(); + boolean updated = false; if (appendEntriesReply.isSuccess()) { - followerLogInformation - .setMatchIndex(appendEntriesReply.getLogLastIndex()); - followerLogInformation - .setNextIndex(appendEntriesReply.getLogLastIndex() + 1); + updated = followerLogInformation.setMatchIndex(appendEntriesReply.getLogLastIndex()); + updated = followerLogInformation.setNextIndex(appendEntriesReply.getLogLastIndex() + 1) || updated; + + if(updated && LOG.isDebugEnabled()) { + LOG.debug("{}: handleAppendEntriesReply - FollowerLogInformation for {} updated: matchIndex: {}, nextIndex: {}", logName(), + followerId, followerLogInformation.getMatchIndex(), followerLogInformation.getNextIndex()); + } } else { + LOG.debug("{}: handleAppendEntriesReply: received unsuccessful reply: {}", logName(), appendEntriesReply); // TODO: When we find that the follower is out of sync with the // Leader we simply decrement that followers next index by 1. @@ -224,8 +227,10 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior { // Apply the change to the state machine if (context.getCommitIndex() > context.getLastApplied()) { - LOG.debug("{}: handleAppendEntriesReply: applying to log - commitIndex: {}, lastAppliedIndex: {}", - logName(), context.getCommitIndex(), context.getLastApplied()); + if(LOG.isDebugEnabled()) { + LOG.debug("{}: handleAppendEntriesReply from {}: applying to log - commitIndex: {}, lastAppliedIndex: {}", + logName(), followerId, context.getCommitIndex(), context.getLastApplied()); + } applyLogToStateMachine(context.getCommitIndex()); } @@ -235,7 +240,7 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior { } //Send the next log entry immediately, if possible, no need to wait for heartbeat to trigger that event - sendUpdatesToFollower(followerId, followerLogInformation, false, false); + sendUpdatesToFollower(followerId, followerLogInformation, false, !updated); return this; } @@ -469,9 +474,9 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior { long leaderLastIndex = context.getReplicatedLog().lastIndex(); long leaderSnapShotIndex = context.getReplicatedLog().getSnapshotIndex(); - if(!isHeartbeat || LOG.isTraceEnabled()) { - LOG.debug("{}: Checking sendAppendEntries for follower {}, leaderLastIndex: {}, leaderSnapShotIndex: {}", - logName(), followerId, leaderLastIndex, leaderSnapShotIndex); + if((!isHeartbeat && LOG.isDebugEnabled()) || LOG.isTraceEnabled()) { + LOG.debug("{}: Checking sendAppendEntries for follower {}, followerNextIndex {}, leaderLastIndex: {}, leaderSnapShotIndex: {}", + logName(), followerId, followerNextIndex, leaderLastIndex, leaderSnapShotIndex); } if (isFollowerActive && context.getReplicatedLog().isPresent(followerNextIndex)) { @@ -556,7 +561,6 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior { } else if (!context.isSnapshotCaptureInitiated()) { - LOG.info("{}: Initiating Snapshot Capture to Install Snapshot, Leader:{}", logName(), getLeaderId()); ReplicatedLogEntry lastAppliedEntry = context.getReplicatedLog().get(context.getLastApplied()); long lastAppliedIndex = -1; long lastAppliedTerm = -1; @@ -572,10 +576,19 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior { boolean isInstallSnapshotInitiated = true; long replicatedToAllIndex = super.getReplicatedToAllIndex(); ReplicatedLogEntry replicatedToAllEntry = context.getReplicatedLog().get(replicatedToAllIndex); - actor().tell(new CaptureSnapshot(lastIndex(), lastTerm(), lastAppliedIndex, lastAppliedTerm, - (replicatedToAllEntry != null ? replicatedToAllEntry.getIndex() : -1), - (replicatedToAllEntry != null ? replicatedToAllEntry.getTerm() : -1), - isInstallSnapshotInitiated), actor()); + + CaptureSnapshot captureSnapshot = new CaptureSnapshot( + lastIndex(), lastTerm(), lastAppliedIndex, lastAppliedTerm, + (replicatedToAllEntry != null ? replicatedToAllEntry.getIndex() : -1), + (replicatedToAllEntry != null ? replicatedToAllEntry.getTerm() : -1), + isInstallSnapshotInitiated); + + if(LOG.isDebugEnabled()) { + LOG.debug("{}: Initiating install snapshot to follower {}: {}", logName(), followerId, + captureSnapshot); + } + + actor().tell(captureSnapshot, actor()); context.setSnapshotCaptureInitiated(true); } } @@ -622,10 +635,12 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior { ).toSerializable(), actor() ); - LOG.info("{}: InstallSnapshot sent to follower {}, Chunk: {}/{}", - logName(), followerActor.path(), - followerToSnapshot.getChunkIndex(), - followerToSnapshot.getTotalChunks()); + + if(LOG.isDebugEnabled()) { + LOG.debug("{}: InstallSnapshot sent to follower {}, Chunk: {}/{}", + logName(), followerActor.path(), followerToSnapshot.getChunkIndex(), + followerToSnapshot.getTotalChunks()); + } } } catch (IOException e) { LOG.error("{}: InstallSnapshot failed for Leader.", logName(), e);