From 6be44b743f7f1470392321b23ecbd431324c80e0 Mon Sep 17 00:00:00 2001 From: scjody Date: Thu, 19 Jul 2007 00:22:04 +0000 Subject: [PATCH] Branch b1_6 To improve performance, disable most logging (for debug purposes) by default. VFSTRACE, RPCTRACE, and DLMTRACE are now off by default, and HA includes contains fewer messages. Original patch by adilger. b=12417 i=scjody i=green --- lustre/ChangeLog | 7 +++++++ lustre/ldlm/ldlm_lib.c | 2 +- lustre/ldlm/ldlm_lockd.c | 4 ++-- lustre/ldlm/ldlm_request.c | 4 ++-- lustre/llite/llite_lib.c | 2 +- lustre/lov/lov_request.c | 2 +- lustre/lvfs/upcall_cache.c | 2 +- lustre/mdc/mdc_request.c | 18 +++++++++--------- lustre/mds/handler.c | 4 ++-- lustre/mds/mds_join.c | 2 +- lustre/mds/mds_lov.c | 2 +- lustre/mds/mds_open.c | 4 ++-- lustre/mds/mds_reint.c | 10 +++++----- lustre/mds/mds_unlink_open.c | 13 +++++-------- lustre/obdclass/genops.c | 8 ++------ lustre/obdclass/llog.c | 6 +++--- lustre/obdclass/llog_cat.c | 8 ++++---- lustre/obdclass/llog_lvfs.c | 4 ++-- lustre/obdclass/llog_obd.c | 4 ++-- lustre/obdfilter/filter.c | 20 +++++++++++--------- lustre/obdfilter/filter_io.c | 22 ++++------------------ lustre/obdfilter/filter_log.c | 8 ++++---- lustre/osc/osc_create.c | 15 ++++++--------- lustre/osc/osc_request.c | 2 +- lustre/ptlrpc/client.c | 20 ++++++++++---------- lustre/ptlrpc/llog_server.c | 2 +- lustre/ptlrpc/pinger.c | 26 ++++++++++++-------------- lustre/ptlrpc/recov_thread.c | 8 ++++---- lustre/ptlrpc/service.c | 4 ++-- 29 files changed, 108 insertions(+), 125 deletions(-) diff --git a/lustre/ChangeLog b/lustre/ChangeLog index 94b4f78..115296e 100644 --- a/lustre/ChangeLog +++ b/lustre/ChangeLog @@ -515,6 +515,13 @@ Description: parallel lock callbacks Details : Instead of sending blocking and completion callbacks as separated requests, adding them to a set and sending in parallel. +Severity : normal +Bugzilla : 12417 +Description: Disable most debugging by default +Details : To improve performance, disable most logging (for debug purposes) + by default. VFSTRACE, RPCTRACE, and DLMTRACE are now off by + default, and HA includes fewer messages. + -------------------------------------------------------------------------------- 2007-05-03 Cluster File Systems, Inc. diff --git a/lustre/ldlm/ldlm_lib.c b/lustre/ldlm/ldlm_lib.c index 54a176a..5d4e608 100644 --- a/lustre/ldlm/ldlm_lib.c +++ b/lustre/ldlm/ldlm_lib.c @@ -530,7 +530,7 @@ void target_client_add_cb(struct obd_device *obd, __u64 transno, void *cb_data, { struct obd_export *exp = cb_data; - CDEBUG(D_HA, "%s: committing for initial connect of %s\n", + CDEBUG(D_RPCTRACE, "%s: committing for initial connect of %s\n", obd->obd_name, exp->exp_client_uuid.uuid); spin_lock(&exp->exp_lock); diff --git a/lustre/ldlm/ldlm_lockd.c b/lustre/ldlm/ldlm_lockd.c index ed48f82..c582e35 100644 --- a/lustre/ldlm/ldlm_lockd.c +++ b/lustre/ldlm/ldlm_lockd.c @@ -870,8 +870,8 @@ int ldlm_handle_enqueue(struct ptlrpc_request *req, lock = find_existing_lock(req->rq_export, &dlm_req->lock_handle[0]); if (lock != NULL) { - DEBUG_REQ(D_HA, req, "found existing lock cookie "LPX64, - lock->l_handle.h_cookie); + DEBUG_REQ(D_DLMTRACE, req, "found existing lock cookie " + LPX64, lock->l_handle.h_cookie); GOTO(existing_lock, rc = 0); } } diff --git a/lustre/ldlm/ldlm_request.c b/lustre/ldlm/ldlm_request.c index 1a6dbc2..9c73ecf 100644 --- a/lustre/ldlm/ldlm_request.c +++ b/lustre/ldlm/ldlm_request.c @@ -855,8 +855,8 @@ int ldlm_cli_cancel_req(struct obd_export *exp, while (1) { imp = class_exp2cliimp(exp); if (imp == NULL || imp->imp_invalid) { - CDEBUG(D_HA, "skipping cancel on invalid import %p\n", - imp); + CDEBUG(D_DLMTRACE, + "skipping cancel on invalid import %p\n", imp); break; } diff --git a/lustre/llite/llite_lib.c b/lustre/llite/llite_lib.c index 0fefc5e..4c9411e 100644 --- a/lustre/llite/llite_lib.c +++ b/lustre/llite/llite_lib.c @@ -80,7 +80,7 @@ static struct ll_sb_info *ll_init_sbi(void) ll_generate_random_uuid(uuid); class_uuid_unparse(uuid, &sbi->ll_sb_uuid); - CDEBUG(D_HA, "generated uuid: %s\n", sbi->ll_sb_uuid.uuid); + CDEBUG(D_CONFIG, "generated uuid: %s\n", sbi->ll_sb_uuid.uuid); spin_lock(&ll_sb_lock); list_add_tail(&sbi->ll_list, &ll_super_blocks); diff --git a/lustre/lov/lov_request.c b/lustre/lov/lov_request.c index fc3d0d7..439d34b 100644 --- a/lustre/lov/lov_request.c +++ b/lustre/lov/lov_request.c @@ -509,7 +509,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_HA, "lov idx %d subobj "LPX64" no lock?\n", + CDEBUG(D_RPCTRACE,"lov idx %d subobj "LPX64" no lock\n", loi->loi_ost_idx, loi->loi_id); continue; } diff --git a/lustre/lvfs/upcall_cache.c b/lustre/lvfs/upcall_cache.c index 2db5d90..87c6b8e 100644 --- a/lustre/lvfs/upcall_cache.c +++ b/lustre/lvfs/upcall_cache.c @@ -417,7 +417,7 @@ int upcall_cache_downcall(struct upcall_cache *hash, __u32 err, __u64 key, } if (!UC_CACHE_IS_ACQUIRING(entry)) { - CDEBUG(D_HA, "%s: found uptodate entry %p (key "LPU64")\n", + CDEBUG(D_RPCTRACE,"%s: found uptodate entry %p (key "LPU64")\n", hash->uc_name, entry, entry->ue_key); GOTO(out, rc = 0); } diff --git a/lustre/mdc/mdc_request.c b/lustre/mdc/mdc_request.c index bb148d7..43dc9a4 100644 --- a/lustre/mdc/mdc_request.c +++ b/lustre/mdc/mdc_request.c @@ -352,7 +352,7 @@ void mdc_store_inode_generation(struct ptlrpc_request *req, int reqoff, LBUG(); } - DEBUG_REQ(D_HA, req, "storing generation %u for ino "LPU64, + DEBUG_REQ(D_INODE, req, "storing generation %u for ino "LPU64, rec->cr_replayfid.generation, rec->cr_replayfid.id); } @@ -512,7 +512,7 @@ static void mdc_replay_open(struct ptlrpc_request *req) struct lustre_handle *file_fh; LASSERT(och->och_magic == OBD_CLIENT_HANDLE_MAGIC); file_fh = &och->och_fh; - CDEBUG(D_HA, "updating handle from "LPX64" to "LPX64"\n", + CDEBUG(D_RPCTRACE, "updating handle from "LPX64" to "LPX64"\n", file_fh->cookie, body->handle.cookie); memcpy(&old, file_fh, sizeof(old)); memcpy(file_fh, &body->handle, sizeof(*file_fh)); @@ -526,7 +526,7 @@ static void mdc_replay_open(struct ptlrpc_request *req) sizeof(*close_body)); if (och != NULL) LASSERT(!memcmp(&old, &close_body->handle, sizeof old)); - DEBUG_REQ(D_HA, close_req, "updating close body with new fh"); + DEBUG_REQ(D_RPCTRACE, close_req, "updating close with new fh"); memcpy(&close_body->handle, &body->handle, sizeof(close_body->handle)); } @@ -581,7 +581,7 @@ void mdc_set_open_replay_data(struct obd_client_handle *och, LBUG(); } - DEBUG_REQ(D_HA, open_req, "set up replay data"); + DEBUG_REQ(D_RPCTRACE, open_req, "set up replay data"); } void mdc_clear_open_replay_data(struct obd_client_handle *och) @@ -604,7 +604,7 @@ static void mdc_commit_close(struct ptlrpc_request *req) struct ptlrpc_request *open_req; struct obd_import *imp = req->rq_import; - DEBUG_REQ(D_HA, req, "close req committed"); + DEBUG_REQ(D_RPCTRACE, req, "close req committed"); if (mod == NULL) return; @@ -617,7 +617,7 @@ static void mdc_commit_close(struct ptlrpc_request *req) LASSERT(open_req != LP_POISON); LASSERT(open_req->rq_type != LI_POISON); - DEBUG_REQ(D_HA, open_req, "open req balanced"); + DEBUG_REQ(D_RPCTRACE, open_req, "open req balanced"); LASSERT(open_req->rq_transno != 0); LASSERT(open_req->rq_import == imp); @@ -666,9 +666,9 @@ int mdc_close(struct obd_export *exp, struct obdo *oa, GOTO(out, rc = -EIO); } mod->mod_close_req = req; - DEBUG_REQ(D_HA, mod->mod_open_req, "matched open"); + DEBUG_REQ(D_RPCTRACE, mod->mod_open_req, "matched open"); } else { - CDEBUG(D_HA, "couldn't find open req; expecting close error\n"); + CDEBUG(D_RPCTRACE, "couldn't find open req; expecting error\n"); } mdc_close_pack(req, REQ_REC_OFF, oa, oa->o_valid, och); @@ -683,7 +683,7 @@ int mdc_close(struct obd_export *exp, struct obdo *oa, mdc_put_rpc_lock(obd->u.cli.cl_close_lock, NULL); if (req->rq_repmsg == NULL) { - CDEBUG(D_HA, "request failed to send: %p, %d\n", req, + CDEBUG(D_RPCTRACE, "request failed to send: %p, %d\n", req, req->rq_status); if (rc == 0) rc = req->rq_status ? req->rq_status : -EIO; diff --git a/lustre/mds/handler.c b/lustre/mds/handler.c index 14f095b..2477d58 100644 --- a/lustre/mds/handler.c +++ b/lustre/mds/handler.c @@ -2280,7 +2280,7 @@ static void fixup_handle_for_resent_req(struct ptlrpc_request *req, int offset, if (lock->l_remote_handle.cookie == remote_hdl.cookie) { lockh->cookie = lock->l_handle.h_cookie; LDLM_DEBUG(lock, "restoring lock cookie"); - DEBUG_REQ(D_HA, req, "restoring lock cookie "LPX64, + DEBUG_REQ(D_DLMTRACE, req,"restoring lock cookie "LPX64, lockh->cookie); if (old_lock) *old_lock = LDLM_LOCK_GET(lock); @@ -2307,7 +2307,7 @@ static void fixup_handle_for_resent_req(struct ptlrpc_request *req, int offset, lustre_msg_clear_flags(req->rq_reqmsg, MSG_RESENT); - DEBUG_REQ(D_HA, req, "no existing lock with rhandle "LPX64, + DEBUG_REQ(D_DLMTRACE, req, "no existing lock with rhandle "LPX64, remote_hdl.cookie); } diff --git a/lustre/mds/mds_join.c b/lustre/mds/mds_join.c index a0ab48e..d2db5cb 100644 --- a/lustre/mds/mds_join.c +++ b/lustre/mds/mds_join.c @@ -233,7 +233,7 @@ static void mds_finish_join(struct mds_obd *mds, struct ptlrpc_request *req, } if (body->valid & OBD_MD_FLMODEASIZE) - CDEBUG(D_HA, "updating max_mdsize/max_cookiesize: %d/%d\n", + CDEBUG(D_INODE, "updating max_mdsize/max_cookiesize: %d/%d\n", mds->mds_max_mdsize, mds->mds_max_cookiesize); mds_pack_inode2fid(&body->fid1, inode); diff --git a/lustre/mds/mds_lov.c b/lustre/mds/mds_lov.c index 36f893e..36e1617 100644 --- a/lustre/mds/mds_lov.c +++ b/lustre/mds/mds_lov.c @@ -559,7 +559,7 @@ int mds_iocontrol(unsigned int cmd, struct obd_export *exp, int len, } case OBD_IOC_SYNC: { - CDEBUG(D_HA, "syncing mds %s\n", obd->obd_name); + CDEBUG(D_INFO, "syncing mds %s\n", obd->obd_name); rc = fsfilt_sync(obd, obd->u.obt.obt_sb); RETURN(rc); } diff --git a/lustre/mds/mds_open.c b/lustre/mds/mds_open.c index 7f69d5d..0c2f6ed 100644 --- a/lustre/mds/mds_open.c +++ b/lustre/mds/mds_open.c @@ -1274,7 +1274,7 @@ int mds_mfd_close(struct ptlrpc_request *req, int offset, int stripe_count = 0; LASSERT(rc == 0); /* mds_put_write_access must have succeeded */ - CDEBUG(D_HA, "destroying orphan object %s\n", fidname); + CDEBUG(D_INODE, "destroying orphan object %s\n", fidname); if ((S_ISREG(inode->i_mode) && inode->i_nlink != 1) || (S_ISDIR(inode->i_mode) && inode->i_nlink != 2)) @@ -1437,7 +1437,7 @@ int mds_close(struct ptlrpc_request *req, int offset) MDS_CHECK_RESENT(req, mds_reconstruct_generic(req)); } - CDEBUG(D_HA, "close req->rep_len %d mdsize %d cookiesize %d\n", + CDEBUG(D_INODE, "close req->rep_len %d mdsize %d cookiesize %d\n", req->rq_replen, obd->u.mds.mds_max_mdsize, obd->u.mds.mds_max_cookiesize); mds_counter_incr(req->rq_export, LPROC_MDS_CLOSE); diff --git a/lustre/mds/mds_reint.c b/lustre/mds/mds_reint.c index e2ec61d..67a4f26 100644 --- a/lustre/mds/mds_reint.c +++ b/lustre/mds/mds_reint.c @@ -71,10 +71,10 @@ static void mds_cancel_cookies_cb(struct obd_device *obd, __u64 transno, obd_transno_commit_cb(obd, transno, error); - CDEBUG(D_HA, "cancelling %d cookies\n", + CDEBUG(D_RPCTRACE, "cancelling %d cookies\n", (int)(mlcd->mlcd_cookielen / sizeof(*mlcd->mlcd_cookies))); - rc = obd_unpackmd(obd->u.mds.mds_osc_exp, &lsm, mlcd->mlcd_lmm, + rc = obd_unpackmd(obd->u.mds.mds_osc_exp, &lsm, mlcd->mlcd_lmm, mlcd->mlcd_eadatalen); if (rc < 0) { CERROR("bad LSM cancelling %d log cookies: rc %d\n", @@ -111,7 +111,7 @@ int mds_finish_transno(struct mds_obd *mds, struct inode *inode, void *handle, __u64 transno, prev_transno; int err; loff_t off; - int log_pri = D_HA; + int log_pri = D_RPCTRACE; ENTRY; if (IS_ERR(handle)) { @@ -365,7 +365,7 @@ void mds_steal_ack_locks(struct ptlrpc_request *req) oldrep->rs_modes[i]); oldrep->rs_nlocks = 0; - DEBUG_REQ(D_HA, req, "stole locks for"); + DEBUG_REQ(D_DLMTRACE, req, "stole locks for"); ptlrpc_schedule_difficult_reply (oldrep); spin_unlock (&svc->srv_lock); @@ -387,7 +387,7 @@ void mds_req_from_mcd(struct ptlrpc_request *req, struct mds_client_data *mcd) req->rq_status = le32_to_cpu(mcd->mcd_last_result); lustre_msg_set_status(req->rq_repmsg, req->rq_status); } - DEBUG_REQ(D_HA, req, "restoring transno "LPD64"/status %d", + DEBUG_REQ(D_RPCTRACE, req, "restoring transno "LPD64"/status %d", req->rq_transno, req->rq_status); mds_steal_ack_locks(req); diff --git a/lustre/mds/mds_unlink_open.c b/lustre/mds/mds_unlink_open.c index d768886..cc7ffe0 100644 --- a/lustre/mds/mds_unlink_open.c +++ b/lustre/mds/mds_unlink_open.c @@ -257,15 +257,12 @@ int mds_cleanup_pending(struct obd_device *obd) MDS_UP_READ_ORPHAN_SEM(child_inode); rc = mds_unlink_orphan(obd, dchild, child_inode, pending_dir); - if (rc == 0) { - item ++; - CDEBUG(D_HA, "%s: removed orphan %s\n", - obd->obd_name, d_name); - } else { - CDEBUG(D_INODE, "%s: removed orphan %s failed," - " rc = %d\n", obd->obd_name, d_name, rc); + CDEBUG(D_INODE, "%s: removed orphan %s: rc %d\n", + obd->obd_name, d_name, rc); + if (rc == 0) + item++; + else rc = 0; - } next: l_dput(dchild); UNLOCK_INODE_MUTEX(pending_dir); diff --git a/lustre/obdclass/genops.c b/lustre/obdclass/genops.c index 9b3790a..9617612 100644 --- a/lustre/obdclass/genops.c +++ b/lustre/obdclass/genops.c @@ -932,12 +932,8 @@ static void class_disconnect_export_list(struct list_head *list, int flags) rc = obd_disconnect(fake_exp); class_export_put(exp); - if (rc) { - CDEBUG(D_HA, "disconnecting export %p failed: %d\n", - exp, rc); - } else { - CDEBUG(D_HA, "export %p disconnected\n", exp); - } + CDEBUG(D_HA, "disconnecting export %s (%p): rc %d\n", + exp->exp_client_uuid.uuid, exp, rc); } EXIT; } diff --git a/lustre/obdclass/llog.c b/lustre/obdclass/llog.c index 217b3f8..977b489 100644 --- a/lustre/obdclass/llog.c +++ b/lustre/obdclass/llog.c @@ -85,7 +85,7 @@ int llog_cancel_rec(struct llog_handle *loghandle, int index) int rc = 0; ENTRY; - CDEBUG(D_HA, "canceling %d in log "LPX64"\n", + CDEBUG(D_RPCTRACE, "canceling %d in log "LPX64"\n", index, loghandle->lgh_id.lgl_oid); if (index == 0) { @@ -94,7 +94,7 @@ int llog_cancel_rec(struct llog_handle *loghandle, int index) } if (!ext2_clear_bit(index, llh->llh_bitmap)) { - CDEBUG(D_HA, "catalog index %u already clear?\n", index); + CDEBUG(D_RPCTRACE, "catalog index %u already clear?\n", index); RETURN(-EINVAL); } @@ -379,7 +379,7 @@ int llog_reverse_process(struct llog_handle *loghandle, llog_cb_t cb, rec = buf; idx = le32_to_cpu(rec->lrh_index); if (idx < index) - CDEBUG(D_HA, "index %u : idx %u\n", index, idx); + CDEBUG(D_RPCTRACE, "index %u : idx %u\n", index, idx); while (idx < index) { rec = ((void *)rec + le32_to_cpu(rec->lrh_len)); idx ++; diff --git a/lustre/obdclass/llog_cat.c b/lustre/obdclass/llog_cat.c index e42fab8..e4c9ba2 100644 --- a/lustre/obdclass/llog_cat.c +++ b/lustre/obdclass/llog_cat.c @@ -90,7 +90,7 @@ static struct llog_handle *llog_cat_new_log(struct llog_handle *cathandle) llh->llh_count++; llh->llh_tail.lrt_index = index; - CDEBUG(D_HA, "new recovery log "LPX64":%x for index %u of catalog " + CDEBUG(D_RPCTRACE,"new recovery log "LPX64":%x for index %u of catalog " LPX64"\n", loghandle->lgh_id.lgl_oid, loghandle->lgh_id.lgl_ogen, index, cathandle->lgh_id.lgl_oid); /* build the record for this log in the catalog */ @@ -324,8 +324,8 @@ int llog_cat_cancel_records(struct llog_handle *cathandle, int count, llog_cat_set_first_idx(cathandle, index); rc = llog_cancel_rec(cathandle, index); if (rc == 0) - CDEBUG(D_HA, "cancel plain log at index %u " - "of catalog "LPX64"\n", + CDEBUG(D_RPCTRACE,"cancel plain log at index %u" + " of catalog "LPX64"\n", index, cathandle->lgh_id.lgl_oid); } } @@ -485,7 +485,7 @@ int llog_cat_set_first_idx(struct llog_handle *cathandle, int index) } } out: - CDEBUG(D_HA, "set catlog "LPX64" first idx %u\n", + CDEBUG(D_RPCTRACE, "set catlog "LPX64" first idx %u\n", cathandle->lgh_id.lgl_oid, llh->llh_cat_idx); } diff --git a/lustre/obdclass/llog_lvfs.c b/lustre/obdclass/llog_lvfs.c index 5e6200d..2303a4b 100644 --- a/lustre/obdclass/llog_lvfs.c +++ b/lustre/obdclass/llog_lvfs.c @@ -161,7 +161,7 @@ static int llog_lvfs_read_header(struct llog_handle *handle) obd = handle->lgh_ctxt->loc_exp->exp_obd; if (handle->lgh_file->f_dentry->d_inode->i_size == 0) { - CDEBUG(D_HA, "not reading header from 0-byte log\n"); + CDEBUG(D_RPCTRACE, "not reading header from 0-byte log\n"); RETURN(LLOG_EEMPTY); } @@ -343,7 +343,7 @@ static int llog_lvfs_write_rec(struct llog_handle *loghandle, if (rc) RETURN(rc); - CDEBUG(D_HA, "added record "LPX64": idx: %u, %u bytes\n", + CDEBUG(D_RPCTRACE, "added record "LPX64": idx: %u, %u bytes\n", loghandle->lgh_id.lgl_oid, index, rec->lrh_len); if (rc == 0 && reccookie) { reccookie->lgc_lgl = loghandle->lgh_id; diff --git a/lustre/obdclass/llog_obd.c b/lustre/obdclass/llog_obd.c index 6cf90d1..c1eff40 100644 --- a/lustre/obdclass/llog_obd.c +++ b/lustre/obdclass/llog_obd.c @@ -283,8 +283,8 @@ int llog_obd_origin_cleanup(struct llog_ctxt *ctxt) llog_cat_set_first_idx(cathandle, index); rc = llog_cancel_rec(cathandle, index); if (rc == 0) - CDEBUG(D_HA, "cancel plain log at index" - " %u of catalog "LPX64"\n", + CDEBUG(D_RPCTRACE, "cancel plain log at" + "index %u of catalog "LPX64"\n", index,cathandle->lgh_id.lgl_oid); } } diff --git a/lustre/obdfilter/filter.c b/lustre/obdfilter/filter.c index 45b1ec1..cc5b961 100644 --- a/lustre/obdfilter/filter.c +++ b/lustre/obdfilter/filter.c @@ -81,7 +81,7 @@ int filter_finish_transno(struct obd_export *exp, struct obd_trans_info *oti, struct filter_client_data *fcd = fed->fed_fcd; __u64 last_rcvd; loff_t off; - int err, log_pri = D_HA; + int err, log_pri = D_RPCTRACE; /* Propagate error code. */ if (rc) @@ -2715,7 +2715,7 @@ static int filter_handle_precreate(struct obd_export *exp, struct obdo *oa, diff = 1; else diff = oa->o_id - filter_last_id(filter, group); - CDEBUG(D_HA, "filter_last_id() = "LPU64" -> diff = %d\n", + CDEBUG(D_RPCTRACE, "filter_last_id() = "LPU64" -> diff = %d\n", filter_last_id(filter, group), diff); LASSERTF(diff >= 0,"%s: "LPU64" - "LPU64" = %d\n",obd->obd_name, @@ -2809,8 +2809,8 @@ static int filter_precreate(struct obd_device *obd, struct obdo *oa, RETURN(-ENOMEM); rc = filter_statfs(obd, osfs, cfs_time_current_64() - HZ); if (rc == 0 && osfs->os_bavail < (osfs->os_blocks >> 10)) { - CDEBUG(D_HA,"%s: not enough space for create "LPU64"\n", - obd->obd_name, osfs->os_bavail << + CDEBUG(D_RPCTRACE,"%s: not enough space for create " + LPU64"\n", obd->obd_name, osfs->os_bavail << filter->fo_vfsmnt->mnt_sb->s_blocksize_bits); *num = 0; rc = -ENOSPC; @@ -2820,8 +2820,8 @@ static int filter_precreate(struct obd_device *obd, struct obdo *oa, RETURN(rc); } - CDEBUG(D_HA, "%s: precreating %d objects in group "LPU64" at "LPU64"\n", - obd->obd_name, *num, group, oa->o_id); + CDEBUG(D_RPCTRACE, "%s: precreating %d objects in group "LPU64 + " at "LPU64"\n", obd->obd_name, *num, group, oa->o_id); for (i = 0; i < *num && err == 0; i++) { int cleanup_phase = 0; @@ -2921,14 +2921,16 @@ static int filter_precreate(struct obd_device *obd, struct obdo *oa, if (rc) break; if (time_after(jiffies, enough_time)) { - CDEBUG(D_HA, "%s: precreate slow - want %d got %d \n", + CDEBUG(D_RPCTRACE, + "%s: precreate slow - want %d got %d \n", obd->obd_name, *num, i); break; } } *num = i; - CDEBUG(D_HA,"%s: created %d objects for group "LPU64": "LPU64" rc %d\n", + CDEBUG(D_RPCTRACE, + "%s: created %d objects for group "LPU64": "LPU64" rc %d\n", obd->obd_name, i, group, filter->fo_last_objids[group], rc); RETURN(rc); @@ -3307,7 +3309,7 @@ int filter_iocontrol(unsigned int cmd, struct obd_export *exp, } case OBD_IOC_SYNC: { - CDEBUG(D_HA, "syncing ost %s\n", obd->obd_name); + CDEBUG(D_RPCTRACE, "syncing ost %s\n", obd->obd_name); rc = fsfilt_sync(obd, obd->u.obt.obt_sb); RETURN(rc); } diff --git a/lustre/obdfilter/filter_io.c b/lustre/obdfilter/filter_io.c index 029eaf4..3869cf1 100644 --- a/lustre/obdfilter/filter_io.c +++ b/lustre/obdfilter/filter_io.c @@ -80,9 +80,6 @@ static void filter_grant_incoming(struct obd_export *exp, struct obdo *oa) { struct filter_export_data *fed; struct obd_device *obd = exp->exp_obd; - static unsigned long last_msg; - static int last_count; - int mask = D_CACHE; ENTRY; LASSERT_SPIN_LOCKED(&obd->obd_osfs_lock); @@ -96,20 +93,10 @@ static void filter_grant_incoming(struct obd_export *exp, struct obdo *oa) fed = &exp->exp_filter_data; - /* Don't print this to the console the first time it happens, since - * it can happen legitimately on occasion, but only rarely. */ - if (time_after(jiffies, last_msg + 60 * HZ)) { - last_count = 0; - last_msg = jiffies; - } - if ((last_count & (-last_count)) == last_count) - mask = D_HA /* until bug 3273 is fixed D_WARNING */; - last_count++; - /* Add some margin, since there is a small race if other RPCs arrive * out-or-order and have already consumed some grant. We want to * leave this here in case there is a large error in accounting. */ - CDEBUG(oa->o_grant > fed->fed_grant + FILTER_GRANT_CHUNK ? mask:D_CACHE, + CDEBUG(D_CACHE, "%s: cli %s/%p reports grant: "LPU64" dropped: %u, local: %lu\n", obd->obd_name, exp->exp_client_uuid.uuid, exp, oa->o_grant, oa->o_dropped, fed->fed_grant); @@ -124,7 +111,7 @@ static void filter_grant_incoming(struct obd_export *exp, struct obdo *oa) oa->o_dirty = fed->fed_grant + 4 * FILTER_GRANT_CHUNK; obd->u.filter.fo_tot_dirty += oa->o_dirty - fed->fed_dirty; if (fed->fed_grant < oa->o_dropped) { - CDEBUG(D_HA,"%s: cli %s/%p reports %u dropped > fedgrant %lu\n", + CDEBUG(D_CACHE,"%s: cli %s/%p reports %u dropped > grant %lu\n", obd->obd_name, exp->exp_client_uuid.uuid, exp, oa->o_dropped, fed->fed_grant); oa->o_dropped = 0; @@ -397,7 +384,7 @@ static int filter_grant_check(struct obd_export *exp, struct obdo *oa, struct filter_export_data *fed = &exp->exp_filter_data; int blocksize = exp->exp_obd->u.obt.obt_sb->s_blocksize; unsigned long used = 0, ungranted = 0, using; - int i, rc = -ENOSPC, obj, n = 0, mask = D_CACHE; + int i, rc = -ENOSPC, obj, n = 0; LASSERT_SPIN_LOCKED(&exp->exp_obd->obd_osfs_lock); @@ -421,7 +408,6 @@ static int filter_grant_check(struct obd_export *exp, struct obdo *oa, exp->exp_obd->obd_name, exp->exp_client_uuid.uuid, exp, used, bytes, fed->fed_grant, n); - mask = D_RPCTRACE; } else { used += bytes; rnb[n].flags |= OBD_BRW_GRANTED; @@ -465,7 +451,7 @@ static int filter_grant_check(struct obd_export *exp, struct obdo *oa, exp->exp_obd->u.filter.fo_tot_granted += ungranted; exp->exp_obd->u.filter.fo_tot_pending += used + ungranted; - CDEBUG(mask, + CDEBUG(D_CACHE, "%s: cli %s/%p used: %lu ungranted: %lu grant: %lu dirty: %lu\n", exp->exp_obd->obd_name, exp->exp_client_uuid.uuid, exp, used, ungranted, fed->fed_grant, fed->fed_dirty); diff --git a/lustre/obdfilter/filter_log.c b/lustre/obdfilter/filter_log.c index d61ff41..e0230c3 100644 --- a/lustre/obdfilter/filter_log.c +++ b/lustre/obdfilter/filter_log.c @@ -145,13 +145,13 @@ static int filter_recov_log_unlink_cb(struct llog_ctxt *ctxt, rc = filter_destroy(exp, oa, NULL, NULL, NULL); OBDO_FREE(oa); if (rc == -ENOENT) { - CDEBUG(D_HA, "object already removed, send cookie\n"); + CDEBUG(D_RPCTRACE, "object already removed, send cookie\n"); llog_cancel(ctxt, NULL, 1, cookie, 0); RETURN(0); } if (rc == 0) - CDEBUG(D_HA, "object: "LPU64" in record is destroyed\n", oid); + CDEBUG(D_RPCTRACE, "object "LPU64" is destroyed\n", oid); RETURN(rc); } @@ -186,13 +186,13 @@ static int filter_recov_log_setattr_cb(struct llog_ctxt *ctxt, OBDO_FREE(oinfo.oi_oa); if (rc == -ENOENT) { - CDEBUG(D_HA, "object already removed, send cookie\n"); + CDEBUG(D_RPCTRACE, "object already removed, send cookie\n"); llog_cancel(ctxt, NULL, 1, cookie, 0); RETURN(0); } if (rc == 0) - CDEBUG(D_HA, "object: "LPU64" in record is chown/chgrp\n", oid); + CDEBUG(D_RPCTRACE, "object "LPU64" is chown/chgrp\n", oid); RETURN(rc); } diff --git a/lustre/osc/osc_create.c b/lustre/osc/osc_create.c index 5d01ce9..8a5a0ed 100644 --- a/lustre/osc/osc_create.c +++ b/lustre/osc/osc_create.c @@ -111,7 +111,7 @@ static int osc_interpret_create(struct ptlrpc_request *req, void *data, int rc) } } - CDEBUG(D_HA, "preallocated through id "LPU64" (next to use "LPU64")\n", + CDEBUG(D_RPCTRACE, "prealloc through id "LPU64", next to use "LPU64"\n", oscc->oscc_last_id, oscc->oscc_next_id); cfs_waitq_signal(&oscc->oscc_waitq); @@ -162,7 +162,7 @@ static int oscc_internal_create(struct osc_creator *oscc) body->oa.o_id = oscc->oscc_last_id + oscc->oscc_grow_count; body->oa.o_valid |= OBD_MD_FLID; spin_unlock(&oscc->oscc_lock); - CDEBUG(D_HA, "preallocating through id "LPU64" (last seen "LPU64")\n", + CDEBUG(D_RPCTRACE, "prealloc through id "LPU64" (last seen "LPU64")\n", body->oa.o_id, oscc->oscc_last_id); ptlrpc_req_set_repsize(request, 2, size); @@ -271,16 +271,13 @@ int osc_create(struct obd_export *exp, struct obdo *oa, } oscc->oscc_flags |= OSCC_FLAG_SYNC_IN_PROGRESS; spin_unlock(&oscc->oscc_lock); - CDEBUG(D_HA, "%s: oscc recovery started\n", - oscc->oscc_obd->obd_name); + CDEBUG(D_HA, "%s: oscc recovery started - delete to "LPU64"\n", + oscc->oscc_obd->obd_name, oscc->oscc_next_id - 1); /* delete from next_id on up */ oa->o_valid |= OBD_MD_FLID; oa->o_id = oscc->oscc_next_id - 1; - CDEBUG(D_HA, "%s: deleting to next_id: "LPU64"\n", - oscc->oscc_obd->obd_name, oa->o_id); - rc = osc_real_create(exp, oa, ea, NULL); spin_lock(&oscc->oscc_lock); @@ -348,7 +345,7 @@ int osc_create(struct obd_export *exp, struct obdo *oa, oscc->oscc_next_id++; try_again = 0; - CDEBUG(D_HA, "%s: set oscc_next_id = "LPU64"\n", + CDEBUG(D_RPCTRACE, "%s: set oscc_next_id = "LPU64"\n", exp->exp_obd->obd_name, oscc->oscc_next_id); } else if (oscc->oscc_flags & OSCC_FLAG_NOSPC) { rc = -ENOSPC; @@ -362,7 +359,7 @@ int osc_create(struct obd_export *exp, struct obdo *oa, } if (rc == 0) - CDEBUG(D_HA, "%s: returning objid "LPU64"\n", + CDEBUG(D_INFO, "%s: returning objid "LPU64"\n", obd2cli_tgt(oscc->oscc_obd), lsm->lsm_object_id); else if (*ea == NULL) obd_free_memmd(exp, &lsm); diff --git a/lustre/osc/osc_request.c b/lustre/osc/osc_request.c index 58f1a9e..6fa67df 100644 --- a/lustre/osc/osc_request.c +++ b/lustre/osc/osc_request.c @@ -3270,7 +3270,7 @@ static int osc_setinfo_mds_conn_interpret(struct ptlrpc_request *req, imp->imp_server_timeout = 1; imp->imp_pingable = 1; spin_unlock(&imp->imp_lock); - CDEBUG(D_HA, "pinging OST %s\n", obd2cli_tgt(imp->imp_obd)); + CDEBUG(D_RPCTRACE, "pinging OST %s\n", obd2cli_tgt(imp->imp_obd)); RETURN(rc); } diff --git a/lustre/ptlrpc/client.c b/lustre/ptlrpc/client.c index 889de36..3b74116 100644 --- a/lustre/ptlrpc/client.c +++ b/lustre/ptlrpc/client.c @@ -1116,7 +1116,7 @@ int ptlrpc_set_wait(struct ptlrpc_request_set *set) /* wait until all complete, interrupted, or an in-flight * req times out */ - CDEBUG(D_HA, "set %p going to sleep for %d seconds\n", + CDEBUG(D_RPCTRACE, "set %p going to sleep for %d seconds\n", set, timeout); lwi = LWI_TIMEOUT_INTR(cfs_time_seconds(timeout ? timeout : 1), ptlrpc_expired_set, @@ -1323,12 +1323,12 @@ void ptlrpc_free_committed(struct obd_import *imp) if (imp->imp_peer_committed_transno == imp->imp_last_transno_checked && imp->imp_generation == imp->imp_last_generation_checked) { - CDEBUG(D_HA, "%s: skip recheck for last_committed "LPU64"\n", + CDEBUG(D_RPCTRACE, "%s: skip recheck: last_committed "LPU64"\n", imp->imp_obd->obd_name, imp->imp_peer_committed_transno); return; } - - CDEBUG(D_HA, "%s: committing for last_committed "LPU64" gen %d\n", + + CDEBUG(D_RPCTRACE, "%s: committing for last_committed "LPU64" gen %d\n", imp->imp_obd->obd_name, imp->imp_peer_committed_transno, imp->imp_generation); imp->imp_last_transno_checked = imp->imp_peer_committed_transno; @@ -1342,22 +1342,22 @@ void ptlrpc_free_committed(struct obd_import *imp) last_req = req; if (req->rq_import_generation < imp->imp_generation) { - DEBUG_REQ(D_HA, req, "freeing request with old gen"); + DEBUG_REQ(D_RPCTRACE, req, "free request with old gen"); GOTO(free_req, 0); } if (req->rq_replay) { - DEBUG_REQ(D_HA, req, "keeping (FL_REPLAY)"); + DEBUG_REQ(D_RPCTRACE, req, "keeping (FL_REPLAY)"); continue; } /* not yet committed */ if (req->rq_transno > imp->imp_peer_committed_transno) { - DEBUG_REQ(D_HA, req, "stopping search"); + DEBUG_REQ(D_RPCTRACE, req, "stopping search"); break; } - DEBUG_REQ(D_HA, req, "committing (last_committed "LPU64")", + DEBUG_REQ(D_RPCTRACE, req, "commit (last_committed "LPU64")", imp->imp_peer_committed_transno); free_req: spin_lock(&req->rq_lock); @@ -1795,7 +1795,7 @@ void ptlrpc_abort_inflight(struct obd_import *imp) struct ptlrpc_request *req = list_entry(tmp, struct ptlrpc_request, rq_list); - DEBUG_REQ(D_HA, req, "inflight"); + DEBUG_REQ(D_RPCTRACE, req, "inflight"); spin_lock (&req->rq_lock); if (req->rq_import_generation < imp->imp_generation) { @@ -1809,7 +1809,7 @@ void ptlrpc_abort_inflight(struct obd_import *imp) struct ptlrpc_request *req = list_entry(tmp, struct ptlrpc_request, rq_list); - DEBUG_REQ(D_HA, req, "aborting waiting req"); + DEBUG_REQ(D_RPCTRACE, req, "aborting waiting req"); spin_lock (&req->rq_lock); if (req->rq_import_generation < imp->imp_generation) { diff --git a/lustre/ptlrpc/llog_server.c b/lustre/ptlrpc/llog_server.c index d4bd482..7b82f4e 100644 --- a/lustre/ptlrpc/llog_server.c +++ b/lustre/ptlrpc/llog_server.c @@ -434,7 +434,7 @@ pop_ctxt: if (rc) CERROR("cancel %d llog-records failed: %d\n", num_cookies, rc); else - CDEBUG(D_HA, "cancel %d llog-records\n", num_cookies); + CDEBUG(D_RPCTRACE, "cancel %d llog-records\n", num_cookies); RETURN(rc); } diff --git a/lustre/ptlrpc/pinger.c b/lustre/ptlrpc/pinger.c index 17bb313..d75d1e9 100644 --- a/lustre/ptlrpc/pinger.c +++ b/lustre/ptlrpc/pinger.c @@ -108,7 +108,7 @@ static int ptlrpc_pinger_main(void *arg) imp->imp_force_verify = 0; spin_unlock(&imp->imp_lock); - CDEBUG(level == LUSTRE_IMP_FULL ? D_INFO : D_HA, + CDEBUG(level == LUSTRE_IMP_FULL ? D_INFO : D_RPCTRACE, "level %s/%u force %u deactive %u pingable %u\n", ptlrpc_import_state_name(level), level, force, imp->imp_deactive, imp->imp_pingable); @@ -517,8 +517,8 @@ static int pinger_check_rpcs(void *arg) req->rq_import_generation = generation; ptlrpc_set_add_req(set, req); } else { - CDEBUG(D_HA, "don't need to ping %s ("CFS_TIME_T" > " - CFS_TIME_T")\n", obd2cli_tgt(imp->imp_obd), + CDEBUG(D_INFO, "don't need to ping %s ("CFS_TIME_T + " > "CFS_TIME_T")\n", obd2cli_tgt(imp->imp_obd), imp->imp_next_ping, pd->pd_this_ping); } } @@ -527,13 +527,13 @@ static int pinger_check_rpcs(void *arg) /* Might be empty, that's OK. */ if (set->set_remaining == 0) - CDEBUG(D_HA, "nothing to ping\n"); + CDEBUG(D_RPCTRACE, "nothing to ping\n"); list_for_each(iter, &set->set_requests) { struct ptlrpc_request *req = list_entry(iter, struct ptlrpc_request, rq_set_chain); - DEBUG_REQ(D_HA, req, "pinging %s->%s", + DEBUG_REQ(D_RPCTRACE, req, "pinging %s->%s", req->rq_import->imp_obd->obd_uuid.uuid, obd2cli_tgt(req->rq_import->imp_obd)); (void)ptl_send_rpc(req, 0); @@ -543,10 +543,9 @@ do_check_set: rc = ptlrpc_check_set(set); /* not finished, and we are not expired, simply return */ - if (!rc && cfs_time_before(curtime, - cfs_time_add(pd->pd_this_ping, - cfs_time_seconds(PING_INTERVAL)))) { - CDEBUG(D_HA, "not finished, but also not expired\n"); + if (!rc && cfs_time_before(curtime, cfs_time_add(pd->pd_this_ping, + cfs_time_seconds(PING_INTERVAL)))) { + CDEBUG(D_RPCTRACE, "not finished, but also not expired\n"); pd->pd_recursion--; return 0; } @@ -569,7 +568,7 @@ do_check_set: continue; } - CDEBUG(D_HA, "pinger initiate expire_one_request\n"); + CDEBUG(D_RPCTRACE, "pinger initiate expire_one_request\n"); ptlrpc_expire_one_request(req); } mutex_up(&pinger_sem); @@ -582,7 +581,7 @@ out: cfs_time_seconds(PING_INTERVAL)); pd->pd_this_ping = 0; /* XXX for debug */ - CDEBUG(D_HA, "finished a round ping\n"); + CDEBUG(D_INFO, "finished a round ping\n"); pd->pd_recursion--; return 0; } @@ -665,9 +664,8 @@ void ptlrpc_pinger_wake_up() /* XXX force pinger to run, if needed */ struct obd_import *imp; list_for_each_entry(imp, &pinger_imports, imp_pinger_chain) { - CDEBUG(D_HA, "Checking that we need to do anything about import" - " %s->%s\n", imp->imp_obd->obd_uuid.uuid, - obd2cli_tgt(imp->imp_obd)); + CDEBUG(D_RPCTRACE, "checking import %s->%s\n", + imp->imp_obd->obd_uuid.uuid, obd2cli_tgt(imp->imp_obd)); #ifdef ENABLE_LIBLUSTRE_RECOVERY if (imp->imp_state == LUSTRE_IMP_DISCON && !imp->imp_deactive) #else diff --git a/lustre/ptlrpc/recov_thread.c b/lustre/ptlrpc/recov_thread.c index b74c72e..e0b21d6 100644 --- a/lustre/ptlrpc/recov_thread.c +++ b/lustre/ptlrpc/recov_thread.c @@ -153,7 +153,7 @@ int llog_obd_repl_cancel(struct llog_ctxt *ctxt, mutex_down(&ctxt->loc_sem); if (ctxt->loc_imp == NULL) { - CDEBUG(D_HA, "no import for ctxt %p\n", ctxt); + CDEBUG(D_RPCTRACE, "no import for ctxt %p\n", ctxt); GOTO(out, rc = 0); } @@ -184,7 +184,7 @@ int llog_obd_repl_cancel(struct llog_ctxt *ctxt, if ((llcd->llcd_size - llcd->llcd_cookiebytes) < sizeof(*cookies) || (flags & OBD_LLOG_FL_SENDNOW)) { - CDEBUG(D_HA, "send llcd %p:%p\n", llcd, llcd->llcd_ctxt); + CDEBUG(D_RPCTRACE, "send llcd %p:%p\n", llcd, llcd->llcd_ctxt); ctxt->loc_llcd = NULL; llcd_send(llcd); } @@ -200,7 +200,7 @@ int llog_obd_repl_sync(struct llog_ctxt *ctxt, struct obd_export *exp) ENTRY; if (exp && (ctxt->loc_imp == exp->exp_imp_reverse)) { - CDEBUG(D_HA, "reverse import disconnected, put llcd %p:%p\n", + CDEBUG(D_RPCTRACE,"reverse import disconnect, put llcd %p:%p\n", ctxt->loc_llcd, ctxt); mutex_down(&ctxt->loc_sem); if (ctxt->loc_llcd != NULL) { @@ -335,7 +335,7 @@ static int log_commit_thread(void *arg) list_del(&llcd->llcd_list); if (llcd->llcd_cookiebytes == 0) { - CDEBUG(D_HA, "put empty llcd %p:%p\n", + CDEBUG(D_RPCTRACE, "put empty llcd %p:%p\n", llcd, llcd->llcd_ctxt); llcd_put(llcd); continue; diff --git a/lustre/ptlrpc/service.c b/lustre/ptlrpc/service.c index 96dab33..32380b3 100644 --- a/lustre/ptlrpc/service.c +++ b/lustre/ptlrpc/service.c @@ -594,7 +594,7 @@ ptlrpc_server_handle_request(struct ptlrpc_service *svc, request->rq_export->exp_obd->obd_fail) { /* Failing over, don't handle any more reqs, send error response instead. */ - CDEBUG(D_HA, "Dropping req %p for failed obd %s\n", + CDEBUG(D_RPCTRACE,"Dropping req %p for failed obd %s\n", request, request->rq_export->exp_obd->obd_name); request->rq_status = -ENODEV; ptlrpc_error(request); @@ -667,7 +667,7 @@ put_conn: request->rq_status, reply ? lustre_msg_get_status(request->rq_repmsg): -999); else - CDEBUG(D_HA, "request "LPU64" opc %u from %s processed in " + CDEBUG(D_RPCTRACE,"request "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, -- 1.8.3.1