performance/io-cache: logging enhancements

Signed-off-by: Amar Tumballi <amar@gluster.com>
Signed-off-by: Vijay Bellur <vijay@dev.gluster.com>

BUG: 2346 (Log message enhancements in GlusterFS - phase 1)
URL: http://bugs.gluster.com/cgi-bin/bugzilla3/show_bug.cgi?id=2346

3 files changed, 172 insertions, 65 deletions

diff --git a/xlators/performance/io-cache/src/io-cache.c b/xlators/performance/io-cache/src/io-cache.c
index be7227e9948..738bd66a2b6 100644
--- a/xlators/performance/io-cache/src/io-cache.c
+++ b/xlators/performance/io-cache/src/io-cache.c
@@ -1826,6 +1826,7 @@ init (xlator_t *this)
 	char            *cache_size_string = NULL, *tmp = NULL;
         int32_t          ret = -1;
         glusterfs_ctx_t *ctx = NULL;
+        data_t          *data = 0;
 
 	if (!this->children || this->children->next) {
 		gf_log (this->name, GF_LOG_ERROR,
@@ -1849,9 +1850,10 @@ init (xlator_t *this)
 	table->page_size = this->ctx->page_size;
 	table->cache_size = IOC_CACHE_SIZE;
 
-	if (dict_get (options, "cache-size"))
-		cache_size_string = data_to_str (dict_get (options,
-							   "cache-size"));
+        data = dict_get (options, "cache-size");
+        if (data)
+		cache_size_string = data_to_str (data);
+
 	if (cache_size_string) {
 		if (gf_string2bytesize (cache_size_string,
 					&table->cache_size) != 0) {
@@ -1868,10 +1870,9 @@ init (xlator_t *this)
 
 	table->cache_timeout = 1;
 
-	if (dict_get (options, "cache-timeout")) {
-		table->cache_timeout =
-			data_to_uint32 (dict_get (options,
-						  "cache-timeout"));
+	data = dict_get (options, "cache-timeout");
+        if (data) {
+		table->cache_timeout = data_to_uint32 (data);
 		gf_log (this->name, GF_LOG_TRACE,
 			"Using %d seconds to revalidate cache",
 			table->cache_timeout);
@@ -1879,9 +1880,9 @@ init (xlator_t *this)
 
 	INIT_LIST_HEAD (&table->priority_list);
 	table->max_pri = 1;
-	if (dict_get (options, "priority")) {
-		char *option_list = data_to_str (dict_get (options,
-							   "priority"));
+        data = dict_get (options, "priority");
+        if (data) {
+		char *option_list = data_to_str (data);
 		gf_log (this->name, GF_LOG_TRACE,
 			"option path %s", option_list);
 		/* parse the list of pattern:priority */
@@ -1896,7 +1897,10 @@ init (xlator_t *this)
 
         table->min_file_size = 0;
 
-        tmp = data_to_str (dict_get (options, "min-file-size"));
+        data = dict_get (options, "min-file-size");
+        if (data)
+                tmp = data_to_str (data);
+
         if (tmp != NULL) {
 		if (gf_string2bytesize (tmp,
                                         (uint64_t *)&table->min_file_size) != 0) {
@@ -1910,8 +1914,12 @@ init (xlator_t *this)
 			"using min-file-size %"PRIu64"", table->min_file_size);
         }
 
+        tmp = NULL;
         table->max_file_size = -1;
-        tmp = data_to_str (dict_get (options, "max-file-size"));
+        data = dict_get (options, "max-file-size");
+        if (data)
+                tmp = data_to_str (data);
+
         if (tmp != NULL) {
                 if (gf_string2bytesize (tmp,
                                         (uint64_t *)&table->max_file_size) != 0) {
diff --git a/xlators/performance/io-cache/src/ioc-inode.c b/xlators/performance/io-cache/src/ioc-inode.c
index 1beb9efd429..e268cac2621 100644
--- a/xlators/performance/io-cache/src/ioc-inode.c
+++ b/xlators/performance/io-cache/src/ioc-inode.c
@@ -36,8 +36,11 @@ void *
 str_to_ptr (char *string)
 {
         void *ptr = NULL;
+        GF_VALIDATE_OR_GOTO ("io-cache", string, out);
 
         ptr = (void *)strtoul (string, NULL, 16);
+
+out:
         return ptr;
 }
 
@@ -52,12 +55,18 @@ ptr_to_str (void *ptr)
 {
         int   ret = 0;
         char *str = NULL;
+
+        GF_VALIDATE_OR_GOTO ("io-cache", ptr, out);
+
         ret = gf_asprintf (&str, "%p", ptr);
         if (-1 == ret) {
-                gf_log ("ioc", GF_LOG_ERROR,
+                gf_log ("io-cache", GF_LOG_WARNING,
                         "asprintf failed while converting ptr to str");
-                return NULL;
+                str = NULL;
+                goto out;
         }
+
+out:
         return str;
 }
 
@@ -73,7 +82,18 @@ ioc_inode_wakeup (call_frame_t *frame, ioc_inode_t *ioc_inode,
         int8_t       need_fault        = 0;
         ioc_page_t  *waiter_page       = NULL;
 
+        GF_VALIDATE_OR_GOTO ("io-cache", frame, out);
+
         local = frame->local;
+        GF_VALIDATE_OR_GOTO (frame->this->name, local, out);
+
+        if (ioc_inode == NULL) {
+                local->op_ret = -1;
+                local->op_errno = EINVAL;
+                gf_log (frame->this->name, GF_LOG_WARNING, "ioc_inode is NULL");
+                goto out;
+        }
+
         ioc_inode_lock (ioc_inode);
         {
                 waiter = ioc_inode->waitq;
@@ -87,7 +107,7 @@ ioc_inode_wakeup (call_frame_t *frame, ioc_inode_t *ioc_inode,
                 cache_still_valid = 0;
 
         if (!waiter) {
-                gf_log (frame->this->name, GF_LOG_DEBUG,
+                gf_log (frame->this->name, GF_LOG_WARNING,
                         "cache validate called without any "
                         "page waiting to be validated");
         }
@@ -117,8 +137,7 @@ ioc_inode_wakeup (call_frame_t *frame, ioc_inode_t *ioc_inode,
                                         waiter_page->ready = 0;
                                         need_fault = 1;
                                 } else {
-                                        gf_log (frame->this->name,
-                                                GF_LOG_TRACE,
+                                        gf_log (frame->this->name, GF_LOG_TRACE,
                                                 "validate frame(%p) is waiting"
                                                 "for in-transit page = %p",
                                                 frame, waiter_page);
@@ -141,6 +160,9 @@ ioc_inode_wakeup (call_frame_t *frame, ioc_inode_t *ioc_inode,
                 waited->data = NULL;
                 GF_FREE (waited);
         }
+
+out:
+        return;
 }
 
 
@@ -159,6 +181,8 @@ ioc_inode_update (ioc_table_t *table, inode_t *inode, uint32_t weight)
 {
         ioc_inode_t     *ioc_inode   = NULL;
 
+        GF_VALIDATE_OR_GOTO ("io-cache", table, out);
+
         ioc_inode = GF_CALLOC (1, sizeof (ioc_inode_t), gf_ioc_mt_ioc_inode_t);
         if (ioc_inode == NULL) {
                 goto out;
@@ -166,21 +190,20 @@ ioc_inode_update (ioc_table_t *table, inode_t *inode, uint32_t weight)
 
         ioc_inode->table = table;
         INIT_LIST_HEAD (&ioc_inode->cache.page_lru);
+        pthread_mutex_init (&ioc_inode->inode_lock, NULL);
+        ioc_inode->weight = weight;
 
         ioc_table_lock (table);
-
-        table->inode_count++;
-        list_add (&ioc_inode->inode_list, &table->inodes);
-        list_add_tail (&ioc_inode->inode_lru, &table->inode_lru[weight]);
-
-        gf_log (table->xl->name,
-                GF_LOG_TRACE,
-                "adding to inode_lru[%d]", weight);
-
+        {
+                table->inode_count++;
+                list_add (&ioc_inode->inode_list, &table->inodes);
+                list_add_tail (&ioc_inode->inode_lru,
+                               &table->inode_lru[weight]);
+        }
         ioc_table_unlock (table);
 
-        pthread_mutex_init (&ioc_inode->inode_lock, NULL);
-        ioc_inode->weight = weight;
+        gf_log (table->xl->name, GF_LOG_TRACE,
+                "adding to inode_lru[%d]", weight);
 
 out:
         return ioc_inode;
@@ -199,12 +222,16 @@ ioc_inode_destroy (ioc_inode_t *ioc_inode)
 {
         ioc_table_t *table = NULL;
 
+        GF_VALIDATE_OR_GOTO ("io-cache", ioc_inode, out);
+
         table = ioc_inode->table;
 
         ioc_table_lock (table);
-        table->inode_count--;
-        list_del (&ioc_inode->inode_list);
-        list_del (&ioc_inode->inode_lru);
+        {
+                table->inode_count--;
+                list_del (&ioc_inode->inode_list);
+                list_del (&ioc_inode->inode_lru);
+        }
         ioc_table_unlock (table);
 
         ioc_inode_flush (ioc_inode);
@@ -212,4 +239,6 @@ ioc_inode_destroy (ioc_inode_t *ioc_inode)
 
         pthread_mutex_destroy (&ioc_inode->inode_lock);
         GF_FREE (ioc_inode);
+out:
+        return;
 }
diff --git a/xlators/performance/io-cache/src/page.c b/xlators/performance/io-cache/src/page.c
index 38bb98fbc67..b50b245ac0b 100644
--- a/xlators/performance/io-cache/src/page.c
+++ b/xlators/performance/io-cache/src/page.c
@@ -34,9 +34,17 @@
 char
 ioc_empty (struct ioc_cache *cache)
 {
-        return list_empty (&cache->page_lru);
+        char is_empty = -1;
+
+        GF_VALIDATE_OR_GOTO ("io-cache", cache, out);
+
+        is_empty = list_empty (&cache->page_lru);
+
+out:
+        return is_empty;
 }
 
+
 ioc_page_t *
 ioc_page_get (ioc_inode_t *ioc_inode, off_t offset)
 {
@@ -44,7 +52,11 @@ ioc_page_get (ioc_inode_t *ioc_inode, off_t offset)
         ioc_table_t  *table          = NULL;
         off_t         rounded_offset = 0;
 
+        GF_VALIDATE_OR_GOTO ("io-cache", ioc_inode, out);
+
         table = ioc_inode->table;
+        GF_VALIDATE_OR_GOTO ("io-cache", ioc_inode, out);
+
         rounded_offset = floor (offset, table->page_size);
 
         page = rbthash_get (ioc_inode->cache.page_table, &rounded_offset,
@@ -55,6 +67,7 @@ ioc_page_get (ioc_inode_t *ioc_inode, off_t offset)
                 list_move_tail (&page->page_lru, &ioc_inode->cache.page_lru);
         }
 
+out:
         return page;
 }
 
@@ -70,6 +83,8 @@ ioc_page_destroy (ioc_page_t *page)
 {
         int64_t  page_size = 0;
 
+        GF_VALIDATE_OR_GOTO ("io-cache", page, out);
+
         page_size = iobref_size (page->iobref);
 
         if (page->waitq) {
@@ -99,6 +114,7 @@ ioc_page_destroy (ioc_page_t *page)
                 GF_FREE (page);
         }
 
+out:
         return page_size;
 }
 
@@ -119,6 +135,8 @@ ioc_prune (ioc_table_t *table)
         uint64_t     size_to_prune = 0;
         uint64_t     size_pruned   = 0;
 
+        GF_VALIDATE_OR_GOTO ("io-cache", table, out);
+
         ioc_table_lock (table);
         {
                 size_to_prune = table->cache_used - table->cache_size;
@@ -145,8 +163,7 @@ ioc_prune (ioc_table_t *table)
                                         if (ret != -1)
                                                 table->cache_used -= ret;
 
-                                        gf_log (table->xl->name,
-                                                GF_LOG_TRACE,
+                                        gf_log (table->xl->name, GF_LOG_TRACE,
                                                 "index = %d && table->cache_"
                                                 "used = %"PRIu64" && table->"
                                                 "cache_size = %"PRIu64,
@@ -156,6 +173,7 @@ ioc_prune (ioc_table_t *table)
                                         if (size_pruned >= size_to_prune)
                                                 break;
                                 } /* list_for_each_entry_safe(page...) */
+
                                 if (ioc_empty (&curr->cache)) {
                                         list_del_init (&curr->inode_lru);
                                 }
@@ -174,6 +192,7 @@ ioc_prune (ioc_table_t *table)
         } /* ioc_inode_table locked region end */
         ioc_table_unlock (table);
 
+out:
         return 0;
 }
 
@@ -192,7 +211,11 @@ ioc_page_create (ioc_inode_t *ioc_inode, off_t offset)
         off_t        rounded_offset = 0;
         ioc_page_t  *newpage        = NULL;
 
+        GF_VALIDATE_OR_GOTO ("io-cache", ioc_inode, out);
+
         table = ioc_inode->table;
+        GF_VALIDATE_OR_GOTO ("io-cache", table, out);
+
         rounded_offset = floor (offset, table->page_size);
 
         newpage = GF_CALLOC (1, sizeof (*newpage), gf_ioc_mt_ioc_newpage_t);
@@ -240,13 +263,22 @@ ioc_wait_on_page (ioc_page_t *page, call_frame_t *frame, off_t offset,
         ioc_waitq_t *waitq = NULL;
         ioc_local_t *local = NULL;
 
+        GF_VALIDATE_OR_GOTO ("io-cache", frame, out);
         local = frame->local;
 
+        GF_VALIDATE_OR_GOTO (frame->this->name, local, out);
+
+        if (page == NULL) {
+                local->op_ret = -1;
+                local->op_errno = ENOMEM;
+                gf_log (frame->this->name, GF_LOG_WARNING,
+                        "asked to wait on a NULL page");
+        }
+
         waitq = GF_CALLOC (1, sizeof (*waitq), gf_ioc_mt_ioc_waitq_t);
         if (waitq == NULL) {
                 local->op_ret = -1;
                 local->op_errno = ENOMEM;
-                gf_log (frame->this->name, GF_LOG_ERROR, "out of memory");
                 goto out;
         }
 
@@ -287,6 +319,8 @@ ioc_cache_still_valid (ioc_inode_t *ioc_inode, struct iatt *stbuf)
 {
         int8_t cache_still_valid = 1;
 
+        GF_VALIDATE_OR_GOTO ("io-cache", ioc_inode, out);
+
 #if 0
         if (!stbuf || (stbuf->ia_mtime != ioc_inode->cache.mtime) ||
             (stbuf->st_mtim.tv_nsec != ioc_inode->stbuf.st_mtim.tv_nsec))
@@ -307,6 +341,7 @@ ioc_cache_still_valid (ioc_inode_t *ioc_inode, struct iatt *stbuf)
         }
 #endif
 
+out:
         return cache_still_valid;
 }
 
@@ -344,19 +379,25 @@ ioc_fault_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         size_t       iobref_page_size = 0;
         char         zero_filled      = 0;
 
+        GF_ASSERT (frame);
+
         local = frame->local;
+        GF_ASSERT (local);
+
         offset = local->pending_offset;
         ioc_inode = local->inode;
+        GF_ASSERT (ioc_inode);
+
         table = ioc_inode->table;
+        GF_ASSERT (table);
 
-        zero_filled = ((op_ret >=0)
-                       && (stbuf->ia_mtime == 0));
+        zero_filled = ((op_ret >=0) && (stbuf->ia_mtime == 0));
 
         ioc_inode_lock (ioc_inode);
         {
-                if (op_ret == -1 ||
-                    !(zero_filled ||
-                      ioc_cache_still_valid(ioc_inode, stbuf))) {
+                if (op_ret == -1 || !(zero_filled ||
+                                      ioc_cache_still_valid(ioc_inode,
+                                                            stbuf))) {
                         gf_log (ioc_inode->table->xl->name, GF_LOG_TRACE,
                                 "cache for inode(%p) is invalid. flushing "
                                 "all pages", ioc_inode);
@@ -383,7 +424,7 @@ ioc_fault_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                         if (!page) {
                                 /* page was flushed */
                                 /* some serious bug ? */
-                                gf_log (this->name, GF_LOG_DEBUG,
+                                gf_log (frame->this->name, GF_LOG_WARNING,
                                         "wasted copy: %"PRId64"[+%"PRId64"] "
                                         "ioc_inode=%p", offset,
                                         table->page_size, ioc_inode);
@@ -411,7 +452,8 @@ ioc_fault_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                                 } else {
                                         /* TODO: we have got a response to
                                          * our request and no data */
-                                        gf_log (this->name, GF_LOG_CRITICAL,
+                                        gf_log (frame->this->name,
+                                                GF_LOG_CRITICAL,
                                                 "frame>root>rsp_refs is null");
                                 } /* if(frame->root->rsp_refs) */
 
@@ -461,7 +503,8 @@ unlock:
                 ioc_prune (ioc_inode->table);
         }
 
-        gf_log (this->name, GF_LOG_TRACE, "fault frame %p returned", frame);
+        gf_log (frame->this->name, GF_LOG_TRACE, "fault frame %p returned",
+                frame);
         pthread_mutex_destroy (&local->local_lock);
 
         fd_unref (local->fd);
@@ -470,6 +513,7 @@ unlock:
         return 0;
 }
 
+
 /*
  * ioc_page_fault -
  *
@@ -490,13 +534,20 @@ ioc_page_fault (ioc_inode_t *ioc_inode, call_frame_t *frame, fd_t *fd,
         ioc_waitq_t  *waitq       = NULL;
         ioc_page_t   *page        = NULL;
 
+        GF_ASSERT (ioc_inode);
+        if (frame == NULL) {
+                op_ret = -1;
+                op_errno = EINVAL;
+                gf_log ("io-cache", GF_LOG_WARNING,
+                        "page fault on a NULL frame");
+                goto err;
+        }
+
         table = ioc_inode->table;
         fault_frame = copy_frame (frame);
         if (fault_frame == NULL) {
                 op_ret = -1;
                 op_errno = ENOMEM;
-                gf_log (ioc_inode->table->xl->name, GF_LOG_ERROR,
-                        "out of memory");
                 goto err;
         }
 
@@ -506,8 +557,6 @@ ioc_page_fault (ioc_inode_t *ioc_inode, call_frame_t *frame, fd_t *fd,
                 op_ret = -1;
                 op_errno = ENOMEM;
                 STACK_DESTROY (fault_frame->root);
-                gf_log (ioc_inode->table->xl->name, GF_LOG_ERROR,
-                        "out of memory");
                 goto err;
         }
 
@@ -543,6 +592,7 @@ err:
         }
 }
 
+
 int32_t
 ioc_frame_fill (ioc_page_t *page, call_frame_t *frame, off_t offset,
                 size_t size)
@@ -555,9 +605,21 @@ ioc_frame_fill (ioc_page_t *page, call_frame_t *frame, off_t offset,
         ioc_inode_t *ioc_inode  = NULL;
         ioc_fill_t  *new        = NULL;
         int8_t       found      = 0;
-        int32_t      ret        = 0;
+        int32_t      ret        = -1;
+
+        GF_VALIDATE_OR_GOTO ("io-cache", frame, out);
 
         local = frame->local;
+        GF_VALIDATE_OR_GOTO (frame->this->name, local, out);
+
+        if (page == NULL) {
+                gf_log (frame->this->name, GF_LOG_WARNING,
+                        "NULL page has been provided to serve read request");
+                local->op_ret = -1;
+                local->op_errno = EINVAL;
+                goto out;
+        }
+
         ioc_inode = page->inode;
 
         gf_log (frame->this->name, GF_LOG_TRACE,
@@ -602,17 +664,13 @@ ioc_frame_fill (ioc_page_t *page, call_frame_t *frame, off_t offset,
                         if (new == NULL) {
                                 local->op_ret = -1;
                                 local->op_errno = ENOMEM;
-                                ret = -1;
-                                gf_log (page->inode->table->xl->name,
-                                        GF_LOG_ERROR, "out of memory");
                                 goto out;
                         }
 
                         new->offset = page->offset;
                         new->size = copy_size;
                         new->iobref = iobref_ref (page->iobref);
-                        new->count = iov_subset (page->vector,
-                                                 page->count,
+                        new->count = iov_subset (page->vector, page->count,
                                                  src_offset,
                                                  src_offset + copy_size,
                                                  NULL);
@@ -626,21 +684,14 @@ ioc_frame_fill (ioc_page_t *page, call_frame_t *frame, off_t offset,
 
                                 iobref_unref (new->iobref);
                                 GF_FREE (new);
-
-                                ret = -1;
-                                gf_log (page->inode->table->xl->name,
-                                        GF_LOG_ERROR, "out of memory");
                                 goto out;
                         }
 
-                        new->count = iov_subset (page->vector,
-                                                 page->count,
+                        new->count = iov_subset (page->vector, page->count,
                                                  src_offset,
                                                  src_offset + copy_size,
                                                  new->vector);
 
-
-
                         /* add the ioc_fill to fill_list for this frame */
                         if (list_empty (&local->fill_list)) {
                                 /* if list is empty, then this is the first
@@ -671,6 +722,7 @@ ioc_frame_fill (ioc_page_t *page, call_frame_t *frame, off_t offset,
                 local->op_ret += copy_size;
         }
 
+        ret = 0;
 out:
         return ret;
 }
@@ -696,13 +748,23 @@ ioc_frame_unwind (call_frame_t *frame)
         struct iatt    stbuf  = {0,};
         int32_t        op_ret = 0;
 
+        GF_ASSERT (frame);
+
         local = frame->local;
+        if (local == NULL) {
+                gf_log (frame->this->name, GF_LOG_WARNING,
+                        "local is NULL");
+                op_ret = -1;
+                local->op_errno = ENOMEM;
+                goto unwind;
+        }
+
         //  ioc_local_lock (local);
         frame->local = NULL;
         iobref = iobref_new ();
         if (iobref == NULL) {
                 op_ret = -1;
-                gf_log (frame->this->name, GF_LOG_ERROR, "out of memory");
+                local->op_errno = ENOMEM;
         }
 
         if (list_empty (&local->fill_list)) {
@@ -719,8 +781,7 @@ ioc_frame_unwind (call_frame_t *frame)
         vector = GF_CALLOC (count, sizeof (*vector), gf_ioc_mt_iovec);
         if (vector == NULL) {
                 op_ret = -1;
-
-                gf_log (frame->this->name, GF_LOG_ERROR, "out of memory");
+                local->op_errno = ENOMEM;
         }
 
         list_for_each_entry_safe (fill, next, &local->fill_list, list) {
@@ -744,6 +805,7 @@ ioc_frame_unwind (call_frame_t *frame)
                 op_ret = iov_length (vector, count);
         }
 
+unwind:
         gf_log (frame->this->name, GF_LOG_TRACE,
                 "frame(%p) unwinding with op_ret=%d", frame, op_ret);
 
@@ -779,6 +841,8 @@ ioc_frame_return (call_frame_t *frame)
         ioc_local_t *local      = NULL;
         int32_t      wait_count = 0;
 
+        GF_ASSERT (frame);
+
         local = frame->local;
         GF_ASSERT (local->wait_count > 0);
 
@@ -808,6 +872,8 @@ ioc_page_wakeup (ioc_page_t *page)
         call_frame_t *frame = NULL;
         int32_t       ret   = -1;
 
+        GF_VALIDATE_OR_GOTO ("io-cache", page, out);
+
         waitq = page->waitq;
         page->waitq = NULL;
 
@@ -825,6 +891,7 @@ ioc_page_wakeup (ioc_page_t *page)
                 }
         }
 
+out:
         return waitq;
 }
 
@@ -845,10 +912,12 @@ ioc_page_error (ioc_page_t *page, int32_t op_ret, int32_t op_errno)
         ioc_table_t  *table = NULL;
         ioc_local_t  *local = NULL;
 
+        GF_VALIDATE_OR_GOTO ("io-cache", page, out);
+
         waitq = page->waitq;
         page->waitq = NULL;
 
-        gf_log (page->inode->table->xl->name, GF_LOG_DEBUG,
+        gf_log (page->inode->table->xl->name, GF_LOG_WARNING,
                 "page error for page = %p & waitq = %p", page, waitq);
 
         for (trav = waitq; trav; trav = trav->next) {
@@ -873,5 +942,6 @@ ioc_page_error (ioc_page_t *page, int32_t op_ret, int32_t op_errno)
                 table->cache_used -= ret;
         }
 
+out:
         return waitq;
 }