added p99 support to the samples logging

Summary:
added global and by-fop-type calculation of p99 latency
to the sampled fop data

Test Plan:
build local glusterfs mount and looked at
the stats while dd if=/dev/zero of=/mnt/fuse/groot/share1/test1 bs=5

Reviewers: sshreyas, mgoulet, jdarcy

Reviewed By: jdarcy

Subscribers: jdarcy

Differential Revision: https://phabricator.intern.facebook.com/D5597662

Change-Id: I3f5cd9c0ea59ae4357827fcbd19bbf009e661c05
Signed-off-by: Jeff Darcy <jdarcy@fb.com>
Reviewed-on: https://review.gluster.org/18277
Reviewed-by: Jeff Darcy <jeff@pl.atyp.us>
Tested-by: Jeff Darcy <jeff@pl.atyp.us>
CentOS-regression: Gluster Build System <jenkins@build.gluster.org>
Smoke: Gluster Build System <jenkins@build.gluster.org>

4 files changed, 131 insertions, 0 deletions

diff --git a/libglusterfs/src/common-utils.c b/libglusterfs/src/common-utils.c
index d4ddff2090e..84a0785d660 100644
--- a/libglusterfs/src/common-utils.c
+++ b/libglusterfs/src/common-utils.c
@@ -3735,6 +3735,28 @@ gf_compare_sockaddr (const struct sockaddr *addr1,
         return _gf_false;
 }
 
