From 48b6894ef41e9a06ccbb696d062d86ef60dc2c4b Mon Sep 17 00:00:00 2001

From: Christine Caulfield <ccaulfie@redhat.com>

Date: Fri, 17 Jan 2020 14:22:16 +0000

Subject: [PATCH] stats: Add stats for scheduler misses

This patch add a stats.schedmiss.* set of entries that

are a record of the last 10 times corosync was not scheduled

in time.

These entries are keypt in reverse order (so stats.schedmiss.0.* is

always the latest one kept) and the values, including the timestamp,

are in milliseconds.

It's also possible to use a cmap tracker to follow these events, which

might be useful.

Signed-off-by: Christine Caulfield <ccaulfie@redhat.com>

Reviewed-by: Jan Friesse <jfriesse@redhat.com>

---

 exec/main.c              |   2 +

 exec/stats.c             | 113 +++++++++++++++++++++++++++++++++++++++++++----

 exec/stats.h             |   2 +

 man/cmap_keys.7          |  26 ++++++++++-

 tools/corosync-cmapctl.c |   5 ++-

 5 files changed, 136 insertions(+), 12 deletions(-)

diff --git a/exec/main.c b/exec/main.c

index 7a471a1..fb0486e 100644

--- a/exec/main.c

+++ b/exec/main.c

@@ -835,6 +835,8 @@ static void timer_function_scheduler_timeout (void *data)

 		log_printf (LOGSYS_LEVEL_WARNING, "Corosync main process was not scheduled for %0.4f ms "

 		    "(threshold is %0.4f ms). Consider token timeout increase.",

 		    (float)tv_diff / QB_TIME_NS_IN_MSEC, (float)timeout_data->max_tv_diff / QB_TIME_NS_IN_MSEC);

+

+		stats_add_schedmiss_event(tv_current / 1000, (float)tv_diff / QB_TIME_NS_IN_MSEC);

 	}

 	/*

diff --git a/exec/stats.c b/exec/stats.c

index e89504e..d5c1cbc 100644

--- a/exec/stats.c

+++ b/exec/stats.c

@@ -1,5 +1,5 @@

 /*

- * Copyright (c) 2017 Red Hat, Inc.

+ * Copyright (c) 2017-2020 Red Hat, Inc.

  *

  * All rights reserved.

  *

@@ -60,9 +60,20 @@ LOGSYS_DECLARE_SUBSYS ("STATS");

 static qb_map_t *stats_map;

+/* Structure of an element in the schedmiss array */

+struct schedmiss_entry {

+	uint64_t timestamp;

+	float delay;

+};

+#define MAX_SCHEDMISS_EVENTS 10

+static struct schedmiss_entry schedmiss_event[MAX_SCHEDMISS_EVENTS];

+static unsigned int highest_schedmiss_event;

+

+#define SCHEDMISS_PREFIX "stats.schedmiss"

+

 /* Convert iterator number to text and a stats pointer */

 struct cs_stats_conv {

-	enum {STAT_PG, STAT_SRP, STAT_KNET, STAT_KNET_HANDLE, STAT_IPCSC, STAT_IPCSG} type;

+	enum {STAT_PG, STAT_SRP, STAT_KNET, STAT_KNET_HANDLE, STAT_IPCSC, STAT_IPCSG, STAT_SCHEDMISS} type;

 	const char *name;

 	const size_t offset;

 	const icmap_value_types_t value_type;

@@ -190,6 +201,10 @@ struct cs_stats_conv cs_ipcs_global_stats[] = {

 	{ STAT_IPCSG, "global.active",        offsetof(struct ipcs_global_stats, active),           ICMAP_VALUETYPE_UINT64},

 	{ STAT_IPCSG, "global.closed",        offsetof(struct ipcs_global_stats, closed),           ICMAP_VALUETYPE_UINT64},

 };

+struct cs_stats_conv cs_schedmiss_stats[] = {

+	{ STAT_SCHEDMISS, "timestamp",    offsetof(struct schedmiss_entry, timestamp), ICMAP_VALUETYPE_UINT64},

+	{ STAT_SCHEDMISS, "delay",        offsetof(struct schedmiss_entry, delay),     ICMAP_VALUETYPE_FLOAT},

+};

 #define NUM_PG_STATS (sizeof(cs_pg_stats) / sizeof(struct cs_stats_conv))

 #define NUM_SRP_STATS (sizeof(cs_srp_stats) / sizeof(struct cs_stats_conv))

@@ -286,7 +301,7 @@ cs_error_t stats_map_init(const struct corosync_api_v1 *corosync_api)

 		stats_add_entry(param, &cs_ipcs_global_stats[i]);

 	}

-	/* KNET and IPCS stats are added when appropriate */

+	/* KNET, IPCS & SCHEDMISS stats are added when appropriate */

 	return CS_OK;

 }

