LU-988 ost: add debugging for inode timestamps

Intermittent test failures for sanity.sh test_39j are showing the
inode timestamps going backward. Add internal debugging to track the
LVB timestamps to see where the old timestamps are coming from, to
determine if this is a problem with the VM environment being used for
testing, or if it is a genuine problem in the Lustre code.

Signed-off-by: Bobi Jam <bobijam@whamcloud.com>
Change-Id: I590d8b28b7a37010af6a43d329917022b840d074
Reviewed-on: http://review.whamcloud.com/3069
Tested-by: Hudson
Tested-by: Maloo <whamcloud.maloo@gmail.com>
Reviewed-by: Lai Siyao <laisiyao@whamcloud.com>
Reviewed-by: Fan Yong <yong.fan@whamcloud.com>
Reviewed-by: Andreas Dilger <adilger@whamcloud.com>

diff --git a/lustre/lov/lov_merge.c b/lustre/lov/lov_merge.c
index f74ff0d..bb29f48 100644 (file)
--- a/lustre/lov/lov_merge.c
+++ b/lustre/lov/lov_merge.c
@@ -67,6 +67,11 @@ int lov_merge_lvb_kms(struct lov_stripe_md *lsm,
         LASSERT(lsm->lsm_lock_owner == cfs_curproc_pid());
 #endif
 
+       CDEBUG(D_INODE, "MDT FID "DFID" initial value: s="LPU64" m="LPU64
+              " a="LPU64" c="LPU64" b="LPU64"\n",
+              lsm->lsm_object_seq, (__u32)lsm->lsm_object_id,
+              (__u32)(lsm->lsm_object_id >> 32), lvb->lvb_size,
+              lvb->lvb_mtime, lvb->lvb_atime, lvb->lvb_ctime, lvb->lvb_blocks);
         for (i = 0; i < lsm->lsm_stripe_count; i++) {
                 struct lov_oinfo *loi = lsm->lsm_oinfo[i];
                 obd_size lov_size, tmpsize;
@@ -99,8 +104,9 @@ int lov_merge_lvb_kms(struct lov_stripe_md *lsm,
                       " a="LPU64" c="LPU64" b="LPU64"\n",
                       lsm->lsm_object_seq, (__u32)lsm->lsm_object_id,
                       (__u32)(lsm->lsm_object_id >> 32), loi->loi_ost_idx,
-                      lvb->lvb_size, lvb->lvb_mtime, lvb->lvb_atime,
-                      lvb->lvb_ctime, lvb->lvb_blocks);
+                      loi->loi_lvb.lvb_size, loi->loi_lvb.lvb_mtime,
+                      loi->loi_lvb.lvb_atime, loi->loi_lvb.lvb_ctime,
+                      loi->loi_lvb.lvb_blocks);
         }
 
         *kms_place = kms;

diff --git a/lustre/obdfilter/filter_io_26.c b/lustre/obdfilter/filter_io_26.c
index 26fb2cf..6feac45 100644 (file)
--- a/lustre/obdfilter/filter_io_26.c
+++ b/lustre/obdfilter/filter_io_26.c
@@ -758,6 +758,11 @@ retry:
                 iattr.ia_valid = save & ~(ATTR_UID | ATTR_GID);
         }
 
+       CDEBUG(D_INODE, "FID "DFID" to write: s="LPU64" m="LPU64" a="LPU64
+                       " c="LPU64" b="LPU64"\n",
+                       oa->o_id, (__u32)oa->o_seq, (__u32)oa->o_seq,
+                       oa->o_size, oa->o_mtime, oa->o_atime, oa->o_ctime,
+                       oa->o_blocks);
         /* filter_direct_io drops i_mutex */
         rc = filter_direct_io(OBD_BRW_WRITE, res->dentry, iobuf, exp, &iattr,
                               oti, sync_journal_commit ? &wait_handle : NULL);
@@ -772,6 +777,11 @@ retry:
         obdo_from_inode(oa, inode, (rc == 0 ? FILTER_VALID_FLAGS : 0) |
                                    OBD_MD_FLUID | OBD_MD_FLGID);
 
+       CDEBUG(D_INODE, "FID "DFID" after write: s="LPU64" m="LPU64" a="LPU64
+                       " c="LPU64" b="LPU64"\n",
+                       oa->o_id, (__u32)oa->o_seq, (__u32)oa->o_seq,
+                       oa->o_size, oa->o_mtime, oa->o_atime, oa->o_ctime,
+                       oa->o_blocks);
         lquota_getflag(filter_quota_interface_ref, obd, oa);
 
         fsfilt_check_slow(obd, now, "direct_io");

diff --git a/lustre/tests/sanity.sh b/lustre/tests/sanity.sh
index a008b0b..190f128 100644 (file)
--- a/lustre/tests/sanity.sh
+++ b/lustre/tests/sanity.sh
@@ -2426,8 +2426,7 @@ test_39i() {
 run_test 39i "write, rename, stat =============================="
 
 test_39j() {
-       debugsave
-       lctl set_param debug=-1
+       start_full_debug_logging
        touch $DIR1/$tfile
        sleep 1
 
@@ -2448,7 +2447,7 @@ test_39j() {
                cancel_lru_locks osc
                if [ $i = 0 ] ; then echo "repeat after cancel_lru_locks"; fi
        done
-       debugrestore
+       stop_full_debug_logging
 }
 run_test 39j "write, rename, close, stat ======================="