+
+/*
+ * gf_compare_double
+ * simple compare function for doubles
+ * for the purpose of sorting
+ */
+
+int
+gf_compare_double (const void* a, const void* b)
+{
+        double da = *(double *) a, db = *(double *) b;
+
+        if (da == db) {
+                return 0;
+        } else if (da < db) {
+                return -1;
+        } else {
+                return 1;
+        }
+}
+
+
 /*
  * gf_set_timestamp:
  *      It sets the mtime and atime of 'dest' file as of 'src'.
diff --git a/libglusterfs/src/common-utils.h b/libglusterfs/src/common-utils.h
index d917671fedf..9c6ae8307a8 100644
--- a/libglusterfs/src/common-utils.h
+++ b/libglusterfs/src/common-utils.h
@@ -795,6 +795,9 @@ gf_boolean_t
 gf_compare_sockaddr (const struct sockaddr *addr1,
                      const struct sockaddr *addr2);
 
+int
+gf_compare_double (const void *a, const void *b);
+
 char *
 gf_backtrace_save (char *buf);
 
diff --git a/xlators/debug/io-stats/src/io-stats.c b/xlators/debug/io-stats/src/io-stats.c
index f1970a41c3b..e958601b304 100644
--- a/xlators/debug/io-stats/src/io-stats.c
+++ b/xlators/debug/io-stats/src/io-stats.c
@@ -308,6 +308,7 @@ struct ios_conf {
         gf_boolean_t              sample_hard_errors;
         gf_boolean_t              sample_all_errors;
         uint32_t                  outstanding_req;
+        gf_boolean_t              dump_p99_latencies;
 };
 
 
@@ -904,6 +905,79 @@ ios_stats_cleanup (xlator_t *this, inode_t *inode)
                 gf_log (this->name, GF_LOG_TRACE, fmt);         \
         } while (0)
 
+double
+io_stats_dump_p99_latencies (xlator_t *this, FILE* logfp, char * key_prefix, char * str_prefix)
+{
+        struct ios_conf  *conf = NULL;
+        double           *ios_latencies[GF_FOP_MAXVALUE] = {NULL, };
+        double           *global_ios_latency = NULL;
+        int               num_fop[GF_FOP_MAXVALUE] = {0, };
+        ios_sample_t     *ios_samples = NULL;
+        int               collected = 0;
+        int               i = 0;
+        int               j = 0;
+        int               fop_idx = 0;
+        glusterfs_fop_t   fop_type = 0;
+        double            p99_val = 0.0;
+        int               p99_idx = 0;
+        int               ret = 0;
+
+        conf = this->private;
+        collected = conf->ios_sample_buf->collected;
+
+        for (i = 0; i < GF_FOP_MAXVALUE; i++) {
+                ios_latencies[i] = GF_CALLOC (collected,
+                                              sizeof (double),
+                                              0);
+                if (!ios_latencies[i]) {
+                        ret = -ENOMEM;
+                        goto out;
+                }
+        }
+        global_ios_latency = GF_CALLOC (collected, sizeof (double),
+                                        0);
+        if (!global_ios_latency) {
+                ret = -ENOMEM;
+                goto out;
+        }
+
+        ios_samples = conf->ios_sample_buf->ios_samples;
+        for (i = 0; i < collected; i++) {
+                global_ios_latency[i] = ios_samples[i].elapsed;
+                fop_type = ios_samples[i].fop_type;
+                fop_idx = num_fop[fop_type];
+                ios_latencies[fop_type][fop_idx] = ios_samples[i].elapsed;
+                num_fop[fop_type]++;
+        }
+
+        qsort (global_ios_latency, collected, sizeof (double),
+               gf_compare_double);
+
+        p99_idx = (int)(0.99 * collected);
+        p99_val = global_ios_latency[p99_idx];
+        ios_log (this, logfp,
+                "\"%s.%s.fop.%s.p99_latency_usec\":\"%0.4lf\",",
+                key_prefix, str_prefix, "global", p99_val);
+
+        for (i = 0; i < GF_FOP_MAXVALUE; i++) {
+                qsort (ios_latencies[i], num_fop[i], sizeof (double),
+                       gf_compare_double);
+                p99_idx = (int)(0.99*num_fop[i]);
+                p99_val = ios_latencies[i][p99_idx];
+                ios_log (this, logfp,
+                        "\"%s.%s.fop.%s.p99_latency_usec\":\"%0.4lf\",",
+                        key_prefix, str_prefix, gf_fop_list[i], p99_val);
+        }
+
+out:
+        GF_FREE (global_ios_latency);
+        for (j = 0; j < i; j++) {
+                GF_FREE (ios_latencies[j]);
+        }
+
+        return ret;
+}
+
 int
 ios_dump_file_stats (struct ios_stat_head *list_head, xlator_t *this,
                      FILE *logfp)
@@ -1234,6 +1308,20 @@ io_stats_dump_global_to_json_logfp (xlator_t *this,
                 "\"%s.%s.fop.unweighted_latency_ave_usec\":\"%0.4lf\",",
                 key_prefix, str_prefix, fop_ave_usec);
 
+        ios_log (this, logfp,
+                "\"%s.%s.fop.GOT1\":\"%0.4lf\",",
+                key_prefix, str_prefix, fop_ave_usec);
+        if (conf->dump_p99_latencies) {
+                io_stats_dump_p99_latencies (this, logfp, key_prefix,
+                                             str_prefix);
+                ios_log (this, logfp,
+                        "\"%s.%s.fop.GOT2\":\"%0.4lf\",",
+                        key_prefix, str_prefix, fop_ave_usec);
+        }
+        ios_log (this, logfp,
+                "\"%s.%s.fop.GOT3\":\"%0.4lf\",",
+                key_prefix, str_prefix, fop_ave_usec);
+
         if (conf->iamnfsd) {
                 dict_t *xattr = NULL;
                 ret = syncop_getxattr (this, &unused_loc, &xattr,
@@ -4312,6 +4400,9 @@ reconfigure (xlator_t *this, dict_t *options)
         GF_OPTION_RECONF ("fop-sample-hard-errors",
                           conf->sample_hard_errors, options, bool, out);
 
+        GF_OPTION_RECONF ("dump-p99-latencies", conf->dump_p99_latencies,
+                          options, bool, out);
+
         ret = 0;
 out:
         gf_log (this ? this->name : "io-stats",
@@ -4477,6 +4568,8 @@ init (xlator_t *this)
         GF_OPTION_INIT ("log-flush-timeout", log_flush_timeout, time, out);
         gf_log_set_log_flush_timeout (log_flush_timeout);
 
+        GF_OPTION_INIT ("dump-p99-latencies", conf->dump_p99_latencies,
+                        bool, out);
 
         this->private = conf;
         if (conf->ios_dump_interval > 0) {
@@ -4884,6 +4977,12 @@ struct volume_options options[] = {
           .description = "This option samples all fops with \"hard errors\""
                          "including EROFS, ENOSPC, etc."
         },
+        { .key  = { "dump-p99-latencies" },
+          .type = GF_OPTION_TYPE_BOOL,
+          .default_value = "off",
+          .description = "If on the p99 latency of each operation "
+                         "and all types is dumped at each sample interval. "
+        },
         { .key  = {NULL} },
 
 };
diff --git a/xlators/mgmt/glusterd/src/glusterd-volume-set.c b/xlators/mgmt/glusterd/src/glusterd-volume-set.c
index 985490892f3..996be7f1618 100644
--- a/xlators/mgmt/glusterd/src/glusterd-volume-set.c
+++ b/xlators/mgmt/glusterd/src/glusterd-volume-set.c
@@ -1360,6 +1360,13 @@ struct volopt_map_entry glusterd_volopt_map[] = {
           .type        = NO_DOC,
           .op_version  = 1
         },
+        { .key         = "diagnostics.dump-p99-latencies",
+          .voltype     = "debug/io-stats",
+          .option      = "dump-p99-latencies",
+          .value       = "off",
+          .type        = NO_DOC,
+          .op_version  = 1
+        },
         { .key         = "diagnostics.brick-log-level",
           .voltype     = "debug/io-stats",
           .value       = "INFO",