From 2faa19e96c5c1a249c0e6e8095e3e8eeaa3954a5 Mon Sep 17 00:00:00 2001

From: Poornima G <pgurusid@redhat.com>

Date: Wed, 17 Aug 2016 20:19:59 +0530

Subject: [PATCH 131/141] io-stats: Add stats for upcall notifications

With this patch, there will be additional entries seen in

the profile info:

UPCALL : Total number of upcall events that were sent from

         the brick(in brick profile), and number of upcall

         notifications recieved by client(in client profile)

Cache invalidation events:

-------------------------

CI_IATT : Number of upcalls that were cache invalidation and

         had one of the IATT_UPDATE_FLAGS set. This indicates

         that one of the iatt value was changed.

CI_XATTR : Number of upcalls that were cache invalidation, and

         had one of the UP_XATTR or UP_XATTR_RM set. This indicates

         that an xattr was updated or deleted.

CI_RENAME : Number of upcalls that were cache invalidation,

         resulted by the renaming of a file or directory

CI_UNLINK : Number of upcalls that were cache invalidation,

         resulted by the unlink of a file.

CI_FORGET : Number of upcalls that were cache invalidation,

         resulted by the forget of inode on the server side.

Lease events:

------------

LEASE_RECALL : Number of lease recalls sent by the brick (in

         brick profile), and number of lease recalls recieved

         by client(in client profile)

Note that the sum of CI_IATT, CI_XATTR, CI_RENAME, CI_UNLINK,

CI_FORGET, LEASE_RECALL may not be equal to UPCALL. This is

because, each cache invalidation can carry multiple flags.

Eg:

- Every CI_XATTR will have CI_IATT

- Every CI_UNLINK will also increment CI_IATT as link count is an

iatt attribute.

Also UP_PARENT_DENTRY_FLAGS is currently not accounted for,

as CI_RENAME and CI_UNLINK will always have the flag

UP_PARENT_DENTRY_FLAGS

Change-Id: Ieb8cd21dde2c4c7618f12d025a5e5156f9cc0fe9

BUG: 1284873

Signed-off-by: Poornima G <pgurusid@redhat.com>

Reviewed-on: http://review.gluster.org/15193

Smoke: Gluster Build System <jenkins@build.gluster.org>

NetBSD-regression: NetBSD Build System <jenkins@build.gluster.org>

Reviewed-by: Rajesh Joseph <rjoseph@redhat.com>

CentOS-regression: Gluster Build System <jenkins@build.gluster.org>

Reviewed-by: Pranith Kumar Karampuri <pkarampu@redhat.com>

Reviewed-on: https://code.engineering.redhat.com/gerrit/87044

Tested-by: Rajesh Joseph <rjoseph@redhat.com>

---

 cli/src/cli-rpc-ops.c                 |   25 +++++++++

 cli/src/cli-xml-output.c              |   44 ++++++++++++++++-

 libglusterfs/src/globals.c            |   13 +++++

 libglusterfs/src/globals.h            |    1 +

 rpc/xdr/src/glusterfs-fops.x          |   12 +++++

 tests/bugs/upcall/bug-upcall-stat.t   |   38 ++++++++++++++

 xlators/debug/io-stats/src/io-stats.c |   87 +++++++++++++++++++++++++++++++++

 7 files changed, 219 insertions(+), 1 deletions(-)

 create mode 100755 tests/bugs/upcall/bug-upcall-stat.t

diff --git a/cli/src/cli-rpc-ops.c b/cli/src/cli-rpc-ops.c

index e8fc658..58884a2 100644

--- a/cli/src/cli-rpc-ops.c

+++ b/cli/src/cli-rpc-ops.c

@@ -30,6 +30,7 @@

 #include "protocol-common.h"

 #include "cli-mem-types.h"

 #include "compat.h"

+#include "upcall-utils.h"

 #include "syscall.h"

 #include "glusterfs3.h"

@@ -6293,6 +6294,7 @@ cmd_profile_volume_brick_out (dict_t *dict, int count, int interval)

         uint64_t                rb_counts[32] = {0};

         uint64_t                wb_counts[32] = {0};

         cli_profile_info_t      profile_info[GF_FOP_MAXVALUE] = {{0}};