@@ -307,6 +322,8 @@ cs_error_t stats_map_get(const char *key_name,

 	int link_no;

 	int service_id;

 	uint32_t pid;

+	unsigned int sm_event;

+	char *sm_type;

 	void *conn_ptr;

 	item = qb_map_get(stats_map, key_name);

@@ -363,17 +380,85 @@ cs_error_t stats_map_get(const char *key_name,

 			cs_ipcs_get_global_stats(&ipcs_global_stats);

 			stats_map_set_value(statinfo, &ipcs_global_stats, value, value_len, type);

 			break;

+		case STAT_SCHEDMISS:

+			if (sscanf(key_name, SCHEDMISS_PREFIX ".%d", &sm_event) != 1) {

+				return CS_ERR_NOT_EXIST;

+			}

+

+			sm_type = strrchr(key_name, '.');

+			if (sm_type == NULL) {

+				return CS_ERR_NOT_EXIST;

+			}

+			sm_type++;

+

+			if (strcmp(sm_type, "timestamp") == 0) {

+				memcpy(value, &schedmiss_event[sm_event].timestamp, sizeof(uint64_t));

+				*value_len = sizeof(uint64_t);

+				*type = ICMAP_VALUETYPE_UINT64;

+			}

+			if (strcmp(sm_type, "delay") == 0) {

+				memcpy(value, &schedmiss_event[sm_event].delay, sizeof(float));

+				*value_len = sizeof(float);

+				*type = ICMAP_VALUETYPE_FLOAT;

+			}

+			break;

 		default:

 			return CS_ERR_LIBRARY;

 	}

 	return CS_OK;

 }

-#define STATS_CLEAR       "stats.clear."

-#define STATS_CLEAR_KNET  "stats.clear.knet"

-#define STATS_CLEAR_IPC   "stats.clear.ipc"

-#define STATS_CLEAR_TOTEM "stats.clear.totem"

-#define STATS_CLEAR_ALL   "stats.clear.all"

+static void schedmiss_clear_stats(void)

+{

+	int i;

+	char param[ICMAP_KEYNAME_MAXLEN];

+

+	for (i=0; i

+		if (i < highest_schedmiss_event) {

+			sprintf(param, SCHEDMISS_PREFIX ".%i.timestamp", i);

+			stats_rm_entry(param);

+			sprintf(param, SCHEDMISS_PREFIX ".%i.delay", i);

+			stats_rm_entry(param);

+		}

+		schedmiss_event[i].timestamp = (uint64_t)0LL;

+		schedmiss_event[i].delay = 0.0f;

+	}

+	highest_schedmiss_event = 0;

+}

+

+/* Called from main.c */

+void stats_add_schedmiss_event(uint64_t timestamp, float delay)

+{

+	char param[ICMAP_KEYNAME_MAXLEN];

+	int i;

+

+	/* Move 'em all up */

+	for (i=MAX_SCHEDMISS_EVENTS-2; i>=0; i--) {

+		schedmiss_event[i+1].timestamp = schedmiss_event[i].timestamp;

+		schedmiss_event[i+1].delay = schedmiss_event[i].delay;

+	}

+

+	/* New entries are always at the front */

+	schedmiss_event[0].timestamp = timestamp;

+	schedmiss_event[0].delay = delay;

+

+	/* If we've not run off the end then add an entry in the trie for the new 'end' one */

+	if (highest_schedmiss_event < MAX_SCHEDMISS_EVENTS) {

+		sprintf(param, SCHEDMISS_PREFIX ".%i.timestamp", highest_schedmiss_event);

+		stats_add_entry(param, &cs_schedmiss_stats[0]);

+		sprintf(param, SCHEDMISS_PREFIX ".%i.delay", highest_schedmiss_event);

+		stats_add_entry(param, &cs_schedmiss_stats[1]);

+		highest_schedmiss_event++;

+	}

+	/* Notifications get sent by the stats_updater */

+}

+

+#define STATS_CLEAR           "stats.clear."

+#define STATS_CLEAR_KNET      "stats.clear.knet"

+#define STATS_CLEAR_IPC       "stats.clear.ipc"

+#define STATS_CLEAR_TOTEM     "stats.clear.totem"

+#define STATS_CLEAR_ALL       "stats.clear.all"

