From a4b33a2be350accb1c5ebdf9fd8b927f6a165ca6 Mon Sep 17 00:00:00 2001
From: Moiz Raja <moraja@cisco.com>
Date: Fri, 20 Feb 2015 04:15:27 -0800
Subject: [PATCH 1/1] BUG 2676 : Add a diagnostic log message to detect delay
 in ApplyState processing

Log a message when ApplyState is processed 50 milliseconds after being generated

Change-Id: I7e101dab292b4a72d23904798dc2362a740e4c04
Signed-off-by: Moiz Raja <moraja@cisco.com>
---
 .../controller/cluster/raft/RaftActor.java     | 10 ++++++++++
 .../cluster/raft/base/messages/ApplyState.java | 18 ++++++++++++++++--
 2 files changed, 26 insertions(+), 2 deletions(-)

diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/RaftActor.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/RaftActor.java
index 65254f2d62..3ec8cc5c58 100644
--- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/RaftActor.java
+++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/RaftActor.java
@@ -22,6 +22,7 @@ import com.google.common.base.Stopwatch;
 import com.google.protobuf.ByteString;
 import java.io.Serializable;
 import java.util.Map;
+import java.util.concurrent.TimeUnit;
 import org.opendaylight.controller.cluster.DataPersistenceProvider;
 import org.opendaylight.controller.cluster.common.actor.AbstractUntypedPersistentActor;
 import org.opendaylight.controller.cluster.notifications.RoleChanged;
@@ -82,6 +83,9 @@ import org.slf4j.LoggerFactory;
  * </ul>
  */
 public abstract class RaftActor extends AbstractUntypedPersistentActor {
+
+    private static final long APPLY_STATE_DELAY_THRESHOLD_IN_NANOS = TimeUnit.MILLISECONDS.toNanos(50L); // 50 millis
+
     protected final Logger LOG = LoggerFactory.getLogger(getClass());
 
     /**
@@ -278,6 +282,12 @@ public abstract class RaftActor extends AbstractUntypedPersistentActor {
         if (message instanceof ApplyState){
             ApplyState applyState = (ApplyState) message;
 
+            long elapsedTime = (System.nanoTime() - applyState.getStartTime());
+            if(elapsedTime >= APPLY_STATE_DELAY_THRESHOLD_IN_NANOS){
+                LOG.warn("ApplyState took more time than expected. Elapsed Time = {} ms ApplyState = {}",
+                        TimeUnit.NANOSECONDS.toMillis(elapsedTime), applyState);
+            }
+
             if(LOG.isDebugEnabled()) {
                 LOG.debug("{}: Applying state for log index {} data {}",
                     persistenceId(), applyState.getReplicatedLogEntry().getIndex(),
diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/base/messages/ApplyState.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/base/messages/ApplyState.java
index 0a7a632880..9299e752d1 100644
--- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/base/messages/ApplyState.java
+++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/base/messages/ApplyState.java
@@ -9,21 +9,22 @@
 package org.opendaylight.controller.cluster.raft.base.messages;
 
 import akka.actor.ActorRef;
-import org.opendaylight.controller.cluster.raft.ReplicatedLogEntry;
-
 import java.io.Serializable;
+import org.opendaylight.controller.cluster.raft.ReplicatedLogEntry;
 
 public class ApplyState implements Serializable {
     private static final long serialVersionUID = 1L;
     private final ActorRef clientActor;
     private final String identifier;
     private final ReplicatedLogEntry replicatedLogEntry;
+    private final long startTime;
 
     public ApplyState(ActorRef clientActor, String identifier,
         ReplicatedLogEntry replicatedLogEntry) {
         this.clientActor = clientActor;
         this.identifier = identifier;
         this.replicatedLogEntry = replicatedLogEntry;
+        this.startTime = System.nanoTime();
     }
 
     public ActorRef getClientActor() {
@@ -37,4 +38,17 @@ public class ApplyState implements Serializable {
     public ReplicatedLogEntry getReplicatedLogEntry() {
         return replicatedLogEntry;
     }
+
+    public long getStartTime() {
+        return startTime;
+    }
+
+    @Override
+    public String toString() {
+        return "ApplyState{" +
+                "identifier='" + identifier + '\'' +
+                ", replicatedLogEntry.index =" + replicatedLogEntry.getIndex() +
+                ", startTime=" + startTime +
+                '}';
+    }
 }
-- 
2.36.6