server: get server-side performance data

Save some performance data in the thread local data. This is disabled by
default, can be enabled for each service (even when the service is running)
or per request.
Performance data is printed at the end of access log messages.

Variables.CMakeFile

@@ -128,6 +128,7 @@ dir2macro(OIO_SERVER_FD_MAX_PASSIVE)
 dir2macro(OIO_SERVER_LOG_OUTGOING)
 dir2macro(OIO_SERVER_MALLOC_TRIM_SIZE_ONDEMAND)
 dir2macro(OIO_SERVER_MALLOC_TRIM_SIZE_PERIODIC)
+dir2macro(OIO_SERVER_PERFDATA_ENABLED)
 dir2macro(OIO_SERVER_PERIODIC_DECACHE_MAX_BASES)
 dir2macro(OIO_SERVER_PERIODIC_DECACHE_MAX_DELAY)
 dir2macro(OIO_SERVER_PERIODIC_DECACHE_PERIOD)

Variables.md

@@ -1103,6 +1103,14 @@ Used by `gcc`
  * cmake directive: *OIO_SERVER_MALLOC_TRIM_SIZE_PERIODIC*
  * range: 0 -> 2147483648
 
+### server.perfdata.enabled
+
+> Enable server-side performance data collection.
+
+ * default: **FALSE**
+ * type: gboolean
+ * cmake directive: *OIO_SERVER_PERFDATA_ENABLED*
+
 ### server.periodic_decache.max_bases
 
 > How many bases may be decached each time the background task performs its Dance of Death

conf.json

@@ -312,6 +312,11 @@
 				"def": false,
 				"descr": "" },
 
+			{ "type": "bool", "name": "server_perfdata_enabled",
+				"key": "server.perfdata.enabled",
+				"def": false,
+				"descr": "Enable server-side performance data collection."},
+
 			{ "type": "bool", "name": "oio_socket_linger_onoff",
 				"key": "socket.linger.enabled",
 				"def": false,
@@ -813,6 +818,7 @@
 				"descr": "How long a request might take to run on the server side. This value is used to compute a deadline for several waitings (DB cache, manager of elections, etc). Common to all sqliterepo-based services, it might be overriden.",
 				"def": "300s", "min": "1ms", "max": "1h",
 				"aliases": ["server.request.max_delay_start"] }
