LU-17853 ptlrpc: Negative value for req_waittime

A negative value was being reported in req_waittime mdt. This was
likely caused by a backwards adjustment of a few microseconds and
would cause a negative time delta to be calculated.

Fixed negative wait times by setting the time delta to be 1 if
the time delta was calculated to be negative. This should have
minimal impact on the statistics.

Signed-off-by: Frederick Dilger <fdilger@whamcloud.com>
Change-Id: I48543b8b1fbc83829421a30f4f7be7da8b681132
Reviewed-on: https://review.whamcloud.com/c/fs/lustre-release/+/55605
Tested-by: jenkins <devops@whamcloud.com>
Tested-by: Maloo <maloo@whamcloud.com>
Reviewed-by: Oleg Drokin <green@whamcloud.com>
Reviewed-by: Nathaniel Clark <nclark@whamcloud.com>
Reviewed-by: Andreas Dilger <adilger@whamcloud.com>

diff --git a/lustre/ptlrpc/client.c b/lustre/ptlrpc/client.c
index 7efc593..35692af 100644 (file)
--- a/lustre/ptlrpc/client.c
+++ b/lustre/ptlrpc/client.c
@@ -1501,6 +1501,8 @@ static int after_reply(struct ptlrpc_request *req)
 
        work_start = ktime_get_real();
        timediff = ktime_us_delta(work_start, req->rq_sent_ns);
+       if (unlikely(timediff < 0))
+               timediff = 1;
 
        /*
         * NB Until this point, the whole of the incoming message,

diff --git a/lustre/ptlrpc/service.c b/lustre/ptlrpc/service.c
index d19d2f4..8805451 100644 (file)
--- a/lustre/ptlrpc/service.c
+++ b/lustre/ptlrpc/service.c
@@ -2287,6 +2287,8 @@ static int ptlrpc_server_handle_request(struct ptlrpc_service_part *svcpt,
        work_start = ktime_get_real();
        arrived = timespec64_to_ktime(request->rq_arrival_time);
        timediff_usecs = ktime_us_delta(work_start, arrived);
+       if (unlikely(timediff_usecs < 0))
+               timediff_usecs = 1;
        if (likely(svc->srv_stats != NULL)) {
                lprocfs_counter_add(svc->srv_stats, PTLRPC_REQWAIT_CNTR,
                                    timediff_usecs);
@@ -2359,7 +2361,11 @@ put_conn:
 
        work_end = ktime_get_real();
        timediff_usecs = ktime_us_delta(work_end, work_start);
+       if (unlikely(timediff_usecs < 0))
+               timediff_usecs = 1;
        arrived_usecs = ktime_us_delta(work_end, arrived);
+       if (unlikely(arrived_usecs < 0))
+               arrived_usecs = 1;
        CDEBUG(D_RPCTRACE,
               "Handled RPC req@%p pname:cluuid+ref:pid:xid:nid:opc:job %s:%s+%d:%d:x%llu:%s:%d:%s Request processed in %lldus (%lldus total) trans %llu rc %d/%d\n",
               request, current->comm,