- 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"LPU64":%s:%d Request procesed in "
- "%ldus (%ldus total) trans "LPU64" rc %d/%d\n",
- current_comm(),
- (request->rq_export ?
- (char *)request->rq_export->exp_client_uuid.uuid : "0"),
- (request->rq_export ?
- atomic_read(&request->rq_export->exp_refcount) : -99),
- lustre_msg_get_status(request->rq_reqmsg),
- 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),
- (request->rq_repmsg ?
- lustre_msg_get_transno(request->rq_repmsg) :
- request->rq_transno),
- request->rq_status,
- (request->rq_repmsg ?
- lustre_msg_get_status(request->rq_repmsg) : -999));
- if (likely(svc->srv_stats != NULL && request->rq_reqmsg != NULL)) {
- __u32 op = lustre_msg_get_opc(request->rq_reqmsg);
- int opc = opcode_offset(op);
- if (opc > 0 && !(op == LDLM_ENQUEUE || op == MDS_REINT)) {
- LASSERT(opc < LUSTRE_MAX_OPCODES);
- lprocfs_counter_add(svc->srv_stats,
- opc + EXTRA_MAX_OPCODES,
- timediff);
- }
- }
- if (unlikely(request->rq_early_count)) {
- DEBUG_REQ(D_ADAPTTO, request,
- "sent %d early replies before finishing in "
- CFS_DURATION_T"s",
- request->rq_early_count,
- cfs_time_sub(work_end.tv_sec,
- request->rq_arrival_time.tv_sec));
- }
+ 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 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(),
+ (request->rq_export ?
+ (char *)request->rq_export->exp_client_uuid.uuid : "0"),
+ (request->rq_export ?
+ refcount_read(&request->rq_export->exp_handle.h_ref) : -99),
+ lustre_msg_get_status(request->rq_reqmsg),
+ request->rq_xid,
+ libcfs_id2str(request->rq_peer),
+ lustre_msg_get_opc(request->rq_reqmsg),
+ lustre_msg_get_jobid(request->rq_reqmsg) ?: "",
+ timediff_usecs,
+ arrived_usecs,
+ (request->rq_repmsg ?
+ lustre_msg_get_transno(request->rq_repmsg) :
+ request->rq_transno),
+ request->rq_status,
+ (request->rq_repmsg ?
+ lustre_msg_get_status(request->rq_repmsg) : -999));
+ if (likely(svc->srv_stats != NULL && request->rq_reqmsg != NULL)) {
+ __u32 op = lustre_msg_get_opc(request->rq_reqmsg);
+ int opc = opcode_offset(op);
+
+ if (opc > 0 && !(op == LDLM_ENQUEUE || op == MDS_REINT)) {
+ LASSERT(opc < LUSTRE_MAX_OPCODES);
+ lprocfs_counter_add(svc->srv_stats,
+ opc + EXTRA_MAX_OPCODES,
+ timediff_usecs);
+ }
+ }
+ if (unlikely(request->rq_early_count)) {
+ DEBUG_REQ(D_ADAPTTO, request,
+ "sent %d early replies before finishing in %llds",
+ request->rq_early_count,
+ div_u64(arrived_usecs, USEC_PER_SEC));
+ }