+        cli_profile_info_t      upcall_info[GF_UPCALL_FLAGS_MAXVALUE] = {{0},};

         char                    output[128] = {0};

         int                     per_line = 0;

         char                    read_blocks[128] = {0};

@@ -6316,6 +6318,13 @@ cmd_profile_volume_brick_out (dict_t *dict, int count, int interval)

                 ret = dict_get_uint64 (dict, key, &wb_counts[i]);

         }

+        for (i = 0; i < GF_UPCALL_FLAGS_MAXVALUE; i++) {

+                snprintf (key, sizeof (key), "%d-%d-%d-upcall-hits", count,

+                          interval, i);

+                ret = dict_get_uint64 (dict, key, &upcall_info[i].fop_hits);

+                upcall_info[i].fop_name = (char *)gf_upcall_list[i];

+        }

+

         for (i = 0; i < GF_FOP_MAXVALUE; i++) {

                 memset (key, 0, sizeof (key));

                 snprintf (key, sizeof (key), "%d-%d-%d-hits", count,

@@ -6440,6 +6449,22 @@ cmd_profile_volume_brick_out (dict_t *dict, int count, int interval)

                                  profile_info[i].fop_name);

                 }

         }

+

+        for (i = 0; i < GF_UPCALL_FLAGS_MAXVALUE; i++) {

+                if (upcall_info[i].fop_hits == 0)

+                        continue;

+                if (upcall_info[i].fop_hits) {

+                        cli_out ("%10.2lf %10.2lf us %10.2lf us %10.2lf us"

+                                 " %14"PRId64" %11s",

+                                 upcall_info[i].percentage_avg_latency,

+                                 upcall_info[i].avg_latency,

+                                 upcall_info[i].min_latency,

+                                 upcall_info[i].max_latency,

+                                 upcall_info[i].fop_hits,

+                                 upcall_info[i].fop_name);

+                }

+        }

+

         cli_out (" ");

         cli_out ("%12s: %"PRId64" seconds", "Duration", sec);

         cli_out ("%12s: %"PRId64" bytes", "Data Read", r_count);

diff --git a/cli/src/cli-xml-output.c b/cli/src/cli-xml-output.c

index 6d1e617..f249e40 100644

--- a/cli/src/cli-xml-output.c

+++ b/cli/src/cli-xml-output.c

@@ -13,7 +13,7 @@

 #include "run.h"

 #include "compat.h"

 #include "syscall.h"

-

+#include "upcall-utils.h"

 enum gf_task_types {

     GF_TASK_TYPE_REBALANCE,

@@ -2200,6 +2200,48 @@ cont:

                 max_latency = 0.0;

         }

+        for (i = 0; i < GF_UPCALL_FLAGS_MAXVALUE; i++) {

+                hits = 0;

+                avg_latency = 0.0;

+                min_latency = 0.0;

+                max_latency = 0.0;

+

+                memset (key, 0, sizeof (key));

+                snprintf (key, sizeof (key), "%d-%d-%d-upcall-hits", brick_index,

+                          interval, i);

+                ret = dict_get_uint64 (dict, key, &hits);

+                if (ret)

+                        continue;

+

+                /* <fop> */

+                ret = xmlTextWriterStartElement (writer, (xmlChar *)"fop");

+                XML_RET_CHECK_AND_GOTO (ret, out);

+

+                ret = xmlTextWriterWriteFormatElement

+                        (writer, (xmlChar *)"name", "%s", gf_fop_list[i]);

+                XML_RET_CHECK_AND_GOTO (ret, out);

+

+                ret = xmlTextWriterWriteFormatElement

+                        (writer, (xmlChar *)"hits", "%"PRIu64, hits);

+                XML_RET_CHECK_AND_GOTO (ret, out);

+

+                ret = xmlTextWriterWriteFormatElement

+                        (writer, (xmlChar *)"avgLatency", "%f", avg_latency);

+                XML_RET_CHECK_AND_GOTO (ret, out);

+

+                ret = xmlTextWriterWriteFormatElement

+                        (writer, (xmlChar *)"minLatency", "%f", min_latency);

+                XML_RET_CHECK_AND_GOTO (ret, out);

+

+                ret = xmlTextWriterWriteFormatElement

+                        (writer, (xmlChar *)"maxLatency", "%f", max_latency);

+                XML_RET_CHECK_AND_GOTO (ret, out);

+

+                /* </fop> */

+                ret = xmlTextWriterEndElement (writer);

+                XML_RET_CHECK_AND_GOTO (ret, out);

+        }

