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