LU-5545 ptlrpc: false alarm in AT network latency measuring

If early reply of client RPC is lost and client RPC is expired and
resent, server will drop the resent RPC because it's already in
processing, server may also send reply or early reply to client,
which can still match reply buffer of the original request.
In this case, client is measuring time from resent time, but server
is reporting service time of original RPC, which is longer than
the time measured by client.

Signed-off-by: Liang Zhen <liang.zhen@intel.com>
Change-Id: I772fb054480a3212e28dc018a6f592f3da7a87b5
Reviewed-on: http://review.whamcloud.com/12018
Tested-by: Jenkins
Tested-by: Maloo <hpdd-maloo@intel.com>
Reviewed-by: Li Wei <wei.g.li@intel.com>
Reviewed-by: Johann Lombardi <johann.lombardi@intel.com>

diff --git a/lustre/ptlrpc/client.c b/lustre/ptlrpc/client.c
index 1f9452d..422bdaf 100644 (file)
--- a/lustre/ptlrpc/client.c
+++ b/lustre/ptlrpc/client.c
@@ -289,14 +289,27 @@ void ptlrpc_at_adj_net_latency(struct ptlrpc_request *req,
         time_t now = cfs_time_current_sec();
 
         LASSERT(req->rq_import);
         time_t now = cfs_time_current_sec();
 
         LASSERT(req->rq_import);

-        at = &req->rq_import->imp_at;
+
+       if (service_time > now - req->rq_sent + 3) {
+               /* bz16408, however, this can also happen if early reply
+                * is lost and client RPC is expired and resent, early reply
+                * or reply of original RPC can still be fit in reply buffer
+                * of resent RPC, now client is measuring time from the
+                * resent time, but server sent back service time of original
+                * RPC.
+                */
+               CDEBUG((lustre_msg_get_flags(req->rq_reqmsg) & MSG_RESENT) ?
+                      D_ADAPTTO : D_WARNING,
+                      "Reported service time %u > total measured time "
+                      CFS_DURATION_T"\n", service_time,
+                      cfs_time_sub(now, req->rq_sent));
+               return;
+       }

 
         /* Network latency is total time less server processing time */
 
         /* Network latency is total time less server processing time */

-        nl = max_t(int, now - req->rq_sent - service_time, 0) +1/*st rounding*/;
-        if (service_time > now - req->rq_sent + 3 /* bz16408 */)
-                CWARN("Reported service time %u > total measured time "
-                      CFS_DURATION_T"\n", service_time,
-                      cfs_time_sub(now, req->rq_sent));
+       nl = max_t(int, now - req->rq_sent -
+                       service_time, 0) + 1; /* st rounding */
+       at = &req->rq_import->imp_at;

 
         oldnl = at_measured(&at->iat_net_latency, nl);
         if (oldnl != 0)
 
         oldnl = at_measured(&at->iat_net_latency, nl);
         if (oldnl != 0)