+
 		]
 	},
 	"proxy": {

core/ext.c

@@ -1,6 +1,6 @@
 /*
 OpenIO SDS core library
-Copyright (C) 2015-2017 OpenIO SAS, as part of OpenIO SDS
+Copyright (C) 2015-2020 OpenIO SAS, as part of OpenIO SDS
 
 This library is free software; you can redistribute it and/or
 modify it under the terms of the GNU Lesser General Public
@@ -181,6 +181,7 @@ struct oio_ext_local_s {
 	gchar *force_versioning;
 	guint8 simulate_versioning;
 	gchar reqid[LIMIT_LENGTH_REQID];
+	GHashTable *perfdata;
 };
 
 static void _local_free(gpointer p) {
@@ -199,6 +200,10 @@ static void _local_free(gpointer p) {
 		g_free(l->force_versioning);
 		l->force_versioning = NULL;
 	}
+	if (l->perfdata) {
+		g_hash_table_destroy(l->perfdata);
+		l->perfdata = NULL;
+	}
 	g_free (l);
 }
 
@@ -352,6 +357,32 @@ void oio_ext_set_simulate_versioning(const gboolean simulate_versioning) {
 	l->simulate_versioning = BOOL(simulate_versioning);
 }
 
+GHashTable *oio_ext_get_perfdata(void) {
+	struct oio_ext_local_s *l = _local_ensure();
+	return l->perfdata;
+}
+
+GHashTable *oio_ext_enable_perfdata(gboolean enabled) {
+	struct oio_ext_local_s *l = _local_ensure();
+	if (enabled && !l->perfdata) {
+		l->perfdata = g_hash_table_new_full(
+				g_str_hash, g_str_equal, g_free, NULL);
+	} else if (!enabled && l->perfdata) {
+		g_hash_table_destroy(l->perfdata);
+		l->perfdata = NULL;
+	}
+	return l->perfdata;
+}
+
+void oio_ext_add_perfdata(const gchar *key, gint64 value) {
+	struct oio_ext_local_s *l = _local_ensure();
+	if (l->perfdata) {
+		gint64 old = GPOINTER_TO_INT(g_hash_table_lookup(l->perfdata, key));
+		g_hash_table_insert(l->perfdata,
+				g_strdup(key), GINT_TO_POINTER(old + value));
+	}
+}
+
 /* -------------------------------------------------------------------------- */
 
 # ifdef HAVE_BACKTRACE

core/oioext.h

@@ -1,6 +1,6 @@
 /*
 OpenIO SDS core library
-Copyright (C) 2015-2017 OpenIO SAS, as part of OpenIO SDS
+Copyright (C) 2015-2020 OpenIO SAS, as part of OpenIO SDS
 
 This library is free software; you can redistribute it and/or
 modify it under the terms of the GNU Lesser General Public
@@ -125,6 +125,17 @@ gboolean oio_ext_has_simulate_versioning(void);
 
 void oio_ext_set_simulate_versioning(const gboolean simulate_versioning);
 
+/** Enable or disable the performance data collection. */
+GHashTable *oio_ext_enable_perfdata(gboolean enabled);
+
+/** Get the performance data hash table (will be NULL when disabled) */
+GHashTable *oio_ext_get_perfdata(void);
+
+/** Add one metric in the performance data hash table.
+ * Does not take ownership of the key.
+ * When called several times with the same key, add values. */
+void oio_ext_add_perfdata(const gchar *key, gint64 value);
+
 gint64 oio_ext_real_time (void);
 
 gint64 oio_ext_monotonic_time (void);

metautils/lib/comm_message.c

@@ -1,7 +1,7 @@
 /*
 OpenIO SDS metautils
 Copyright (C) 2014 Worldline, as part of Redcurrant
-Copyright (C) 2015-2017 OpenIO SAS, as part of OpenIO SDS
+Copyright (C) 2015-2020 OpenIO SAS, as part of OpenIO SDS
 
 This library is free software; you can redistribute it and/or
 modify it under the terms of the GNU Lesser General Public
@@ -151,6 +151,9 @@ message_marshall_gba(MESSAGE m, GError **err)
 	if (oio_ext_has_simulate_versioning())
 		metautils_message_add_field_strint(m, NAME_MSGKEY_SIM_VER, 1);
 
+	if (oio_ext_get_perfdata())
+		metautils_message_add_field_strint(m, NAME_MSGKEY_PERFDATA, 1);
+
 	const gchar *user_agent = oio_ext_get_user_agent();
 	if (user_agent != NULL)
 		metautils_message_add_field_str(

metautils/lib/metautils_macros.h

@@ -1,7 +1,7 @@
 /*
 OpenIO SDS metautils
 Copyright (C) 2014 Worldline, as part of Redcurrant
-Copyright (C) 2015-2019 OpenIO SAS, as part of OpenIO SDS
+Copyright (C) 2015-2020 OpenIO SAS, as part of OpenIO SDS
 
 This library is free software; you can redistribute it and/or
 modify it under the terms of the GNU Lesser General Public
@@ -85,6 +85,7 @@ License along with this library.
 #define NAME_MSGKEY_NOTIN              "!IN"
 #define NAME_MSGKEY_OLD                "OLD"
 #define NAME_MSGKEY_OVERWRITE          "OVERWRITE"
+#define NAME_MSGKEY_PERFDATA           "PERF"
 #define NAME_MSGKEY_PREFIX             "PREFIX"
 #define NAME_MSGKEY_QUERY              "Q"
 #define NAME_MSGKEY_RECOMPUTE          "RECOMPUTE"

proxy/m2_actions.c

@@ -1,7 +1,7 @@
 /*
 OpenIO SDS proxy
 Copyright (C) 2014 Worldline, as part of Redcurrant
-Copyright (C) 2015-2019 OpenIO SAS, as part of OpenIO SDS
+Copyright (C) 2015-2020 OpenIO SAS, as part of OpenIO SDS
 
 This program is free software: you can redistribute it and/or modify
 it under the terms of the GNU Affero General Public License as
@@ -53,6 +53,10 @@ _resolve_meta2(struct req_args_s *args, enum proxy_preference_e how,
 		out_list = (GSList **) out;
 		*out_list = NULL;
 	}
+	/* Check if the client application wants performance data. */
+	gboolean req_perfdata_enabled =
+		g_tree_lookup(args->rq->tree_headers, PROXYD_HEADER_PERFDATA) != NULL;
+	oio_ext_enable_perfdata(req_perfdata_enabled);
 
 	GError *err = gridd_request_replicated_with_retry(args, &ctx, pack);
 
@@ -73,13 +77,14 @@ _resolve_meta2(struct req_args_s *args, enum proxy_preference_e how,
 			}
 		}
 	}
