From b3862979090d4a010384869a90861ebd0891fa91 Mon Sep 17 00:00:00 2001 From: Florent Vennetier Date: Wed, 4 Mar 2020 18:39:18 +0100 Subject: [PATCH] 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 | 1 + Variables.md | 8 ++++++++ conf.json | 6 ++++++ core/ext.c | 33 ++++++++++++++++++++++++++++++- core/oioext.h | 13 +++++++++++- metautils/lib/comm_message.c | 5 ++++- metautils/lib/metautils_macros.h | 3 ++- proxy/m2_actions.c | 9 +++++++-- server/transport_gridd.c | 34 +++++++++++++++++++++++++++++--- sqliterepo/cache.c | 5 ++++- sqliterepo/cache.h | 2 +- sqliterepo/replication.c | 17 ++++++++-------- sqliterepo/repository.c | 4 +++- 13 files changed, 120 insertions(+), 20 deletions(-) diff --git a/Variables.CMakeFile b/Variables.CMakeFile index 3ab2bb1d0c..cbfc96fd9b 100644 --- a/Variables.CMakeFile +++ b/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) diff --git a/Variables.md b/Variables.md index ba95391961..ba5a6a7153 100644 --- a/Variables.md +++ b/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 diff --git a/conf.json b/conf.json index d9f36a7cb9..28bd61664b 100644 --- a/conf.json +++ b/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": { diff --git a/core/ext.c b/core/ext.c index ad34e2ad0b..4b2cb52282 100644 --- a/core/ext.c +++ b/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 diff --git a/core/oioext.h b/core/oioext.h index 5a8603660e..b2bae1379a 100644 --- a/core/oioext.h +++ b/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); diff --git a/metautils/lib/comm_message.c b/metautils/lib/comm_message.c index cd73acfc01..69fdc07519 100644 --- a/metautils/lib/comm_message.c +++ b/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( diff --git a/metautils/lib/metautils_macros.h b/metautils/lib/metautils_macros.h index aebde9062f..0ed951c029 100644 --- a/metautils/lib/metautils_macros.h +++ b/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" diff --git a/proxy/m2_actions.c b/proxy/m2_actions.c index f860ef0c43..1219c51e31 100644 --- a/proxy/m2_actions.c +++ b/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; } diff --git a/server/transport_gridd.c b/server/transport_gridd.c index 6544aa5ea1..de113d2c43 100644 --- a/server/transport_gridd.c +++ b/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,6 +679,11 @@ _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 @@ -668,6 +691,10 @@ _client_call_handler(struct req_ctx_s *req_ctx) * 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; } diff --git a/sqliterepo/cache.c b/sqliterepo/cache.c index 75d24be5e1..263e9ca6a3 100644 --- a/sqliterepo/cache.c +++ b/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=%" diff --git a/sqliterepo/cache.h b/sqliterepo/cache.h index 0ab314a19c..f22f569b89 100644 --- a/sqliterepo/cache.h +++ b/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 diff --git a/sqliterepo/replication.c b/sqliterepo/replication.c index 7ec0060245..d7bbe458b2 100644 --- a/sqliterepo/replication.c +++ b/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 diff --git a/sqliterepo/repository.c b/sqliterepo/repository.c index 26d2a5f8e2..5e5cf5c94e 100644 --- a/sqliterepo/repository.c +++ b/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