+

         /* </fopStats> */

         ret = xmlTextWriterEndElement (writer);

         XML_RET_CHECK_AND_GOTO (ret, out);

diff --git a/libglusterfs/src/globals.c b/libglusterfs/src/globals.c

index 50ef4db..c537971 100644

--- a/libglusterfs/src/globals.c

+++ b/libglusterfs/src/globals.c

@@ -16,6 +16,7 @@

 #include "mem-pool.h"

 #include "syncop.h"

 #include "libglusterfs-messages.h"

+#include "upcall-utils.h"

 const char *gf_fop_list[GF_FOP_MAXVALUE] = {

         [GF_FOP_NULL]        = "NULL",

@@ -74,6 +75,18 @@ const char *gf_fop_list[GF_FOP_MAXVALUE] = {

         [GF_FOP_GETACTIVELK] = "GETACTIVELK",

         [GF_FOP_SETACTIVELK] = "SETACTIVELK",

 };

+

+const char *gf_upcall_list[GF_UPCALL_FLAGS_MAXVALUE] = {

+        [GF_UPCALL_NULL] = "NULL",

+        [GF_UPCALL] = "UPCALL",

+        [GF_UPCALL_CI_STAT] = "CI_IATT",

+        [GF_UPCALL_CI_XATTR] = "CI_XATTR",

+        [GF_UPCALL_CI_RENAME] = "CI_RENAME",

+        [GF_UPCALL_CI_NLINK] = "CI_UNLINK",

+        [GF_UPCALL_CI_FORGET] = "CI_FORGET",

+        [GF_UPCALL_LEASE_RECALL] = "LEASE_RECALL",

+};

+

 /* THIS */

 /* This global ctx is a bad hack to prevent some of the libgfapi crashes.

diff --git a/libglusterfs/src/globals.h b/libglusterfs/src/globals.h

index 514109a..b12b0ad 100644

--- a/libglusterfs/src/globals.h

+++ b/libglusterfs/src/globals.h

@@ -129,6 +129,7 @@ char *glusterfs_leaseid_buf_get ();

 int glusterfs_globals_init (glusterfs_ctx_t *ctx);

 extern const char *gf_fop_list[];

+extern const char *gf_upcall_list[];

 /* mem acct enable/disable */

 int gf_global_mem_acct_enable_get (void);

diff --git a/rpc/xdr/src/glusterfs-fops.x b/rpc/xdr/src/glusterfs-fops.x

index 3b6b649..4bfdd4b 100644

--- a/rpc/xdr/src/glusterfs-fops.x

+++ b/rpc/xdr/src/glusterfs-fops.x

@@ -197,3 +197,15 @@ enum gf_seek_what_t {

         GF_SEEK_DATA,

         GF_SEEK_HOLE

 };

+

+enum gf_upcall_flags_t {

+        GF_UPCALL_NULL,

+        GF_UPCALL,

+        GF_UPCALL_CI_STAT,

+        GF_UPCALL_CI_XATTR,

+        GF_UPCALL_CI_RENAME,

+        GF_UPCALL_CI_NLINK,

+        GF_UPCALL_CI_FORGET,

+        GF_UPCALL_LEASE_RECALL,

+        GF_UPCALL_FLAGS_MAXVALUE

+};

diff --git a/tests/bugs/upcall/bug-upcall-stat.t b/tests/bugs/upcall/bug-upcall-stat.t

new file mode 100755

index 0000000..b229c13

--- /dev/null

+++ b/tests/bugs/upcall/bug-upcall-stat.t

@@ -0,0 +1,38 @@

+#!/bin/bash

+

+. $(dirname $0)/../../include.rc

+. $(dirname $0)/../../volume.rc

+

+cleanup;

+TEST glusterd;

+

+TEST $CLI volume create $V0 $H0:$B0/${V0}{1};

+

+TEST $CLI volume set $V0 performance.md-cache-timeout 600

+TEST $CLI volume set $V0 performance.cache-samba-metadata on

+TEST $CLI volume set $V0 features.cache-invalidation on

+TEST $CLI volume set $V0 features.cache-invalidation-timeout 600

+

+#TEST $CLI volume stop $V0

+TEST $CLI volume start $V0

+

+## 5. Create two gluster mounts

+TEST glusterfs --volfile-id=/$V0 --volfile-server=$H0 $M0

+TEST glusterfs --volfile-id=/$V0 --volfile-server=$H0 $M1

+

+TEST $CLI volume profile $V0 start

+

+## 8. Create a file

+TEST touch $M0/file1

+

+TEST "setfattr -n user.DOSATTRIB -v "abc" $M0/file1"

+TEST "getfattr -n user.DOSATTRIB $M1/file1 | grep -q abc"

+TEST "setfattr -n user.DOSATTRIB -v "xyz" $M0/file1"

+sleep 2; #There can be a very very small window where the next getxattr

+         #reaches md-cache, before the cache-invalidation caused by previous

+         #setxattr, reaches md-cache. Hence sleeping for 2 sec.

+         #Also it should not be > 600.

+TEST "getfattr -n user.DOSATTRIB $M1/file1 | grep -q xyz"

+

+$CLI volume profile $V0 info | grep -q CI_XATTR

+EXPECT '0' echo $?

diff --git a/xlators/debug/io-stats/src/io-stats.c b/xlators/debug/io-stats/src/io-stats.c

index 43fba57..c2375d9 100644

--- a/xlators/debug/io-stats/src/io-stats.c

+++ b/xlators/debug/io-stats/src/io-stats.c

@@ -37,6 +37,7 @@

 #include "statedump.h"

 #include <pwd.h>

 #include <grp.h>

+#include "upcall-utils.h"

 #define MAX_LIST_MEMBERS 100

 #define DEFAULT_PWD_BUF_SZ 16384

@@ -119,6 +120,7 @@ struct ios_global_stats {

         uint64_t        block_count_write[32];

         uint64_t        block_count_read[32];

         uint64_t        fop_hits[GF_FOP_MAXVALUE];

+        uint64_t        upcall_hits[GF_UPCALL_FLAGS_MAXVALUE];

         struct timeval  started_at;

         struct ios_lat  latency[GF_FOP_MAXVALUE];

         uint64_t        nr_opens;

@@ -365,6 +367,19 @@ is_fop_latency_started (call_frame_t *frame)

                                                throughput, iosstat);           \

         } while (0)

