LU-988 llite: 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: Iae09d2361e81c05ccc5883dd4418067d9a90abab
Reviewed-on: http://review.whamcloud.com/2274
Tested-by: Hudson
Reviewed-by: Andreas Dilger <adilger@whamcloud.com>
Tested-by: Maloo <whamcloud.maloo@gmail.com>
Reviewed-by: Oleg Drokin <green@whamcloud.com>

diff --git a/lustre/lov/lov_merge.c b/lustre/lov/lov_merge.c
index 4e3eb72..f74ff0d 100644 (file)
--- a/lustre/lov/lov_merge.c
+++ b/lustre/lov/lov_merge.c
@@ -95,6 +95,12 @@ int lov_merge_lvb_kms(struct lov_stripe_md *lsm,
                         current_atime = loi->loi_lvb.lvb_atime;
                 if (loi->loi_lvb.lvb_ctime > current_ctime)
                         current_ctime = loi->loi_lvb.lvb_ctime;
+               CDEBUG(D_INODE, "MDT FID "DFID" on OST[%u]: 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), loi->loi_ost_idx,
+                      lvb->lvb_size, lvb->lvb_mtime, lvb->lvb_atime,
+                      lvb->lvb_ctime, lvb->lvb_blocks);
         }
 
         *kms_place = kms;
@@ -125,9 +131,11 @@ int lov_merge_lvb(struct obd_export *exp,
         rc = lov_merge_lvb_kms(lsm, lvb, &kms);
         if (kms_only)
                 lvb->lvb_size = kms;
-        CDEBUG(D_INODE, "merged: "LPU64" "LPU64" "LPU64" "LPU64" "LPU64"\n",
-               lvb->lvb_size, lvb->lvb_mtime, lvb->lvb_atime,
-               lvb->lvb_ctime, lvb->lvb_blocks);
+       CDEBUG(D_INODE, "merged for FID "DFID" 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);
         RETURN(rc);
 }
 

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