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 <amk@cray.com>
Change-Id: Ib7ec75e28581f3ac420314812e2521fa49f021dd
Reviewed-on: https://review.whamcloud.com/35445
Reviewed-by: Patrick Farrell <pfarrell@whamcloud.com>
Tested-by: jenkins <devops@whamcloud.com>
Reviewed-by: Andreas Dilger <adilger@whamcloud.com>
Tested-by: Maloo <maloo@whamcloud.com>
- "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,
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) {
rc = ptl_send_rpc(req, 0);
if (rc == -ENOMEM) {
if (req->rq_reqmsg)
CDEBUG(D_RPCTRACE,
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),
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);
/*
spin_lock(&imp->imp_lock);
/*
vaf.fmt = fmt;
vaf.va = &args;
libcfs_debug_msg(msgdata,
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,
&vaf,
req, req->rq_xid, req->rq_transno,
req_ok ? lustre_msg_get_transno(req->rq_reqmsg) : 0,
atomic_read(&req->rq_refcount),
DEBUG_REQ_FLAGS(req),
req_ok ? lustre_msg_get_flags(req->rq_reqmsg) : -1,
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);
va_end(args);
}
EXPORT_SYMBOL(_debug_req);
- "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),
(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);
if (lustre_msg_get_opc(request->rq_reqmsg) != OBD_PING)
CFS_FAIL_TIMEOUT_MS(OBD_FAIL_PTLRPC_PAUSE_REQ, cfs_fail_val);
timediff_usecs = ktime_us_delta(work_end, work_start);
arrived_usecs = ktime_us_delta(work_end, arrived);
CDEBUG(D_RPCTRACE,
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 ?
(request->rq_export ?
(char *)request->rq_export->exp_client_uuid.uuid : "0"),
(request->rq_export ?
request->rq_xid,
libcfs_id2str(request->rq_peer),
lustre_msg_get_opc(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 ?
timediff_usecs,
arrived_usecs,
(request->rq_repmsg ?