+#define STATS_CLEAR_SCHEDMISS "stats.clear.schedmiss"

 cs_error_t stats_map_set(const char *key_name,

 			 const void *value,

@@ -394,9 +479,14 @@ cs_error_t stats_map_set(const char *key_name,

 		totempg_stats_clear(TOTEMPG_STATS_CLEAR_TOTEM);

 		cleared = 1;

 	}

+	if (strncmp(key_name, STATS_CLEAR_SCHEDMISS, strlen(STATS_CLEAR_SCHEDMISS)) == 0) {

+		schedmiss_clear_stats();

+		cleared = 1;

+	}

 	if (strncmp(key_name, STATS_CLEAR_ALL, strlen(STATS_CLEAR_ALL)) == 0) {

 		totempg_stats_clear(TOTEMPG_STATS_CLEAR_TRANSPORT | TOTEMPG_STATS_CLEAR_TOTEM);

 		cs_ipcs_clear_stats();

+		schedmiss_clear_stats();

 		cleared = 1;

 	}

 	if (!cleared) {

@@ -500,6 +590,11 @@ static void stats_map_notify_fn(uint32_t event, char *key, void *old_value, void

 		return ;

 	}

+	/* Ignore schedmiss trackers as the values are read from the circular buffer */

+	if (strncmp(key, SCHEDMISS_PREFIX, strlen(SCHEDMISS_PREFIX)) == 0 ) {

+		return ;

+	}

+

 	new_val.data = new_value;

 	if (stats_map_get(key,

 			  &new_value,

@@ -556,7 +651,7 @@ cs_error_t stats_map_track_add(const char *key_name,

 		}

 		/* Get initial value */

 		if (stats_map_get(tracker->key_name,

-				  &tracker->old_value, &value_len, &type) == CS_OK) {

+				  &tracker->old_value, &value_len, &type) != CS_OK) {

 			tracker->old_value = 0ULL;

 		}

 	} else {

diff --git a/exec/stats.h b/exec/stats.h

index 45891ae..eac9e7c 100644

--- a/exec/stats.h

+++ b/exec/stats.h

@@ -69,3 +69,5 @@ void stats_trigger_trackers(void);

 void stats_ipcs_add_connection(int service_id, uint32_t pid, void *ptr);

 void stats_ipcs_del_connection(int service_id, uint32_t pid, void *ptr);

 cs_error_t cs_ipcs_get_conn_stats(int service_id, uint32_t pid, void *conn_ptr, struct ipcs_conn_stats *ipcs_stats);

+

+void stats_add_schedmiss_event(uint64_t, float delay);

diff --git a/man/cmap_keys.7 b/man/cmap_keys.7

index 6bc04fe..da95c51 100644

--- a/man/cmap_keys.7

+++ b/man/cmap_keys.7

@@ -1,5 +1,5 @@

 .\"/*

-.\" * Copyright (c) 2012-2018 Red Hat, Inc.

+.\" * Copyright (c) 2012-2020 Red Hat, Inc.

 .\" *

 .\" * All rights reserved.

 .\" *

@@ -357,6 +357,27 @@ contains the total number of interrupted sends.

 .B service_id

 contains the ID of service which the IPC is connected to.

+

+.TP

+stats.schedmiss.<n>.*

+If corosync is not scheduled after the required period of time it will

+log this event and also write an entry to the stats cmap under this key.

+There can be up to 10 entries (0..9) in here, when an 11th event happens

+the earliest will be removed.

+

+These events will always be in reverse order, so stats.schedmiss.0.* will

+always be the latest event kept and 9 the oldest. If you want to listen

+for notifications then you are recommended to listen for changes

+to stats.schedmiss.0.timestamp or stats.schedmiss.0.delay.

+

+.B timestamp

+The time of the event in ms since the Epoch (ie time_t * 1000 but with

+valid milliseconds).

+

+.B delay

+The time that corosync was paused (in ms, float value).

+

+

 .TP

 stats.clear.*

 These are write-only keys used to clear the stats for various subsystems

@@ -370,6 +391,9 @@ Clears the knet stats

 .B ipc

 Clears the ipc stats

+.B schedmiss

+Clears the schedmiss stats

+

 .B all

 Clears all of the above stats

diff --git a/tools/corosync-cmapctl.c b/tools/corosync-cmapctl.c

index a4b61bd..ffca7e1 100644

--- a/tools/corosync-cmapctl.c

+++ b/tools/corosync-cmapctl.c

@@ -115,7 +115,7 @@ static int print_help(void)

 	printf("    about the networking and IPC traffic in some detail.\n");

 	printf("\n");

 	printf("Clear stats:\n");

-	printf("    corosync-cmapctl -C [knet|ipc|totem|all]\n");

+	printf("    corosync-cmapctl -C [knet|ipc|totem|schedmiss|all]\n");

 	printf("    The 'stats' map is implied\n");

 	printf("\n");

 	printf("Load settings from a file:\n");

@@ -849,6 +849,7 @@ int main(int argc, char *argv[])

 			if (strcmp(optarg, "knet") == 0 ||

 			    strcmp(optarg, "totem") == 0 ||

 			    strcmp(optarg, "ipc") == 0 ||

+			    strcmp(optarg, "schedmiss") == 0 ||

 			    strcmp(optarg, "all") == 0) {

 				action = ACTION_CLEARSTATS;

 				clear_opt = optarg;

@@ -857,7 +858,7 @@ int main(int argc, char *argv[])

 				map = CMAP_MAP_STATS;

 			}

 			else {

-				fprintf(stderr, "argument to -C should be 'knet', 'totem', 'ipc' or 'all'\n");

+				fprintf(stderr, "argument to -C should be 'knet', 'totem', 'ipc', 'schedmiss' or 'all'\n");

 				return (EXIT_FAILURE);

 			}

 			break;

-- 

1.8.3.1