-	if (g_tree_lookup(args->rq->tree_headers, PROXYD_HEADER_PERFDATA)) {
+	if (req_perfdata_enabled) {
 		gchar *perfdata = g_strdup_printf(
 				"resolve=%"G_GINT64_FORMAT",meta2=%"G_GINT64_FORMAT,
 				ctx.resolve_duration, ctx.request_duration);
 		args->rp->add_header(PROXYD_HEADER_PERFDATA, perfdata);
 	}
 
+	oio_ext_enable_perfdata(FALSE);
 	client_clean (&ctx);
 	return err;
 }

server/transport_gridd.c

@@ -1,7 +1,7 @@
 /*
 OpenIO SDS server
 Copyright (C) 2014 Worldline, as part of Redcurrant
-Copyright (C) 2015-2019 OpenIO SAS, as part of OpenIO SDS
+Copyright (C) 2015-2020 OpenIO SAS, as part of OpenIO SDS
 
 This library is free software; you can redistribute it and/or
 modify it under the terms of the GNU Lesser General Public
@@ -229,6 +229,15 @@ network_client_log_access(struct log_item_s *item)
 
 	/* arbitrary */
 	g_string_append_printf(gstr, " t=%"G_GINT64_FORMAT, diff_handler);
+	GHashTable *perfdata = oio_ext_get_perfdata();
+	if (perfdata) {
+		void __log_perfdata(gpointer key, gpointer val, gpointer udata UNUSED)
+		{
+			g_string_append_printf(gstr, " %s=%"G_GINT64_FORMAT,
+				(char*)key, (gint64)GPOINTER_TO_INT(val));
+		}
+		g_hash_table_foreach(perfdata, __log_perfdata, NULL);
+	}
 	if (r->subject) {
 		g_string_append_c (gstr, ' ');
 		g_string_append(gstr, ensure(r->subject));
@@ -514,9 +523,16 @@ _notify_request(struct req_ctx_s *ctx, GQuark gq_count, GQuark gq_time)
 static gsize
 _reply_message(struct network_client_s *clt, MESSAGE reply)
 {
+	gint64 start = oio_ext_monotonic_time();
 	GByteArray *encoded = message_marshall_gba_and_clean(reply);
+	gint64 encode = oio_ext_monotonic_time();
 	gsize encoded_size = encoded->len;
 	network_client_send_slab(clt, data_slab_make_gba(encoded));
+	gint64 send = oio_ext_monotonic_time();
+	if (server_perfdata_enabled) {
+		oio_ext_add_perfdata("resp_encode", encode - start);
+		oio_ext_add_perfdata("resp_send", send - encode);
+	}
 	return encoded_size;
 }
 
@@ -587,8 +603,10 @@ _client_call_handler(struct req_ctx_s *req_ctx)
 			GHashTableIter iter;
 			gpointer n, v;
 			g_hash_table_iter_init(&iter, headers);
-			while (g_hash_table_iter_next(&iter, &n, &v))
-				metautils_message_add_field(answer, (gchar*)n, ((GByteArray*)v)->data, ((GByteArray*)v)->len);
+			while (g_hash_table_iter_next(&iter, &n, &v)) {
+				metautils_message_add_field(answer, (gchar*)n,
+						((GByteArray*)v)->data, ((GByteArray*)v)->len);
+			}
 		}
 
 		/* encode and send */
@@ -661,13 +679,22 @@ _client_call_handler(struct req_ctx_s *req_ctx)
 			ctx.deadline = MIN(ctx.deadline, req_deadline);
 		}
 	}
+	gint64 req_perfdata_enabled = FALSE;
+	if (metautils_message_extract_string_noerror(req_ctx->request,
+				NAME_MSGKEY_PERFDATA, tostr, sizeof(tostr))) {
+		oio_str_is_number(tostr, &req_perfdata_enabled);
+	}
 
 	/* Ugly quirk: it is currently too expansive to alter all the calls to
 	 * the meta2 backend, especially right now while we are writing this
 	 * comment in the 4.x branch. There is currently no support of a single
 	 * context with all the common open args, in 4.x, while there is one in
 	 * the 'master' branch. */
 	oio_ext_set_deadline(ctx.deadline);
+	if (req_perfdata_enabled || server_perfdata_enabled) {
+		oio_ext_enable_perfdata(TRUE);
+		oio_ext_add_perfdata("req_decode", now - req_ctx->tv_start);
+	}
 
 	gboolean rc = FALSE;
 	if (req_ctx->tv_start < OLDEST(now, meta_queue_max_delay)) {
@@ -704,6 +731,7 @@ _client_call_handler(struct req_ctx_s *req_ctx)
 	EXTRA_ASSERT(body == NULL);
 	if (headers)
 		g_hash_table_destroy(headers);
+	oio_ext_enable_perfdata(FALSE);
 	return rc;
 }
 

