Whamcloud - gitweb
LU-4423 ptlrpc: use 64-bit times for request times
[fs/lustre-release.git] / lustre / ptlrpc / service.c
index 221974e..7006a57 100644 (file)
@@ -1167,7 +1167,7 @@ static void ptlrpc_at_set_timer(struct ptlrpc_service_part *svcpt)
        }
 
        /* Set timer for closest deadline */
-       next = (__s32)(array->paa_deadline - cfs_time_current_sec() -
+       next = (__s32)(array->paa_deadline - ktime_get_real_seconds() -
                       at_early_margin);
        if (next <= 0) {
                ptlrpc_at_timer((unsigned long)svcpt);
@@ -1198,7 +1198,7 @@ static int ptlrpc_at_add_timed(struct ptlrpc_request *req)
        spin_lock(&svcpt->scp_at_lock);
        LASSERT(list_empty(&req->rq_timed_list));
 
-        index = (unsigned long)req->rq_deadline % array->paa_size;
+       div_u64_rem(req->rq_deadline, array->paa_size, &index);
         if (array->paa_reqs_count[index] > 0) {
                 /* latest rpcs will have the latest deadlines in the list,
                  * so search backward. */
@@ -1261,8 +1261,8 @@ static int ptlrpc_at_send_early_reply(struct ptlrpc_request *req)
        struct ptlrpc_service_part *svcpt = req->rq_rqbd->rqbd_svcpt;
        struct ptlrpc_request *reqcopy;
        struct lustre_msg *reqmsg;
-       cfs_duration_t olddl = req->rq_deadline - cfs_time_current_sec();
-       time_t  newdl;
+       time64_t olddl = req->rq_deadline - ktime_get_real_seconds();
+       time64_t newdl;
        int rc;
 
        ENTRY;
@@ -1275,18 +1275,18 @@ static int ptlrpc_at_send_early_reply(struct ptlrpc_request *req)
         /* deadline is when the client expects us to reply, margin is the
            difference between clients' and servers' expectations */
         DEBUG_REQ(D_ADAPTTO, req,
-                  "%ssending early reply (deadline %+lds, margin %+lds) for "
+                 "%ssending early reply (deadline %+llds, margin %+llds) for "
                   "%d+%d", AT_OFF ? "AT off - not " : "",
-                 olddl, olddl - at_get(&svcpt->scp_at_estimate),
+                 (s64)olddl, (s64)(olddl - at_get(&svcpt->scp_at_estimate)),
                  at_get(&svcpt->scp_at_estimate), at_extra);
 
         if (AT_OFF)
                 RETURN(0);
 
         if (olddl < 0) {
-                DEBUG_REQ(D_WARNING, req, "Already past deadline (%+lds), "
+               DEBUG_REQ(D_WARNING, req, "Already past deadline (%+llds), "
                           "not sending early reply. Consider increasing "
-                          "at_early_margin (%d)?", olddl, at_early_margin);
+                         "at_early_margin (%d)?", (s64)olddl, at_early_margin);
 
                 /* Return an error so we're not re-added to the timed list. */
                 RETURN(-ETIMEDOUT);
@@ -1326,7 +1326,7 @@ static int ptlrpc_at_send_early_reply(struct ptlrpc_request *req)
                 * account for network latency). See ptlrpc_at_recv_early_reply
                 */
                at_measured(&svcpt->scp_at_estimate, at_extra +
-                           cfs_time_current_sec() -
+                           ktime_get_real_seconds() -
                            req->rq_arrival_time.tv_sec);
                newdl = req->rq_arrival_time.tv_sec +
                        at_get(&svcpt->scp_at_estimate);
@@ -1335,9 +1335,8 @@ static int ptlrpc_at_send_early_reply(struct ptlrpc_request *req)
        /* Check to see if we've actually increased the deadline -
         * we may be past adaptive_max */
        if (req->rq_deadline >= newdl) {
-               DEBUG_REQ(D_WARNING, req, "Couldn't add any time "
-                         "(%ld/%ld), not sending early reply\n",
-                         olddl, newdl - cfs_time_current_sec());
+               DEBUG_REQ(D_WARNING, req, "Couldn't add any time (%lld/%lld), not sending early reply\n",
+                         (s64)olddl, (s64)(newdl - ktime_get_real_seconds()));
                RETURN(-ETIMEDOUT);
        }
 
@@ -1424,8 +1423,8 @@ static int ptlrpc_at_check_timed(struct ptlrpc_service_part *svcpt)
         struct ptlrpc_request *rq, *n;
        struct list_head work_list;
         __u32  index, count;
-        time_t deadline;
-        time_t now = cfs_time_current_sec();
+       time64_t deadline;
+       time64_t now = ktime_get_real_seconds();
         cfs_duration_t delay;
         int first, counter = 0;
         ENTRY;
@@ -1456,7 +1455,7 @@ static int ptlrpc_at_check_timed(struct ptlrpc_service_part *svcpt)
           server will take. Send early replies to everyone expiring soon. */
        INIT_LIST_HEAD(&work_list);
        deadline = -1;
-       index = (unsigned long)array->paa_deadline % array->paa_size;
+       div_u64_rem(array->paa_deadline, array->paa_size, &index);
        count = array->paa_count;
        while (count > 0) {
                count -= array->paa_reqs_count[index];
@@ -1499,8 +1498,7 @@ static int ptlrpc_at_check_timed(struct ptlrpc_service_part *svcpt)
                 LCONSOLE_WARN("%s: This server is not able to keep up with "
                              "request traffic (cpu-bound).\n",
                              svcpt->scp_service->srv_name);
-               CWARN("earlyQ=%d reqQ=%d recA=%d, svcEst=%d, "
-                     "delay="CFS_DURATION_T"(jiff)\n",
+               CWARN("earlyQ=%d reqQ=%d recA=%d, svcEst=%d, delay=%ld(jiff)\n",
                      counter, svcpt->scp_nreqs_incoming,
                      svcpt->scp_nreqs_active,
                      at_get(&svcpt->scp_at_estimate), delay);
@@ -1950,10 +1948,10 @@ ptlrpc_server_handle_req_in(struct ptlrpc_service_part *svcpt,
         }
 
         /* req_in handling should/must be fast */
-        if (cfs_time_current_sec() - req->rq_arrival_time.tv_sec > 5)
-                DEBUG_REQ(D_WARNING, req, "Slow req_in handling "CFS_DURATION_T"s",
-                          cfs_time_sub(cfs_time_current_sec(),
-                                       req->rq_arrival_time.tv_sec));
+       if (ktime_get_real_seconds() - req->rq_arrival_time.tv_sec > 5)
+               DEBUG_REQ(D_WARNING, req, "Slow req_in handling %llds",
+                         (s64)(ktime_get_real_seconds() -
+                               req->rq_arrival_time.tv_sec));
 
         /* Set rpc server deadline and add it to the timed list */
         deadline = (lustre_msghdr_get_flags(req->rq_reqmsg) &
@@ -2011,12 +2009,14 @@ static int
 ptlrpc_server_handle_request(struct ptlrpc_service_part *svcpt,
                             struct ptlrpc_thread *thread)
 {
-       struct ptlrpc_service   *svc = svcpt->scp_service;
-       struct ptlrpc_request   *request;
-       struct timeval           work_start;
-       struct timeval           work_end;
-       long                     timediff;
-       int                      fail_opc = 0;
+       struct ptlrpc_service *svc = svcpt->scp_service;
+       struct ptlrpc_request *request;
+       ktime_t work_start;
+       ktime_t work_end;
+       ktime_t arrived;
+       s64 timediff_usecs;
+       s64 arrived_usecs;
+       int fail_opc = 0;
 
        ENTRY;
 
@@ -2039,11 +2039,12 @@ ptlrpc_server_handle_request(struct ptlrpc_service_part *svcpt,
        if(OBD_FAIL_CHECK(OBD_FAIL_PTLRPC_DUMP_LOG))
                libcfs_debug_dumplog();
 
-       do_gettimeofday(&work_start);
-       timediff = cfs_timeval_sub(&work_start, &request->rq_arrival_time,NULL);
+       work_start = ktime_get_real();
+       arrived = timespec64_to_ktime(request->rq_arrival_time);
+       timediff_usecs = ktime_us_delta(arrived, work_start);
        if (likely(svc->srv_stats != NULL)) {
                 lprocfs_counter_add(svc->srv_stats, PTLRPC_REQWAIT_CNTR,
-                                    timediff);
+                                   timediff_usecs);
                 lprocfs_counter_add(svc->srv_stats, PTLRPC_REQQDEPTH_CNTR,
                                    svcpt->scp_nreqs_incoming);
                lprocfs_counter_add(svc->srv_stats, PTLRPC_REQACTIVE_CNTR,
@@ -2055,19 +2056,18 @@ ptlrpc_server_handle_request(struct ptlrpc_service_part *svcpt,
        if (likely(request->rq_export)) {
                if (unlikely(ptlrpc_check_req(request)))
                        goto put_conn;
-                ptlrpc_update_export_timer(request->rq_export, timediff >> 19);
+               ptlrpc_update_export_timer(request->rq_export,
+                                          timediff_usecs >> 19);
         }
 
         /* Discard requests queued for longer than the deadline.
            The deadline is increased if we send an early reply. */
-        if (cfs_time_current_sec() > request->rq_deadline) {
-                DEBUG_REQ(D_ERROR, request, "Dropping timed-out request from %s"
-                          ": deadline "CFS_DURATION_T":"CFS_DURATION_T"s ago\n",
+       if (ktime_get_real_seconds() > request->rq_deadline) {
+               DEBUG_REQ(D_ERROR, request, "Dropping timed-out request from %s: deadline %lld:%llds ago\n",
                           libcfs_id2str(request->rq_peer),
-                          cfs_time_sub(request->rq_deadline,
-                          request->rq_arrival_time.tv_sec),
-                          cfs_time_sub(cfs_time_current_sec(),
-                          request->rq_deadline));
+                         request->rq_deadline -
+                         request->rq_arrival_time.tv_sec,
+                         ktime_get_real_seconds() - request->rq_deadline);
                 goto put_conn;
         }
 
@@ -2098,21 +2098,17 @@ ptlrpc_server_handle_request(struct ptlrpc_service_part *svcpt,
        ptlrpc_rqphase_move(request, RQ_PHASE_COMPLETE);
 
 put_conn:
-       if (unlikely(cfs_time_current_sec() > request->rq_deadline)) {
-                    DEBUG_REQ(D_WARNING, request, "Request took longer "
-                              "than estimated ("CFS_DURATION_T":"CFS_DURATION_T"s);"
-                              " client may timeout.",
-                              cfs_time_sub(request->rq_deadline,
-                                           request->rq_arrival_time.tv_sec),
-                              cfs_time_sub(cfs_time_current_sec(),
-                                           request->rq_deadline));
-       }
-
-       do_gettimeofday(&work_end);
-       timediff = cfs_timeval_sub(&work_end, &work_start, NULL);
-       CDEBUG(D_RPCTRACE, "Handled RPC pname:cluuid+ref:pid:xid:nid:opc "
-              "%s:%s+%d:%d:x%llu:%s:%d Request procesed in "
-              "%ldus (%ldus total) trans %llu rc %d/%d\n",
+       if (unlikely(ktime_get_real_seconds() > request->rq_deadline)) {
+               DEBUG_REQ(D_WARNING, request, "Request took longer than estimated (%lld:%llds); client may timeout.",
+                         request->rq_deadline -
+                         request->rq_arrival_time.tv_sec,
+                         ktime_get_real_seconds() - request->rq_deadline);
+       }
+
+       work_end = ktime_get_real();
+       timediff_usecs = ktime_us_delta(work_end, work_start);
+       arrived_usecs = ktime_us_delta(work_end, arrived);
+       CDEBUG(D_RPCTRACE, "Handled RPC pname:cluuid+ref:pid:xid:nid:opc %s:%s+%d:%d:x%llu:%s:%d Request procesed in %lldus (%lldus total) trans %llu rc %d/%d\n",
                current_comm(),
                (request->rq_export ?
                 (char *)request->rq_export->exp_client_uuid.uuid : "0"),
@@ -2122,8 +2118,8 @@ put_conn:
                 request->rq_xid,
                 libcfs_id2str(request->rq_peer),
                 lustre_msg_get_opc(request->rq_reqmsg),
-                timediff,
-                cfs_timeval_sub(&work_end, &request->rq_arrival_time, NULL),
+               timediff_usecs,
+               arrived_usecs,
                 (request->rq_repmsg ?
                  lustre_msg_get_transno(request->rq_repmsg) :
                  request->rq_transno),
@@ -2137,16 +2133,14 @@ put_conn:
                         LASSERT(opc < LUSTRE_MAX_OPCODES);
                         lprocfs_counter_add(svc->srv_stats,
                                             opc + EXTRA_MAX_OPCODES,
-                                            timediff);
+                                           timediff_usecs);
                 }
         }
         if (unlikely(request->rq_early_count)) {
                 DEBUG_REQ(D_ADAPTTO, request,
-                          "sent %d early replies before finishing in "
-                          CFS_DURATION_T"s",
+                         "sent %d early replies before finishing in %llds",
                           request->rq_early_count,
-                          cfs_time_sub(work_end.tv_sec,
-                          request->rq_arrival_time.tv_sec));
+                         arrived_usecs / USEC_PER_SEC);
         }
 
        ptlrpc_server_finish_active_request(svcpt, request);
@@ -3241,11 +3235,11 @@ EXPORT_SYMBOL(ptlrpc_unregister_service);
  * to be shot, so it's intentionally non-aggressive. */
 static int ptlrpc_svcpt_health_check(struct ptlrpc_service_part *svcpt)
 {
-       struct ptlrpc_request           *request = NULL;
-       struct timeval                  right_now;
-       long                            timediff;
+       struct ptlrpc_request *request = NULL;
+       struct timespec64 right_now;
+       struct timespec64 timediff;
 
-       do_gettimeofday(&right_now);
+       ktime_get_real_ts64(&right_now);
 
        spin_lock(&svcpt->scp_req_lock);
        /* How long has the next entry been waiting? */
@@ -3259,13 +3253,13 @@ static int ptlrpc_svcpt_health_check(struct ptlrpc_service_part *svcpt)
                return 0;
        }
 
-       timediff = cfs_timeval_sub(&right_now, &request->rq_arrival_time, NULL);
+       timediff = timespec64_sub(right_now, request->rq_arrival_time);
        spin_unlock(&svcpt->scp_req_lock);
 
-       if ((timediff / ONE_MILLION) >
+       if ((timediff.tv_sec) >
            (AT_OFF ? obd_timeout * 3 / 2 : at_max)) {
-               CERROR("%s: unhealthy - request has been waiting %lds\n",
-                      svcpt->scp_service->srv_name, timediff / ONE_MILLION);
+               CERROR("%s: unhealthy - request has been waiting %llds\n",
+                      svcpt->scp_service->srv_name, (s64)timediff.tv_sec);
                return -1;
        }