From f3febe9d625f6b524e62aac502916e3b06ef04b1 Mon Sep 17 00:00:00 2001

From: Poornima G <pgurusid@redhat.com>

Date: Tue, 2 Aug 2016 14:51:23 +0530

Subject: [PATCH 119/141] md-cache: Add logging to increase debuggability

Change-Id: I147d16ec3c20d3372892fdd5f62010e52f82f8bd

BUG: 1284873

Signed-off-by: Poornima G <pgurusid@redhat.com>

Reviewed-on: http://review.gluster.org/15069

Smoke: Gluster Build System <jenkins@build.gluster.org>

NetBSD-regression: NetBSD Build System <jenkins@build.gluster.org>

CentOS-regression: Gluster Build System <jenkins@build.gluster.org>

Reviewed-by: Vijay Bellur <vbellur@redhat.com>

Reviewed-by: Raghavendra G <rgowdapp@redhat.com>

Reviewed-on: https://code.engineering.redhat.com/gerrit/87032

Reviewed-by: Rajesh Joseph <rjoseph@redhat.com>

Tested-by: Rajesh Joseph <rjoseph@redhat.com>

---

 .../performance/md-cache/src/md-cache-messages.h   |    4 +-

 xlators/performance/md-cache/src/md-cache.c        |   56 +++++++++++++++++---

 2 files changed, 51 insertions(+), 9 deletions(-)

diff --git a/xlators/performance/md-cache/src/md-cache-messages.h b/xlators/performance/md-cache/src/md-cache-messages.h

index a4259ba..1fe26cc 100644

--- a/xlators/performance/md-cache/src/md-cache-messages.h

+++ b/xlators/performance/md-cache/src/md-cache-messages.h

@@ -40,7 +40,7 @@

  */

 #define GLFS_MD_CACHE_BASE                   GLFS_MSGID_COMP_MD_CACHE

-#define GLFS_MD_CACHE_NUM_MESSAGES           2

+#define GLFS_MD_CACHE_NUM_MESSAGES           3

 #define GLFS_MSGID_END  (GLFS_MD_CACHE_BASE + GLFS_MD_CACHE_NUM_MESSAGES + 1)

 /* Messages with message IDs */

@@ -67,6 +67,8 @@

 #define MD_CACHE_MSG_DISCARD_UPDATE    (GLFS_MD_CACHE_BASE + 2)

+#define MD_CACHE_MSG_CACHE_UPDATE      (GLFS_MD_CACHE_BASE + 3)

+

 /*------------*/

 #define glfs_msg_end_x GLFS_MSGID_END, "Invalid: End of messages"

diff --git a/xlators/performance/md-cache/src/md-cache.c b/xlators/performance/md-cache/src/md-cache.c

index d15da04..28e7a57 100644

--- a/xlators/performance/md-cache/src/md-cache.c

+++ b/xlators/performance/md-cache/src/md-cache.c