sqliterepo/cache.c

@@ -745,8 +745,10 @@ sqlx_cache_open_and_lock_base(sqlx_cache_t *cache, const hashstr_t *hname,
 	if (base) {
 		gint64 now = oio_ext_monotonic_time();
 		time_t now_secs = now / G_TIME_SPAN_SECOND;
+		gint64 wait_time = now - start;
 		grid_single_rrd_add(base->open_attempts, now_secs, 1);
-		grid_single_rrd_add(base->open_wait_time, now_secs, now - start);
+		grid_single_rrd_add(base->open_wait_time, now_secs, wait_time);
+		oio_ext_add_perfdata("db_wait", wait_time);
 
 		if (!err) {
 			sqlx_base_debug(__FUNCTION__, base);
@@ -825,6 +827,7 @@ sqlx_cache_unlock_and_close_base(sqlx_cache_t *cache, gint bd, guint32 flags)
 
 	if (base && !err) {
 		sqlx_base_debug(__FUNCTION__, base);
+		oio_ext_add_perfdata("db_lock", lock_time);
 		if (lock_time > _cache_timeout_open * 3 / 4) {
 			GRID_WARN("The current thread held a lock on [%s] for %"
 					G_GINT64_FORMAT"us (sqliterepo.cache.timeout.open=%"

sqliterepo/cache.h

@@ -1,7 +1,7 @@
 /*
 OpenIO SDS sqliterepo
 Copyright (C) 2014 Worldline, as part of Redcurrant
-Copyright (C) 2015-2017 OpenIO SAS, as part of OpenIO SDS
+Copyright (C) 2015-2020 OpenIO SAS, as part of OpenIO SDS
 
 This library is free software; you can redistribute it and/or
 modify it under the terms of the GNU Lesser General Public

sqliterepo/replication.c

@@ -1,7 +1,7 @@
 /*
 OpenIO SDS sqliterepo
 Copyright (C) 2014 Worldline, as part of Redcurrant
-Copyright (C) 2015-2017 OpenIO SAS, as part of OpenIO SDS
+Copyright (C) 2015-2020 OpenIO SAS, as part of OpenIO SDS
 
 This library is free software; you can redistribute it and/or
 modify it under the terms of the GNU Lesser General Public
@@ -445,19 +445,20 @@ hook_commit(gpointer d)
 
 	ctx->any_change = 1;
 
+	gint64 start = oio_ext_monotonic_time();
+	int rc = 0;
 	if (ctx->huge) {
 		_defer_synchronous_RESYNC(ctx);
-		return 0;
-	}
-
-	if (ctx->sequence.list.count <= 0) {
+	} else if (ctx->sequence.list.count <= 0) {
 		GRID_DEBUG("Empty transaction!");
 		ctx->any_change = 0;
 		context_flush_rowsets(ctx);
-		return 0;
+	} else {
+		rc = _perform_REPLICATE(ctx);
 	}
-
-	return _perform_REPLICATE(ctx);
+	gint64 duration = oio_ext_monotonic_time() - start;
+	oio_ext_add_perfdata("db_commit", duration);
+	return rc;
 }
 
 static void

sqliterepo/repository.c

@@ -1,7 +1,7 @@
 /*
 OpenIO SDS sqliterepo
 Copyright (C) 2014 Worldline, as part of Redcurrant
-Copyright (C) 2015-2019 OpenIO SAS, as part of OpenIO SDS
+Copyright (C) 2015-2020 OpenIO SAS, as part of OpenIO SDS
 
 This library is free software; you can redistribute it and/or
 modify it under the terms of the GNU Lesser General Public
@@ -912,6 +912,7 @@ _open_and_lock_base(struct open_args_s *args, enum election_status_e expected,
 	const gboolean election_configured =
 		election_manager_configured(args->repo->election_manager);
 
+	gint64 start = oio_ext_monotonic_time();
 	if (election_configured && !args->no_refcheck) {
 		gboolean replicated = FALSE;
 		enum election_step_e step = STEP_NONE;
@@ -970,6 +971,7 @@ _open_and_lock_base(struct open_args_s *args, enum election_status_e expected,
 
 		g_free0(url);
 	}
+	oio_ext_add_perfdata("db_election", oio_ext_monotonic_time() - start);
 
 	if (!err)
 		err = args->repo->cache