Fix ApplyState elapsed time check 84/37084/3
authorTom Pantelis <tpanteli@brocade.com>
Mon, 4 Apr 2016 05:40:06 +0000 (01:40 -0400)
committerMoiz Raja <moraja@cisco.com>
Wed, 6 Apr 2016 16:25:42 +0000 (16:25 +0000)
commit57d7e4788a488d992b9868d44ebc392b06e317c5
tree8c55106cedc334b2c661b4561882f1cf09c583a2
parentb14856a01f6515e6063f82e5fb448f7e9a57029b
Fix ApplyState elapsed time check

On ApplyState, there's a check if the elapsed time exceeds a 50ms
threshold and it logs a warning. However the start time is captured when
the message is created prior to queueing. So if there's many ApplyState
or other messages already queued, the elapsed time also includes the time spent
in the queue, ie as a side effect includes the cumulative processing time
of each prior message in the queue. When a follower starts up, there can
be hundreds to thousands of catchup ApplyState messages and, eventually,
the cumulative processing times can add up to more than 50 ms, in which
case every subsequent ApplyState message trips the threshold with
increasing elapsed times, even though none of them actually took 50 ms
to process. Seeing hundreds to thousands of warnings with misleading
elapsed times looks ominous and leads users to think something is wrong.

Therefore I changed it to capture the start time just prior to calling
applyState so it captures just the processing time for that message. I
also removed the startTime field from ApplyState. This class is
Serializable but it is only ever sent locally to self and is never
serialized so there's no backwards compatibility concerns.

Change-Id: I9493734b5307d6dd5d723e5fe416ba97915dfc63
Signed-off-by: Tom Pantelis <tpanteli@brocade.com>
opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/RaftActor.java
opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/base/messages/ApplyState.java