glusterd/rebalance: Display run-time of rebalance process

Added run-time value field to cli output of rebalance/remove-brick.

A new cluster/distribute boolean option rebalance-stats when set to
ON, time taken for migration of each file is logged.

With rebalance-stats OFF (default), rebalance logs will only have
entries showing time spent in each directory.

Change-Id: I02a8918621120068cd71ffaf2999d30b3a2d10a2
BUG: 821987
Signed-off-by: shishir gowda <shishirng@gluster.com>
Reviewed-on: http://review.gluster.com/3303
Tested-by: Gluster Build System <jenkins@build.gluster.com>
Reviewed-by: Anand Avati <avati@redhat.com>

1 files changed, 41 insertions, 2 deletions

diff --git a/xlators/cluster/dht/src/dht-rebalance.c b/xlators/cluster/dht/src/dht-rebalance.c
index fd07a1c7e..32c1774be 100644
--- a/xlators/cluster/dht/src/dht-rebalance.c
+++ b/xlators/cluster/dht/src/dht-rebalance.c
@@ -1050,9 +1050,15 @@ gf_defrag_migrate_data (xlator_t *this, gf_defrag_info_t *defrag, loc_t *loc,
         char                    *uuid_str       = NULL;
         uuid_t                   node_uuid      = {0,};
         int                      readdir_operrno = 0;
+        struct timeval           dir_start      = {0,};
+        struct timeval           end            = {0,};
+        double                   elapsed        = {0,};
+        struct timeval           start          = {0,};
 
         gf_log (this->name, GF_LOG_INFO, "migrate data called on %s",
                 loc->path);
+        gettimeofday (&dir_start, NULL);
+
         fd = fd_create (loc->inode, defrag->pid);
         if (!fd) {
                 gf_log (this->name, GF_LOG_ERROR, "Failed to create fd");
@@ -1097,7 +1103,9 @@ gf_defrag_migrate_data (xlator_t *this, gf_defrag_info_t *defrag, loc_t *loc,
                                 continue;
 
                         defrag->num_files_lookedup++;
-
+                        if (defrag->stats == _gf_true) {
+                                gettimeofday (&start, NULL);
+                        }
                         loc_wipe (&entry_loc);
                         ret =dht_build_child_loc (this, &entry_loc, loc,
                                                   entry->d_name);
@@ -1217,6 +1225,15 @@ gf_defrag_migrate_data (xlator_t *this, gf_defrag_info_t *defrag, loc_t *loc,
                                 defrag->total_data += iatt.ia_size;
                         }
                         UNLOCK (&defrag->lock);
+                        if (defrag->stats == _gf_true) {
+                                gettimeofday (&end, NULL);
+                                elapsed = (end.tv_sec - start.tv_sec) * 1e6 +
+                                          (end.tv_usec - start.tv_usec);
+                                gf_log (this->name, GF_LOG_INFO, "Migration of "
+                                        "file:%s size:%"PRIu64" bytes took %.2f"
+                                        "secs", entry_loc.path, iatt.ia_size,
+                                         elapsed/1e6);
+                        }
                 }
 
                 gf_dirent_free (&entries);
@@ -1226,6 +1243,12 @@ gf_defrag_migrate_data (xlator_t *this, gf_defrag_info_t *defrag, loc_t *loc,
                 if (readdir_operrno == ENOENT)
                         break;
         }
+
+        gettimeofday (&end, NULL);
+        elapsed = (end.tv_sec - dir_start.tv_sec) * 1e6 +
+                  (end.tv_usec - dir_start.tv_usec);
+        gf_log (this->name, GF_LOG_INFO, "Migration operation on dir %s took "
+                "%.2f secs", loc->path, elapsed/1e6);
         ret = 0;
 out:
         if (free_entries)
@@ -1416,6 +1439,8 @@ gf_defrag_start_crawl (void *data)
         defrag = conf->defrag;
         if (!defrag)
                 goto out;
+
+        gettimeofday (&defrag->start_time, NULL);
         dht_build_root_inode (this, &defrag->root_inode);
         if (!defrag->root_inode)
                 goto out;
@@ -1552,6 +1577,9 @@ gf_defrag_status_get (gf_defrag_info_t *defrag, dict_t *dict)
         uint64_t lookup = 0;
         uint64_t failures = 0;
         char     *status = "";
+        double   elapsed = 0;
+        struct timeval end = {0,};
+
 
         if (!defrag)
                 goto out;
@@ -1565,6 +1593,10 @@ gf_defrag_status_get (gf_defrag_info_t *defrag, dict_t *dict)
         lookup = defrag->num_files_lookedup;
         failures = defrag->total_failures;
 
+        gettimeofday (&end, NULL);
+
+        elapsed = end.tv_sec - defrag->start_time.tv_sec;
+
         if (!dict)
                 goto log;
 
@@ -1587,6 +1619,12 @@ gf_defrag_status_get (gf_defrag_info_t *defrag, dict_t *dict)
         if (ret)
                 gf_log (THIS->name, GF_LOG_WARNING,
                         "failed to set status");
+        if (elapsed) {
+                ret = dict_set_double (dict, "run-time", elapsed);
+                if (ret)
+                        gf_log (THIS->name, GF_LOG_WARNING,
+                                "failed to set run-time");
+        }
 
         ret = dict_set_uint64 (dict, "failures", failures);
 log:
@@ -1608,7 +1646,8 @@ log:
                 break;
         }
 
-        gf_log (THIS->name, GF_LOG_INFO, "Rebalance is %s", status);
+        gf_log (THIS->name, GF_LOG_INFO, "Rebalance is %s. Time taken is %.2f "
+                "secs", status, elapsed);
         gf_log (THIS->name, GF_LOG_INFO, "Files migrated: %"PRIu64", size: %"
                 PRIu64", lookups: %"PRIu64", failures: %"PRIu64, files, size,
                 lookup, failures);