From a3eb9709c251d4bbeb4cbba1f68f86b6f2775b73 Mon Sep 17 00:00:00 2001 From: Tom Pantelis Date: Wed, 11 Mar 2015 18:31:25 -0400 Subject: [PATCH] Reduce/enhance logging in AbstractLeader If you turn on debug logging for Shard, the "Checking sendAppendEntries for follower..." message is logged by sendUpdatesToFollower on every AppendEntriesReply heartbeat even when no data was sent to the follower. This bombards the karaf.log. To avoid this, we need this only logged if something changed for the follower. So, I changed the FollwerLogInformation setMatchIndex and setNextIndex methods to return a boolean if changed which handleAppendEntriesReply checks to see if either were updated. If neither changed, it passes true to sendUpdatesToFollower for isHeartbeat so the message isn't logged. I also made a few other minor logging changes. Change-Id: Ib1f2109092b3656c3cc3dfdd2cd7b4641a3f890b Signed-off-by: Tom Pantelis --- .../cluster/raft/FollowerLogInformation.java | 14 ++++- .../raft/FollowerLogInformationImpl.java | 18 ++++-- .../raft/behaviors/AbstractLeader.java | 59 ++++++++++++------- 3 files changed, 63 insertions(+), 28 deletions(-) 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); -- 2.36.6