From e4943206b31f8132ad5a8ea6650905c59cd13aea Mon Sep 17 00:00:00 2001 From: Andreas Dilger Date: Wed, 24 Aug 2011 15:17:53 -0600 Subject: [PATCH] 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 Reviewed-on: http://review.whamcloud.com/1286 Tested-by: Hudson Reviewed-by: Mikhail Pershin Tested-by: Maloo Reviewed-by: Niu Yawei Reviewed-by: Oleg Drokin --- libcfs/libcfs/nidstrings.c | 2 +- lustre/ptlrpc/client.c | 13 ++++--------- lustre/ptlrpc/pack_generic.c | 39 +++++++++++++++++++++++---------------- 3 files changed, 28 insertions(+), 26 deletions(-) diff --git a/libcfs/libcfs/nidstrings.c b/libcfs/libcfs/nidstrings.c index d5b03ed..23ebcc8 100644 --- 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 --- 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 --- 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); -- 1.8.3.1