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 <fan.yong@intel.com>
Change-Id: Iaa7fbfbbadb9312528b5092d64615b277de6b679
Reviewed-on: http://review.whamcloud.com/12573
Tested-by: Jenkins
Tested-by: Maloo <hpdd-maloo@intel.com>
Reviewed-by: Lai Siyao <lai.siyao@intel.com>
Reviewed-by: Alex Zhuravlev <alexey.zhuravlev@intel.com>
Reviewed-by: Oleg Drokin <oleg.drokin@intel.com>

diff --git a/lustre/lfsck/lfsck_engine.c b/lustre/lfsck/lfsck_engine.c
index 196eb43..3c98c2b 100644 (file)
--- 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 (file)
--- 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 (file)
--- 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 (file)
--- 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 (file)
--- 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}