b=17682 limit performance impact of rpctrace, dlmtrace & quota (real commit)

Performance improvements for debug messages with
D_RPCTRACE, D_LDLM, D_QUOTA
previous commit (995342ab73da4ac8e364f90d2b26a88a5eef4801)
only included the changelog entry.

i=alexey.lyashkov
i=andrew.perepechko
i=johann

diff --git a/lustre/include/lustre_net.h b/lustre/include/lustre_net.h
index d5e060e..9ee9892 100644 (file)
--- a/lustre/include/lustre_net.h
+++ b/lustre/include/lustre_net.h
@@ -1011,7 +1011,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 9534f6d..8d6a5e7 100644 (file)
--- a/lustre/include/lustre_quota.h
+++ b/lustre/include/lustre_quota.h
@@ -317,7 +317,7 @@ static inline void lqs_getref(struct lustre_qunit_size *lqs)
         if (atomic_inc_return(&lqs->lqs_refcount) == 2) /* quota_create_lqs */
                 atomic_inc(&lqs->lqs_ctxt->lqc_lqs);
 
-        CDEBUG(D_QUOTA, "lqs=%p refcount %d\n",
+        CDEBUG(D_INFO, "lqs=%p refcount %d\n",
                lqs, atomic_read(&lqs->lqs_refcount));
 }
 
@@ -328,7 +328,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 f16c537..530fb92 100644 (file)
--- a/lustre/ldlm/ldlm_lockd.c
+++ b/lustre/ldlm/ldlm_lockd.c
@@ -465,7 +465,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;
         }
 
@@ -1408,7 +1408,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;
@@ -1420,17 +1420,16 @@ 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 is 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");
         LDLM_LOCK_PUT(lock);
         EXIT;
 }

diff --git a/lustre/ldlm/ldlm_request.c b/lustre/ldlm/ldlm_request.c
index 573ecac..b3126df 100644 (file)
--- a/lustre/ldlm/ldlm_request.c
+++ b/lustre/ldlm/ldlm_request.c
@@ -304,7 +304,6 @@ int ldlm_cli_enqueue_local(struct ldlm_namespace *ns,
                                 completion, glimpse, data, lvb_len);
         if (!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);
@@ -328,13 +327,10 @@ int ldlm_cli_enqueue_local(struct ldlm_namespace *ns,
         if ((*flags) & LDLM_FL_LOCK_CHANGED)
                 *res_id = lock->l_resource->lr_name;
 
-        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_PUT(lock);
@@ -918,7 +914,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 d3910e4..f1b4c05 100644 (file)
--- a/lustre/lov/lov_request.c
+++ b/lustre/lov/lov_request.c
@@ -535,7 +535,7 @@ int lov_prep_cancel_set(struct obd_export *exp, struct obd_info *oinfo,
                 loi = lsm->lsm_oinfo[i];
                 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 0a0fb2a..66b656a 100644 (file)
--- a/lustre/ptlrpc/service.c
+++ b/lustre/ptlrpc/service.c
@@ -1332,16 +1332,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 && !request->rq_copy_queued)
                 class_export_rpc_put(export);
@@ -1357,15 +1347,28 @@ 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,
+
+        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);
+               (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 (svc->srv_stats != NULL) {
                 __u32 op = lustre_msg_get_opc(request->rq_reqmsg);
                 int opc = opcode_offset(op);