@@ -463,6 +463,8 @@ mdc_inode_iatt_set_validate(xlator_t *this, inode_t *inode, struct iatt *prebuf,

         LOCK (&mdc->lock);

         {

                 if (!iatt || !iatt->ia_ctime) {

+                        gf_msg_trace ("md-cache", 0, "invalidating iatt(NULL)"

+                                      "(%s)", uuid_utoa (inode->gfid));

                         mdc->ia_time = 0;

                         goto unlock;

                 }

@@ -508,12 +510,22 @@ mdc_inode_iatt_set_validate(xlator_t *this, inode_t *inode, struct iatt *prebuf,

 			if (!prebuf || (prebuf->ia_ctime != mdc->md_ctime) ||

 			    (prebuf->ia_ctime_nsec != mdc->md_ctime_nsec) ||

 			    (prebuf->ia_mtime != mdc->md_mtime) ||

-			    (prebuf->ia_mtime_nsec != mdc->md_mtime_nsec))

+			    (prebuf->ia_mtime_nsec != mdc->md_mtime_nsec)) {

+                                gf_msg_trace ("md-cache", 0, "prebuf doesn't "

+                                              "match the value we have cached,"

+                                              " invalidate the inode(%s)",

+                                              uuid_utoa (inode->gfid));

+

 				inode_invalidate(inode);

+                        }

                 mdc_from_iatt (mdc, iatt);

                 time (&mdc->ia_time);

+                gf_msg_callingfn ("md-cache", GF_LOG_TRACE, 0,

+                                  MD_CACHE_MSG_CACHE_UPDATE, "Updated iatt(%s)"

+                                  " time:%lld ", uuid_utoa (inode->gfid),

+                                  (long long)mdc->ia_time);

         }

 unlock:

         UNLOCK (&mdc->lock);

@@ -533,11 +545,17 @@ mdc_inode_iatt_get (xlator_t *this, inode_t *inode, struct iatt *iatt)

         int              ret = -1;

         struct md_cache *mdc = NULL;

-        if (mdc_inode_ctx_get (this, inode, &mdc) != 0)

+        if (mdc_inode_ctx_get (this, inode, &mdc) != 0) {

+                gf_msg_trace ("md-cache", 0, "mdc_inode_ctx_get failed (%s)",

+                              uuid_utoa (inode->gfid));

                 goto out;

+        }

-	if (!is_md_cache_iatt_valid (this, mdc))

+	if (!is_md_cache_iatt_valid (this, mdc)) {

+                gf_msg_trace ("md-cache", 0, "iatt cache not valid for (%s)",

+                              uuid_utoa (inode->gfid));

 		goto out;

+        }

         LOCK (&mdc->lock);

         {

@@ -644,12 +662,17 @@ mdc_inode_xatt_set (xlator_t *this, inode_t *inode, dict_t *dict)

         if (!mdc)

                 goto out;

-        if (!dict)

+        if (!dict) {

+                gf_msg_trace ("md-cache", 0, "mdc_inode_xatt_set failed (%s) "

+                              "dict NULL", uuid_utoa (inode->gfid));

                 goto out;

+        }

         LOCK (&mdc->lock);

         {

                 if (mdc->xattr) {

+                        gf_msg_trace ("md-cache", 0, "deleteing the old xattr "

+                              "cache (%s)", uuid_utoa (inode->gfid));

                         dict_unref (mdc->xattr);

 			mdc->xattr = NULL;

 		}

@@ -664,6 +687,9 @@ mdc_inode_xatt_set (xlator_t *this, inode_t *inode, dict_t *dict)

 			mdc->xattr = newdict;

                 time (&mdc->xa_time);

+                gf_msg_trace ("md-cache", 0, "xatt cache set for (%s) time:%lld",

+                              uuid_utoa (inode->gfid), (long long)mdc->xa_time);

+

         }

         UNLOCK (&mdc->lock);

         ret = 0;

@@ -734,11 +760,17 @@ mdc_inode_xatt_get (xlator_t *this, inode_t *inode, dict_t **dict)

         int              ret = -1;

         struct md_cache *mdc = NULL;

-        if (mdc_inode_ctx_get (this, inode, &mdc) != 0)

+        if (mdc_inode_ctx_get (this, inode, &mdc) != 0) {

+                gf_msg_trace ("md-cache", 0, "mdc_inode_ctx_get failed (%s)",

+                              uuid_utoa (inode->gfid));

                 goto out;

+        }

-	if (!is_md_cache_xatt_valid (this, mdc))

+	if (!is_md_cache_xatt_valid (this, mdc)) {

+                gf_msg_trace ("md-cache", 0, "xattr cache not valid for (%s)",

+                              uuid_utoa (inode->gfid));

 		goto out;

+        }

         LOCK (&mdc->lock);

         {

@@ -746,8 +778,11 @@ mdc_inode_xatt_get (xlator_t *this, inode_t *inode, dict_t **dict)

 		/* Missing xattr only means no keys were there, i.e

 		   a negative cache for the "loaded" keys

 		*/

-                if (!mdc->xattr)

+                if (!mdc->xattr) {

+                        gf_msg_trace ("md-cache", 0, "xattr not present (%s)",

+                                      uuid_utoa (inode->gfid));

                         goto unlock;

+                }

                 if (dict)

                         *dict = dict_ref (mdc->xattr);

@@ -883,6 +918,8 @@ is_mdc_key_satisfied (const char *key)

 			return 1;

 	}

+        gf_msg_trace ("md-cache", 0, "xattr key %s doesn't satisfy "

+                      "caching requirements", key);

 	return 0;

 }

@@ -961,12 +998,15 @@ mdc_lookup (call_frame_t *frame, xlator_t *this, loc_t *loc,

         loc_copy (&local->loc, loc);

-	if (!loc->name)

+	if (!loc->name) {

+                gf_msg_trace ("md-cache", 0, "Nameless lookup(%s) sent to the "

+                              "brick", uuid_utoa (loc->inode->gfid));

 		/* A nameless discovery is dangerous to serve from cache. We

 		   perform nameless lookup with the intention of

 		   re-establishing an inode "properly"

 		*/

 		goto uncached;

+        }

         ret = mdc_inode_iatt_get (this, loc->inode, &stbuf);

         if (ret != 0)

-- 

1.7.1