+#define BUMP_UPCALL(event)                                                     \

+        do {                                                                   \

+                struct ios_conf  *conf = NULL;                                 \

+                                                                               \

+                conf = this->private;                                          \

+                if (!conf)                                                     \

+                        break;                                                 \

+                if (conf->count_fop_hits) {                                    \

+                        conf->cumulative.upcall_hits[event]++;                 \

+                        conf->incremental.upcall_hits[event]++;                \

+                }                                                              \

+        } while (0)

+

 int

 ios_fd_ctx_get (fd_t *fd, xlator_t *this, struct ios_fd **iosfd)

 {

@@ -883,6 +898,26 @@ io_stats_dump_global_to_json_logfp (xlator_t *this,

                         "\"%s.%s.fop.%s.latency_max_usec\": \"%0.2lf\",",

                         key_prefix, str_prefix, lc_fop_name, fop_lat_max);

         }

+

+        for (i = 0; i < GF_UPCALL_FLAGS_MAXVALUE; i++) {

+                lc_fop_name = strdupa (gf_upcall_list[i]);

+                for (j = 0; lc_fop_name[j]; j++) {

+                        lc_fop_name[j] = tolower (lc_fop_name[j]);

+                }

+                fop_hits = stats->upcall_hits[i];

+                if (interval == -1) {

+                        ios_log (this, logfp,

+                                "\"%s.%s.fop.%s.count\": \"%"PRId64"\",",

+                                key_prefix, str_prefix, lc_fop_name,

+                                fop_hits);

+                } else {

+                        ios_log (this, logfp,

+                                "\"%s.%s.fop.%s.per_sec\": \"%0.2lf\",",

+                                key_prefix, str_prefix, lc_fop_name,

+                                (double)(fop_hits / interval_sec));

+                }

+        }

