LU-629 ptlrpc: fix _debug_req to print opc/status

The 2.x _debug_req() function was changed in bug 16359/commit 5467a86021
to avoid problems with accessing unswabbed message buffers. Unfortunately,
this broke the printing of many/most _debug_req() messages, because it
didn't check whether swabbing was actually needed in the first place.

Also, in ptlrpc_expire_one_request() some extra debugging information was
added in bug 21636/commit 368689640 but never removed, making this common
message overly verbose.

Fix _debug_req() so that it prints opcode/flags/status, unless the
ptlrpc_body _needs_ to be swabbed, but isn't.  Also print out more
useful idenfifiers for the nodes (the obd_name and NID instead of
the connection UUID).  This removes some of the added verbosity from
ptlrpc_expire_one_request(), and most of the rest was already being
printed out (deadline, current, etc).

Change-Id: I88a78486becd19f5b38f5578e5cc30e649564908
Signed-off-by: Andreas Dilger <adilger@whamcloud.com>
Reviewed-on: http://review.whamcloud.com/1286
Tested-by: Hudson
Reviewed-by: Mikhail Pershin <tappro@whamcloud.com>
Tested-by: Maloo <whamcloud.maloo@gmail.com>
Reviewed-by: Niu Yawei <niu@whamcloud.com>
Reviewed-by: Oleg Drokin <green@whamcloud.com>

diff --git a/libcfs/libcfs/nidstrings.c b/libcfs/libcfs/nidstrings.c
index d5b03ed..23ebcc8 100644 (file)
--- a/libcfs/libcfs/nidstrings.c
+++ b/libcfs/libcfs/nidstrings.c
@@ -434,7 +434,7 @@ libcfs_nid2str(lnet_nid_t nid)
         int               nob;
 
         if (nid == LNET_NID_ANY)
-                return "LNET_NID_ANY";
+                return "<?>";
 
         nf = libcfs_lnd2netstrfns(lnd);
         str = libcfs_next_nidstring();

diff --git a/lustre/ptlrpc/client.c b/lustre/ptlrpc/client.c
index 687cb6e..bb7eed7 100644 (file)
--- a/lustre/ptlrpc/client.c
+++ b/lustre/ptlrpc/client.c
@@ -1762,20 +1762,15 @@ int ptlrpc_expire_one_request(struct ptlrpc_request *req, int async_unlink)
         req->rq_timedout = 1;
         cfs_spin_unlock(&req->rq_lock);
 
-        DEBUG_REQ(req->rq_fake ? D_INFO : D_WARNING, req, "Request x"LPU64
-                  " sent from %s to NID %s has %s: [sent "CFS_DURATION_T"] "
-                  "[real_sent "CFS_DURATION_T"] [current "CFS_DURATION_T"] "
-                  "[deadline "CFS_DURATION_T"s] [delay "CFS_DURATION_T"s]",
-                  req->rq_xid, imp ? imp->imp_obd->obd_name : "<?>",
-                  imp ? libcfs_nid2str(imp->imp_connection->c_peer.nid) : "<?>", 
+        DEBUG_REQ(req->rq_fake ? D_INFO : D_WARNING, req, "Request "
+                  " sent has %s: [sent "CFS_DURATION_T"/"
+                  "real "CFS_DURATION_T"]",
                   req->rq_net_err ? "failed due to network error" :
                      ((req->rq_real_sent == 0 ||
                        cfs_time_before(req->rq_real_sent, req->rq_sent) ||
                        cfs_time_aftereq(req->rq_real_sent, req->rq_deadline)) ?
                       "timed out for sent delay" : "timed out for slow reply"),
-                  req->rq_sent, req->rq_real_sent, cfs_time_current_sec(),
-                  cfs_time_sub(req->rq_deadline, req->rq_sent),
-                  cfs_time_sub(cfs_time_current_sec(), req->rq_deadline));
+                  req->rq_sent, req->rq_real_sent);
 
         if (imp != NULL && obd_debug_peer_on_timeout)
                 LNetCtl(IOC_LIBCFS_DEBUG_PEER, &imp->imp_connection->c_peer);

