diff --git a/lustre/ChangeLog b/lustre/ChangeLog index 94b4f785104d25beff919d1a49366f294537a363..115296e645611baccb434c2804ba57abe0abe1e9 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. <info@clusterfs.com> diff --git a/lustre/ldlm/ldlm_lib.c b/lustre/ldlm/ldlm_lib.c index 54a176ac48dd666de26e3c3586a84cd67e292485..5d4e6084136d74300e206049416685c891fc67d5 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 ed48f82959a4c921e5f12d3a3b6b7e456ec8b50e..c582e350d53a561f6db879899519f19b89c6f52f 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 1a6dbc2db88b1be4fdd13581c0c36880ae3f2c20..9c73ecf3e05ecd147720927880d87195eee7b4db 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 0fefc5ebe1969765d73bf3da1bc22b143a3b56d0..4c9411e60c96f6281e055dc45af9a3617c684c70 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 fc3d0d7fa2dbbbfdcf3e25e2dc2f3007f04df9a3..439d34b56ec5120307fd9dedc9923c7a8076186f 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 2db5d90d311f2ff6963fc39bcd48b02c5148bd15..87c6b8ee9fce94b796025eed23349497f32bf504 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 bb148d75b17660ee321c12f1773227def6290231..43dc9a4d44d844b52081b36fedd1ce870e95c385 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 14f095b3ca8c50f41bdb24e23c1348ff7f9d9eaa..2477d580c55352ede703e7fc7d03f1e9ce918fa0 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 a0ab48e5b8f8307bbaeeac94e858099288b7000a..d2db5cb5aa93d04e2a4372ffd3ed96413e54cd00 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 36f893e764b8e3fd5bc61d415aa79add25e4a136..36e1617b1d48c3be82cb95a0b936d08a1cbad087 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 7f69d5d366f6212a2f61c341269089f24046bf7c..0c2f6edaae77722deb5de886185be089058dced8 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 e2ec61d1eea930b80c68fadfee9b47a59260dfed..67a4f2671c64001f28f3ab4a5d691f71e1e1d2e3 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 d768886ce6922a486e11d201a3286b5922c397a9..cc7ffe059e3a14f99f690922785cef49de3c1e5b 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 9b3790a2d506697bfc17015f90df822aa8bf2ac0..9617612db4d500bf7a1d7e5baacb7d2c93536539 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 217b3f86a2f376ff553bda747cf9c7397b9c6b8f..977b489367f4a9b38351ce9bccab8af634398e84 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 e42fab86ba45ffb7829cde53666b32d0637f7aa5..e4c9ba2bfdc7f88c2e2bda2865b2ee1e39d13f1a 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 5e6200d67c7a0498d77c5b6e030efb72f4fb6dea..2303a4ba82b72deee70cd9745716add861be9ee5 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 6cf90d11339cf7b377f9d190f94d6543d7bfcc98..c1eff406c09e2d8095ad7f492a70925de54ce82b 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 45b1ec1152333106fdd00960b58442a18d5d2c59..cc5b9619df12df45e79e47facc80fce4a1fe4c27 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 029eaf406aed65231e3d8b27c178b3f72b8242f2..3869cf117c04f6d809a2250b3b81a109f3e9d6c6 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 d61ff4142f8149905b7a3ab25317e6799a6f27d8..e0230c3ad1f4a3f4f7dee7a094305fddb43caea3 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 5d01ce9a6b8959125afe7305ba1c871414dadee3..8a5a0ed20b6d3b832c87dec12603af1460f78597 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 58f1a9e5133777c13af75aedf8f895779f221937..6fa67dffbc79a24afb3e3ae49342bec7cd2d6869 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 889de36609f7c75254ae44f6e00bd22636e9e996..3b74116a500302cfd8488ee8e26bbcc053071b01 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 d4bd4828ee05ec98f404324e936d4455a51d9799..7b82f4eb42b1c77bfe6238ab00d50a274abfde05 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 17bb313214dd63936c4bd870277a057f6a03fe4f..d75d1e90e1caff29271a4b05a740fc081f1dc182 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 b74c72ec1a1bd49b0cc6150ead3c2e4ade5e3ad3..e0b21d64c5b69f0b7a859f0be487cceebfe0dc93 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 96dab33d737654e3b1a42046547c2d867193bbef..32380b3c603ad4f1827077a05b66f3c2da2c6d50 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,