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 (file)
--- 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);
         }
 
                         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;
                   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 (file)
--- 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);
 
         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)
 }
 
 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);
         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));
 }
 
                lqs, atomic_read(&lqs->lqs_refcount));
 }
 

diff --git a/lustre/ldlm/ldlm_lockd.c b/lustre/ldlm/ldlm_lockd.c
index 9cc6b99..7ff6bd8 100644 (file)
--- 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. */
 
         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;
         }
 
                 return 0;
         }
 


@@ -1443,7 +1443,7 @@ void ldlm_handle_bl_callback(struct ldlm_namespace *ns,
         int do_ast;
         ENTRY;
 
         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;
 
         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) {
         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 {
                 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_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 (file)
--- 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);
         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);
 
         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;
 
         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);
 
         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);
         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");
                 ldlm_lock_cancel(lock);
                 ldlm_reprocess_all(lock->l_resource);

-                LDLM_DEBUG(lock, "server-side local cancel handler END");

         }
 
         RETURN(rc);
         }
 
         RETURN(rc);

diff --git a/lustre/lov/lov_request.c b/lustre/lov/lov_request.c
index 919bbfe..a16eca1 100644 (file)
--- 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)) {
 
                 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;
                 }
                                loi->loi_ost_idx, loi->loi_id);
                         continue;
                 }

diff --git a/lustre/ptlrpc/service.c b/lustre/ptlrpc/service.c
index f9d1b73..4818e7a 100644 (file)
--- 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);
 
 
         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);
 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);
 
         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);
         if (likely(svc->srv_stats != NULL && request->rq_reqmsg != NULL)) {
                 __u32 op = lustre_msg_get_opc(request->rq_reqmsg);
                 int opc = opcode_offset(op);