diff --git a/lustre/ptlrpc/pack_generic.c b/lustre/ptlrpc/pack_generic.c
index 1429774..960d5d3 100644 (file)
--- a/lustre/ptlrpc/pack_generic.c
+++ b/lustre/ptlrpc/pack_generic.c
@@ -2310,37 +2310,44 @@ static inline int rep_ptlrpc_body_swabbed(struct ptlrpc_request *req)
 void _debug_req(struct ptlrpc_request *req, __u32 mask,
                 struct libcfs_debug_msg_data *data, const char *fmt, ... )
 {
+        int req_ok = req->rq_reqmsg != NULL;
+        int rep_ok = req->rq_repmsg != NULL;
         va_list args;
+
+        if (ptlrpc_req_need_swab(req)) {
+                req_ok = req_ok && req_ptlrpc_body_swabbed(req);
+                rep_ok = rep_ok && rep_ptlrpc_body_swabbed(req);
+        }
+
         va_start(args, fmt);
-        libcfs_debug_vmsg2(data->msg_cdls, data->msg_subsys, mask, data->msg_file,
+        libcfs_debug_vmsg2(data->msg_cdls, data->msg_subsys,mask,data->msg_file,
                            data->msg_fn, data->msg_line, fmt, args,
                            " req@%p x"LPU64"/t"LPD64"("LPD64") o%d->%s@%s:%d/%d"
                            " lens %d/%d e %d to %d dl "CFS_TIME_T" ref %d "
                            "fl "REQ_FLAGS_FMT"/%x/%x rc %d/%d\n",
                            req, req->rq_xid, req->rq_transno,
-                           req->rq_reqmsg ? lustre_msg_get_transno(req->rq_reqmsg) : 0,
-                           req->rq_reqmsg && req_ptlrpc_body_swabbed(req) ?
-                           lustre_msg_get_opc(req->rq_reqmsg) : -1,
-                           req->rq_import ? obd2cli_tgt(req->rq_import->imp_obd) :
-                           req->rq_export ?
-                           (char*)req->rq_export->exp_client_uuid.uuid : "<?>",
+                           req_ok ? lustre_msg_get_transno(req->rq_reqmsg) : 0,
+                           req_ok ? lustre_msg_get_opc(req->rq_reqmsg) : -1,
                            req->rq_import ?
-                           (char *)req->rq_import->imp_connection->c_remote_uuid.uuid :
-                           req->rq_export ?
-                           (char *)req->rq_export->exp_connection->c_remote_uuid.uuid : "<?>",
+                                req->rq_import->imp_obd->obd_name :
+                                req->rq_export ?
+                                     req->rq_export->exp_client_uuid.uuid :
+                                     "<?>",
+                           libcfs_nid2str(req->rq_import ?
+                                req->rq_import->imp_connection->c_peer.nid :
+                                req->rq_export ?
+                                     req->rq_export->exp_connection->c_peer.nid:
+                                     LNET_NID_ANY),
                            req->rq_request_portal, req->rq_reply_portal,
                            req->rq_reqlen, req->rq_replen,
                            req->rq_early_count, req->rq_timedout,
                            req->rq_deadline,
                            cfs_atomic_read(&req->rq_refcount),
                            DEBUG_REQ_FLAGS(req),
-                           req->rq_reqmsg && req_ptlrpc_body_swabbed(req) ?
-                           lustre_msg_get_flags(req->rq_reqmsg) : -1,
-                           req->rq_repmsg && rep_ptlrpc_body_swabbed(req) ?
-                           lustre_msg_get_flags(req->rq_repmsg) : -1,
+                           req_ok ? lustre_msg_get_flags(req->rq_reqmsg) : -1,
+                           rep_ok ? lustre_msg_get_flags(req->rq_repmsg) : -1,
                            req->rq_status,
-                           req->rq_repmsg && rep_ptlrpc_body_swabbed(req) ?
-                           lustre_msg_get_status(req->rq_repmsg) : -1);
+                           rep_ok ? lustre_msg_get_status(req->rq_repmsg) : -1);
 }
 EXPORT_SYMBOL(_debug_req);