From: dzogin Date: Fri, 18 Dec 2009 21:41:11 +0000 (-0500) Subject: b=17682 limit performance impact of rpctrace, dlmtrace & quota X-Git-Tag: 1.10.0.33~15 X-Git-Url: https://git.whamcloud.com/?p=fs%2Flustre-release.git;a=commitdiff_plain;h=bc4f27deaf66091c9ecd6e4944cba88bcf846e75 b=17682 limit performance impact of rpctrace, dlmtrace & quota Performance improvements for debug messages with D_RPCTRACE, D_LDLM, D_QUOTA i=alexey.lyashkov i=andrew.perepechko i=johann --- diff --git a/lustre/include/lustre_net.h b/lustre/include/lustre_net.h index af283c5..71ef224 100644 --- a/lustre/include/lustre_net.h +++ b/lustre/include/lustre_net.h @@ -1206,7 +1206,7 @@ ptlrpc_rqphase_move(struct ptlrpc_request *req, enum rq_phase new_phase) atomic_dec(&req->rq_import->imp_unregistering); } - DEBUG_REQ(D_RPCTRACE, req, "move req \"%s\" -> \"%s\"", + DEBUG_REQ(D_INFO, req, "move req \"%s\" -> \"%s\"", ptlrpc_rqphase2str(req), ptlrpc_phase2str(new_phase)); req->rq_phase = new_phase; diff --git a/lustre/include/lustre_quota.h b/lustre/include/lustre_quota.h index a907def..5582637 100644 --- a/lustre/include/lustre_quota.h +++ b/lustre/include/lustre_quota.h @@ -401,7 +401,7 @@ static inline void __lqs_getref(struct lustre_qunit_size *lqs) if (count == 2) /* quota_create_lqs */ atomic_inc(&lqs->lqs_ctxt->lqc_lqs); - CDEBUG(D_QUOTA, "lqs=%p refcount %d\n", lqs, count); + CDEBUG(D_INFO, "lqs=%p refcount %d\n", lqs, count); } static inline void lqs_getref(struct lustre_qunit_size *lqs) @@ -416,7 +416,7 @@ static inline void __lqs_putref(struct lustre_qunit_size *lqs) if (atomic_dec_return(&lqs->lqs_refcount) == 1) if (atomic_dec_and_test(&lqs->lqs_ctxt->lqc_lqs)) cfs_waitq_signal(&lqs->lqs_ctxt->lqc_lqs_waitq); - CDEBUG(D_QUOTA, "lqs=%p refcount %d\n", + CDEBUG(D_INFO, "lqs=%p refcount %d\n", lqs, atomic_read(&lqs->lqs_refcount)); } diff --git a/lustre/ldlm/ldlm_lockd.c b/lustre/ldlm/ldlm_lockd.c index 9cc6b99..7ff6bd8 100644 --- a/lustre/ldlm/ldlm_lockd.c +++ b/lustre/ldlm/ldlm_lockd.c @@ -485,7 +485,7 @@ int ldlm_del_waiting_lock(struct ldlm_lock *lock) if (lock->l_export == NULL) { /* We don't have a "waiting locks list" on clients. */ - LDLM_DEBUG(lock, "client lock: no-op"); + CDEBUG(D_DLMTRACE, "Client lock %p : no-op\n", lock); return 0; } @@ -1443,7 +1443,7 @@ void ldlm_handle_bl_callback(struct ldlm_namespace *ns, int do_ast; ENTRY; - LDLM_DEBUG(lock, "client blocking AST callback handler START"); + LDLM_DEBUG(lock, "client blocking AST callback handler"); lock_res_and_lock(lock); lock->l_flags |= LDLM_FL_CBPENDING; @@ -1455,14 +1455,14 @@ void ldlm_handle_bl_callback(struct ldlm_namespace *ns, unlock_res_and_lock(lock); if (do_ast) { - LDLM_DEBUG(lock, "already unused, calling " - "callback (%p)", lock->l_blocking_ast); + CDEBUG(D_DLMTRACE, "Lock %p already unused, calling callback (%p)\n", + lock, lock->l_blocking_ast); if (lock->l_blocking_ast != NULL) lock->l_blocking_ast(lock, ld, lock->l_ast_data, LDLM_CB_BLOCKING); } else { - LDLM_DEBUG(lock, "Lock still has references, will be" - " cancelled later"); + CDEBUG(D_DLMTRACE, "Lock %p is referenced, will be cancelled later\n", + lock); } LDLM_DEBUG(lock, "client blocking callback handler END"); diff --git a/lustre/ldlm/ldlm_request.c b/lustre/ldlm/ldlm_request.c index 3352317..3cabd3d 100644 --- a/lustre/ldlm/ldlm_request.c +++ b/lustre/ldlm/ldlm_request.c @@ -398,7 +398,6 @@ int ldlm_cli_enqueue_local(struct ldlm_namespace *ns, lock = ldlm_lock_create(ns, res_id, type, mode, &cbs, data, lvb_len); if (unlikely(!lock)) GOTO(out_nolock, err = -ENOMEM); - LDLM_DEBUG(lock, "client-side local enqueue handler, new lock created"); ldlm_lock_addref_internal(lock, mode); ldlm_lock2handle(lock, lockh); @@ -421,13 +420,10 @@ int ldlm_cli_enqueue_local(struct ldlm_namespace *ns, if (policy != NULL) *policy = lock->l_policy_data; - LDLM_DEBUG_NOLOCK("client-side local enqueue handler END (lock %p)", - lock); - if (lock->l_completion_ast) lock->l_completion_ast(lock, *flags, NULL); - LDLM_DEBUG(lock, "client-side local enqueue END"); + LDLM_DEBUG(lock, "client-side local enqueue handler, new lock created"); EXIT; out: LDLM_LOCK_RELEASE(lock); @@ -1030,7 +1026,6 @@ static int ldlm_cli_cancel_local(struct ldlm_lock *lock) LDLM_DEBUG(lock, "server-side local cancel"); ldlm_lock_cancel(lock); ldlm_reprocess_all(lock->l_resource); - LDLM_DEBUG(lock, "server-side local cancel handler END"); } RETURN(rc); diff --git a/lustre/lov/lov_request.c b/lustre/lov/lov_request.c index 919bbfe..a16eca1 100644 --- a/lustre/lov/lov_request.c +++ b/lustre/lov/lov_request.c @@ -517,7 +517,7 @@ int lov_prep_cancel_set(struct obd_export *exp, struct obd_info *oinfo, lov_lockhp = set->set_lockh->llh_handles + i; if (!lustre_handle_is_used(lov_lockhp)) { - CDEBUG(D_RPCTRACE,"lov idx %d subobj "LPX64" no lock\n", + CDEBUG(D_INFO, "lov idx %d subobj "LPX64" no lock\n", loi->loi_ost_idx, loi->loi_id); continue; } diff --git a/lustre/ptlrpc/service.c b/lustre/ptlrpc/service.c index f9d1b73..4818e7a 100644 --- a/lustre/ptlrpc/service.c +++ b/lustre/ptlrpc/service.c @@ -1575,16 +1575,6 @@ ptlrpc_server_handle_request(struct ptlrpc_service *svc, ptlrpc_rqphase_move(request, RQ_PHASE_COMPLETE); - CDEBUG(D_RPCTRACE, "Handled RPC pname:cluuid+ref:pid:xid:nid:opc " - "%s:%s+%d:%d:x"LPU64":%s:%d\n", cfs_curproc_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)); - put_rpc_export: if (export != NULL) class_export_rpc_put(export); @@ -1604,15 +1594,26 @@ put_conn: do_gettimeofday(&work_end); timediff = cfs_timeval_sub(&work_end, &work_start, NULL); - CDEBUG(D_RPCTRACE, "request x"LPU64" opc %u from %s processed in " - "%ldus (%ldus total) trans "LPU64" rc %d/%d\n", - request->rq_xid, lustre_msg_get_opc(request->rq_reqmsg), - libcfs_id2str(request->rq_peer), 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); + CDEBUG(D_RPCTRACE, "Handled RPC pname:cluuid+ref:pid:xid:nid:opc " + "%s:%s+%d:%d:x"LPU64":%s:%d Request procesed in " + "%lds (%lds total) trans "LPU64" rc %d/%d\n", + cfs_curproc_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);