From 48b6894ef41e9a06ccbb696d062d86ef60dc2c4b Mon Sep 17 00:00:00 2001 From: Christine Caulfield 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 Reviewed-by: Jan Friesse --- 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=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..* +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