From: Ann Koehler Date: Mon, 8 Jul 2019 20:17:07 +0000 (-0500) Subject: LU-12523 ptlrpc: Add jobid to rpctrace debug messages X-Git-Tag: 2.12.57~140 X-Git-Url: https://git.whamcloud.com/?p=fs%2Flustre-release.git;a=commitdiff_plain;h=9ae40e4c5ecbc754e47b0570fedddc6963e03f9a LU-12523 ptlrpc: Add jobid to rpctrace debug messages This mod adds the jobid string found in the ptlrpc_body of an rpc to the output of rpctrace messages. If jobids are not in use the string will be empty. If jobids are in use, the string can be useful in analyzing Lustre activity. Test-Parameters: trivial Cray-bug-id: LUS-7557 Signed-off-by: Ann Koehler Change-Id: Ib7ec75e28581f3ac420314812e2521fa49f021dd Reviewed-on: https://review.whamcloud.com/35445 Reviewed-by: Patrick Farrell Tested-by: jenkins Reviewed-by: Andreas Dilger Tested-by: Maloo --- diff --git a/lustre/ptlrpc/client.c b/lustre/ptlrpc/client.c index 2523468..218fb4d 100644 --- a/lustre/ptlrpc/client.c +++ b/lustre/ptlrpc/client.c @@ -1698,11 +1698,12 @@ static int ptlrpc_send_new_req(struct ptlrpc_request *req) } CDEBUG(D_RPCTRACE, - "Sending RPC pname:cluuid:pid:xid:nid:opc %s:%s:%d:%llu:%s:%d\n", - current_comm(), + "Sending RPC req@%p pname:cluuid:pid:xid:nid:opc:job %s:%s:%d:%llu:%s:%d:%s\n", + req, current_comm(), imp->imp_obd->obd_uuid.uuid, lustre_msg_get_status(req->rq_reqmsg), req->rq_xid, - obd_import_nid2str(imp), lustre_msg_get_opc(req->rq_reqmsg)); + obd_import_nid2str(imp), lustre_msg_get_opc(req->rq_reqmsg), + lustre_msg_get_jobid(req->rq_reqmsg)); rc = ptl_send_rpc(req, 0); if (rc == -ENOMEM) { @@ -2149,13 +2150,14 @@ interpret: if (req->rq_reqmsg) CDEBUG(D_RPCTRACE, - "Completed RPC pname:cluuid:pid:xid:nid:opc %s:%s:%d:%llu:%s:%d\n", - current_comm(), + "Completed RPC req@%p pname:cluuid:pid:xid:nid:opc:job %s:%s:%d:%llu:%s:%d:%s\n", + req, current_comm(), imp->imp_obd->obd_uuid.uuid, lustre_msg_get_status(req->rq_reqmsg), req->rq_xid, obd_import_nid2str(imp), - lustre_msg_get_opc(req->rq_reqmsg)); + lustre_msg_get_opc(req->rq_reqmsg), + lustre_msg_get_jobid(req->rq_reqmsg)); spin_lock(&imp->imp_lock); /* diff --git a/lustre/ptlrpc/pack_generic.c b/lustre/ptlrpc/pack_generic.c index ecb6bc0..fa6bc0f 100644 --- a/lustre/ptlrpc/pack_generic.c +++ b/lustre/ptlrpc/pack_generic.c @@ -2595,7 +2595,7 @@ void _debug_req(struct ptlrpc_request *req, vaf.fmt = fmt; vaf.va = &args; libcfs_debug_msg(msgdata, - "%pV req@%p x%llu/t%lld(%lld) o%d->%s@%s:%d/%d lens %d/%d e %d to %lld dl %lld ref %d fl " REQ_FLAGS_FMT "/%x/%x rc %d/%d\n", + "%pV req@%p x%llu/t%lld(%lld) o%d->%s@%s:%d/%d lens %d/%d e %d to %lld dl %lld ref %d fl " REQ_FLAGS_FMT "/%x/%x rc %d/%d job:'%s'\n", &vaf, req, req->rq_xid, req->rq_transno, req_ok ? lustre_msg_get_transno(req->rq_reqmsg) : 0, @@ -2613,7 +2613,8 @@ void _debug_req(struct ptlrpc_request *req, atomic_read(&req->rq_refcount), DEBUG_REQ_FLAGS(req), req_ok ? lustre_msg_get_flags(req->rq_reqmsg) : -1, - rep_flags, req->rq_status, rep_status); + rep_flags, req->rq_status, rep_status, + req_ok ? lustre_msg_get_jobid(req->rq_reqmsg) : ""); va_end(args); } EXPORT_SYMBOL(_debug_req); diff --git a/lustre/ptlrpc/service.c b/lustre/ptlrpc/service.c index be4cd319..44dfec0 100644 --- a/lustre/ptlrpc/service.c +++ b/lustre/ptlrpc/service.c @@ -2218,15 +2218,16 @@ static int ptlrpc_server_handle_request(struct ptlrpc_service_part *svcpt, } CDEBUG(D_RPCTRACE, - "Handling RPC pname:cluuid+ref:pid:xid:nid:opc %s:%s+%d:%d:x%llu:%s:%d\n", - current_comm(), + "Handling RPC req@%p pname:cluuid+ref:pid:xid:nid:opc:job %s:%s+%d:%d:x%llu:%s:%d:%s\n", + request, 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)); + lustre_msg_get_opc(request->rq_reqmsg), + lustre_msg_get_jobid(request->rq_reqmsg)); if (lustre_msg_get_opc(request->rq_reqmsg) != OBD_PING) CFS_FAIL_TIMEOUT_MS(OBD_FAIL_PTLRPC_PAUSE_REQ, cfs_fail_val); @@ -2258,8 +2259,8 @@ put_conn: 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 processed in %lldus (%lldus total) trans %llu rc %d/%d\n", - current_comm(), + "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 ? @@ -2268,6 +2269,7 @@ put_conn: 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 ?