From ec37d78caf6cbd8118cfe1ff012c828950356e7a Mon Sep 17 00:00:00 2001 From: Fan Yong Date: Sat, 6 Sep 2014 12:39:46 +0800 Subject: [PATCH] LU-5848 debug: more debug log for dt_sync Add some D_CACHE logs at the entry/exit for osp_sync()/osd_sync(). Signed-off-by: Fan Yong Change-Id: Iaa7fbfbbadb9312528b5092d64615b277de6b679 Reviewed-on: http://review.whamcloud.com/12573 Tested-by: Jenkins Tested-by: Maloo Reviewed-by: Lai Siyao Reviewed-by: Alex Zhuravlev Reviewed-by: Oleg Drokin --- lustre/lfsck/lfsck_engine.c | 18 +++++++++++++++--- lustre/osd-ldiskfs/osd_handler.c | 12 ++++++++++-- lustre/osd-zfs/osd_handler.c | 3 ++- lustre/osp/osp_dev.c | 9 +++++---- lustre/tests/sanity-lfsck.sh | 8 ++++---- 5 files changed, 36 insertions(+), 14 deletions(-) diff --git a/lustre/lfsck/lfsck_engine.c b/lustre/lfsck/lfsck_engine.c index 196eb43..3c98c2b 100644 --- a/lustre/lfsck/lfsck_engine.c +++ b/lustre/lfsck/lfsck_engine.c @@ -1616,6 +1616,7 @@ int lfsck_assistant_engine(void *args) struct l_wait_info lwi = { 0 }; int rc = 0; int rc1 = 0; + int rc2; ENTRY; CDEBUG(D_LFSCK, "%s: %s LFSCK assistant thread start\n", @@ -1725,11 +1726,16 @@ int lfsck_assistant_engine(void *args) com->lc_time_last_checkpoint + cfs_time_seconds(LFSCK_CHECKPOINT_INTERVAL); + CDEBUG(D_LFSCK, "%s: LFSCK assistant sync before " + "the second-stage scaning\n", + lfsck_lfsck2name(lfsck)); + /* Flush async updates before handling orphan. */ - dt_sync(env, lfsck->li_next); + rc2 = dt_sync(env, lfsck->li_next); CDEBUG(D_LFSCK, "%s: LFSCK assistant phase2 " - "scan start\n", lfsck_lfsck2name(lfsck)); + "scan start, synced: rc = %d\n", + lfsck_lfsck2name(lfsck), rc2); if (OBD_FAIL_CHECK(OBD_FAIL_LFSCK_NO_DOUBLESCAN)) GOTO(cleanup2, rc = 0); @@ -1846,8 +1852,14 @@ cleanup2: rc = rc1; } + CDEBUG(D_LFSCK, "%s: LFSCK assistant sync before exit\n", + lfsck_lfsck2name(lfsck)); + /* Flush async updates before exit. */ - dt_sync(env, lfsck->li_next); + rc2 = dt_sync(env, lfsck->li_next); + + CDEBUG(D_LFSCK, "%s: LFSCK assistant synced before exit: rc = %d\n", + lfsck_lfsck2name(lfsck), rc2); /* Under force exit case, some requests may be just freed without * verification, those objects should be re-handled when next run. diff --git a/lustre/osd-ldiskfs/osd_handler.c b/lustre/osd-ldiskfs/osd_handler.c index 3c09617..0602184 100644 --- a/lustre/osd-ldiskfs/osd_handler.c +++ b/lustre/osd-ldiskfs/osd_handler.c @@ -1356,8 +1356,16 @@ static void osd_conf_get(const struct lu_env *env, */ static int osd_sync(const struct lu_env *env, struct dt_device *d) { - CDEBUG(D_HA, "syncing OSD %s\n", LUSTRE_OSD_LDISKFS_NAME); - return ldiskfs_force_commit(osd_sb(osd_dt_dev(d))); + int rc; + + CDEBUG(D_CACHE, "syncing OSD %s\n", LUSTRE_OSD_LDISKFS_NAME); + + rc = ldiskfs_force_commit(osd_sb(osd_dt_dev(d))); + + CDEBUG(D_CACHE, "synced OSD %s: rc = %d\n", + LUSTRE_OSD_LDISKFS_NAME, rc); + + return rc; } /** diff --git a/lustre/osd-zfs/osd_handler.c b/lustre/osd-zfs/osd_handler.c index dfbd45f..4c60943 100644 --- a/lustre/osd-zfs/osd_handler.c +++ b/lustre/osd-zfs/osd_handler.c @@ -538,8 +538,9 @@ static void osd_conf_get(const struct lu_env *env, static int osd_sync(const struct lu_env *env, struct dt_device *d) { struct osd_device *osd = osd_dt_dev(d); - CDEBUG(D_HA, "syncing OSD %s\n", LUSTRE_OSD_ZFS_NAME); + CDEBUG(D_CACHE, "syncing OSD %s\n", LUSTRE_OSD_ZFS_NAME); txg_wait_synced(dmu_objset_pool(osd->od_os), 0ULL); + CDEBUG(D_CACHE, "synced OSD %s\n", LUSTRE_OSD_ZFS_NAME); return 0; } diff --git a/lustre/osp/osp_dev.c b/lustre/osp/osp_dev.c index 8b038a1..00e5da0 100644 --- a/lustre/osp/osp_dev.c +++ b/lustre/osp/osp_dev.c @@ -709,7 +709,7 @@ static int osp_sync(const struct lu_env *env, struct dt_device *dev) if (rc != 0) GOTO(out, rc); - CDEBUG(D_OTHER, "%s: id: used %lu, processed %lu\n", + CDEBUG(D_CACHE, "%s: id: used %lu, processed %lu\n", d->opd_obd->obd_name, id, d->opd_syn_last_processed_id); /* wait till all-in-line are processed */ @@ -741,7 +741,7 @@ static int osp_sync(const struct lu_env *env, struct dt_device *dev) /* block new processing (barrier>0 - few callers are possible */ atomic_inc(&d->opd_syn_barrier); - CDEBUG(D_OTHER, "%s: %u in flight\n", d->opd_obd->obd_name, + CDEBUG(D_CACHE, "%s: %u in flight\n", d->opd_obd->obd_name, d->opd_syn_rpc_in_flight); /* wait till all-in-flight are replied, so executed by the target */ @@ -770,13 +770,14 @@ static int osp_sync(const struct lu_env *env, struct dt_device *dev) GOTO(out, rc = -ETIMEDOUT); } - CDEBUG(D_OTHER, "%s: done in %lu\n", d->opd_obd->obd_name, - cfs_time_current() - start); out: /* resume normal processing (barrier=0) */ atomic_dec(&d->opd_syn_barrier); __osp_sync_check_for_work(d); + CDEBUG(D_CACHE, "%s: done in %lu: rc = %d\n", d->opd_obd->obd_name, + cfs_time_current() - start, rc); + RETURN(rc); } diff --git a/lustre/tests/sanity-lfsck.sh b/lustre/tests/sanity-lfsck.sh index 0ece9cd..e563d03 100644 --- a/lustre/tests/sanity-lfsck.sh +++ b/lustre/tests/sanity-lfsck.sh @@ -54,8 +54,6 @@ setupall build_test_filter -$LCTL set_param debug=+lfsck > /dev/null || true - MDT_DEV="${FSNAME}-MDT0000" OST_DEV="${FSNAME}-OST0000" MDT_DEVNAME=$(mdsdevname ${SINGLEMDS//mds/}) @@ -1658,6 +1656,8 @@ test_17() { } run_test 17 "LFSCK can repair multiple references" +$LCTL set_param debug=+cache > /dev/null + test_18a() { echo "#####" echo "The target MDT-object is there, but related stripe information" @@ -2345,6 +2345,8 @@ test_18f() { } run_test 18f "Skip the failed OST(s) when handle orphan OST-objects" +$LCTL set_param debug=-cache > /dev/null + test_19a() { check_mount_and_prep $LFS setstripe -c 1 -i 0 $DIR/$tdir @@ -4142,8 +4144,6 @@ test_31h() { } run_test 31h "Repair the corrupted shard's name entry" -$LCTL set_param debug=-lfsck > /dev/null || true - # restore MDS/OST size MDSSIZE=${SAVED_MDSSIZE} OSTSIZE=${SAVED_OSTSIZE} -- 1.8.3.1