+

         if (interval == -1) {

                 ios_log (this, logfp, "\"%s.%s.uptime\": \"%"PRId64"\",",

                          key_prefix, str_prefix,

@@ -1233,6 +1268,14 @@ io_stats_dump_global_to_logfp (xlator_t *this, struct ios_global_stats *stats,

                                  stats->fop_hits[i], stats->latency[i].avg,

                                  stats->latency[i].min, stats->latency[i].max);

         }

+

+        for (i = 0; i < GF_UPCALL_FLAGS_MAXVALUE; i++) {

+                if (stats->upcall_hits[i])

+                        ios_log (this, logfp, "%-13s %10"PRId64" %11s "

+                                 "us %11s us %11s us", gf_upcall_list[i],

+                                 stats->upcall_hits[i], "0", "0", "0");

+        }

+

         ios_log (this, logfp, "------ ----- ----- ----- ----- ----- ----- ----- "

                  " ----- ----- ----- -----\n");

@@ -1415,6 +1458,19 @@ io_stats_dump_global_to_dict (xlator_t *this, struct ios_global_stats *stats,

                         goto out;

                 }

         }

+        for (i = 0; i < GF_UPCALL_FLAGS_MAXVALUE; i++) {

+                if (stats->upcall_hits[i] == 0)

+                        continue;

+                snprintf (key, sizeof (key), "%d-%d-upcall-hits", interval, i);

+                ret = dict_set_uint64 (dict, key, stats->upcall_hits[i]);

+                if (ret) {

+                        gf_log (this->name, GF_LOG_ERROR, "failed to "

+                                "set %s-upcall-hits: %"PRIu64,

+                                gf_upcall_list[i],

+                                stats->upcall_hits[i]);

+                        goto out;

+                }

+        }

 out:

         gf_log (this->name, GF_LOG_DEBUG, "returning %d", ret);

         return ret;

@@ -3780,6 +3836,8 @@ notify (xlator_t *this, int32_t event, void *data, ...)

         double        time = 0;

         gf_boolean_t  is_peek = _gf_false;

         va_list ap;

+        struct gf_upcall *up_data = NULL;

+        struct gf_upcall_cache_invalidation *up_ci = NULL;

         dict = data;

         va_start (ap, data);

@@ -3875,6 +3933,35 @@ notify (xlator_t *this, int32_t event, void *data, ...)

                         }

                 }

                 break;

+        case GF_EVENT_UPCALL:

+                up_data = (struct gf_upcall *)data;

+                BUMP_UPCALL (GF_UPCALL);

+

+                switch (up_data->event_type) {

+                case GF_UPCALL_RECALL_LEASE:

+                        BUMP_UPCALL (GF_UPCALL_LEASE_RECALL);

+                        break;

+                case GF_UPCALL_CACHE_INVALIDATION:

+                        up_ci = (struct gf_upcall_cache_invalidation *)up_data->data;

+                        if (up_ci->flags & (UP_XATTR | UP_XATTR_RM))

+                                BUMP_UPCALL (GF_UPCALL_CI_XATTR);

+                        if (up_ci->flags & IATT_UPDATE_FLAGS)

+                                BUMP_UPCALL (GF_UPCALL_CI_STAT);

+                        if (up_ci->flags & UP_RENAME_FLAGS)

+                                BUMP_UPCALL (GF_UPCALL_CI_RENAME);

+                        if (up_ci->flags & UP_FORGET)

+                                BUMP_UPCALL (GF_UPCALL_CI_FORGET);

+                        if (up_ci->flags & UP_NLINK)

+                                BUMP_UPCALL (GF_UPCALL_CI_NLINK);

+                        break;

+                default:

+                        gf_msg_debug (this->name, 0, "Unknown upcall event "

+                                      "type :%d", up_data->event_type);

+                        break;

+                }

+

+                default_notify (this, event, data);

+                break;

         default:

                 default_notify (this, event, data);

                 break;

-- 

1.7.1