From f3febe9d625f6b524e62aac502916e3b06ef04b1 Mon Sep 17 00:00:00 2001 From: Poornima G 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 Reviewed-on: http://review.gluster.org/15069 Smoke: Gluster Build System NetBSD-regression: NetBSD Build System CentOS-regression: Gluster Build System Reviewed-by: Vijay Bellur Reviewed-by: Raghavendra G Reviewed-on: https://code.engineering.redhat.com/gerrit/87032 Reviewed-by: Rajesh Joseph Tested-by: Rajesh Joseph --- .../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