From 10c56bcea05df9ac5a7036850039900fbe435e00 Mon Sep 17 00:00:00 2001 From: Christian Grothoff Date: Fri, 20 Mar 2020 02:36:50 +0100 Subject: improving benchmarking logic, including more timings --- src/testing/Makefile.am | 1 + .../testing_api_cmd_auditor_deposit_confirmation.c | 9 +- src/testing/testing_api_cmd_auditor_exchanges.c | 9 +- .../testing_api_cmd_bank_admin_add_incoming.c | 9 +- src/testing/testing_api_cmd_batch.c | 5 +- src/testing/testing_api_cmd_deposit.c | 10 +- src/testing/testing_api_cmd_refresh.c | 67 +++++++- src/testing/testing_api_cmd_stat.c | 190 +++++++++++++++++++++ src/testing/testing_api_cmd_withdraw.c | 23 +++ src/testing/testing_api_loop.c | 7 +- 10 files changed, 318 insertions(+), 12 deletions(-) create mode 100644 src/testing/testing_api_cmd_stat.c (limited to 'src/testing') diff --git a/src/testing/Makefile.am b/src/testing/Makefile.am index faad3f731..5d3905d9d 100644 --- a/src/testing/Makefile.am +++ b/src/testing/Makefile.am @@ -62,6 +62,7 @@ libtalertesting_la_SOURCES = \ testing_api_cmd_serialize_keys.c \ testing_api_cmd_signal.c \ testing_api_cmd_sleep.c \ + testing_api_cmd_stat.c \ testing_api_cmd_status.c \ testing_api_cmd_track.c \ testing_api_cmd_wait.c \ diff --git a/src/testing/testing_api_cmd_auditor_deposit_confirmation.c b/src/testing/testing_api_cmd_auditor_deposit_confirmation.c index bcef59c59..9981bc593 100644 --- a/src/testing/testing_api_cmd_auditor_deposit_confirmation.c +++ b/src/testing/testing_api_cmd_auditor_deposit_confirmation.c @@ -29,6 +29,12 @@ #include "taler_signatures.h" #include "backoff.h" +/** + * How long do we wait AT MOST when retrying? + */ +#define MAX_BACKOFF GNUNET_TIME_relative_multiply ( \ + GNUNET_TIME_UNIT_MILLISECONDS, 100) + /** * How often do we retry before giving up? */ @@ -160,7 +166,8 @@ deposit_confirmation_cb (void *cls, if (TALER_EC_DB_COMMIT_FAILED_ON_RETRY == ec) dcs->backoff = GNUNET_TIME_UNIT_ZERO; else - dcs->backoff = EXCHANGE_LIB_BACKOFF (dcs->backoff); + dcs->backoff = GNUNET_TIME_randomized_backoff (dcs->backoff, + MAX_BACKOFF); dcs->retry_task = GNUNET_SCHEDULER_add_delayed (dcs->backoff, &do_retry, dcs); diff --git a/src/testing/testing_api_cmd_auditor_exchanges.c b/src/testing/testing_api_cmd_auditor_exchanges.c index b5a1cab0e..688d5830b 100644 --- a/src/testing/testing_api_cmd_auditor_exchanges.c +++ b/src/testing/testing_api_cmd_auditor_exchanges.c @@ -29,6 +29,12 @@ #include "taler_signatures.h" #include "backoff.h" +/** + * How long do we wait AT MOST when retrying? + */ +#define MAX_BACKOFF GNUNET_TIME_relative_multiply ( \ + GNUNET_TIME_UNIT_MILLISECONDS, 100) + /** * How often do we retry before giving up? @@ -153,7 +159,8 @@ exchanges_cb (void *cls, if (TALER_EC_DB_COMMIT_FAILED_ON_RETRY == ec) es->backoff = GNUNET_TIME_UNIT_ZERO; else - es->backoff = EXCHANGE_LIB_BACKOFF (es->backoff); + es->backoff = GNUNET_TIME_randomized_backoff (es->backoff, + MAX_BACKOFF); es->retry_task = GNUNET_SCHEDULER_add_delayed (es->backoff, &do_retry, es); diff --git a/src/testing/testing_api_cmd_bank_admin_add_incoming.c b/src/testing/testing_api_cmd_bank_admin_add_incoming.c index 6e707a2e4..ddd27babb 100644 --- a/src/testing/testing_api_cmd_bank_admin_add_incoming.c +++ b/src/testing/testing_api_cmd_bank_admin_add_incoming.c @@ -31,6 +31,12 @@ #include "taler_signatures.h" #include "taler_testing_lib.h" +/** + * How long do we wait AT MOST when retrying? + */ +#define MAX_BACKOFF GNUNET_TIME_relative_multiply ( \ + GNUNET_TIME_UNIT_MILLISECONDS, 100) + /** * How often do we retry before giving up? @@ -206,7 +212,8 @@ confirmation_cb (void *cls, if (TALER_EC_DB_COMMIT_FAILED_ON_RETRY == ec) fts->backoff = GNUNET_TIME_UNIT_ZERO; else - fts->backoff = EXCHANGE_LIB_BACKOFF (fts->backoff); + fts->backoff = GNUNET_TIME_randomized_backoff (fts->backoff, + MAX_BACKOFF); fts->retry_task = GNUNET_SCHEDULER_add_delayed (fts->backoff, &do_retry, diff --git a/src/testing/testing_api_cmd_batch.c b/src/testing/testing_api_cmd_batch.c index fe7c19db2..ebb4e6d9a 100644 --- a/src/testing/testing_api_cmd_batch.c +++ b/src/testing/testing_api_cmd_batch.c @@ -70,7 +70,7 @@ batch_run (void *cls, TALER_TESTING_interpreter_next (is); return; } - + bs->batch[bs->batch_ip].start_time = GNUNET_TIME_absolute_get (); bs->batch[bs->batch_ip].run (bs->batch[bs->batch_ip].cls, &bs->batch[bs->batch_ip], is); @@ -193,10 +193,11 @@ TALER_TESTING_cmd_batch_next (struct TALER_TESTING_Interpreter *is) if (NULL == bs->batch[bs->batch_ip].label) { + is->commands[is->ip].finish_time = GNUNET_TIME_absolute_get (); is->ip++; return; } - + bs->batch[bs->batch_ip].finish_time = GNUNET_TIME_absolute_get (); bs->batch_ip++; } diff --git a/src/testing/testing_api_cmd_deposit.c b/src/testing/testing_api_cmd_deposit.c index 6781568a1..6404a94a4 100644 --- a/src/testing/testing_api_cmd_deposit.c +++ b/src/testing/testing_api_cmd_deposit.c @@ -34,6 +34,12 @@ */ #define NUM_RETRIES 5 +/** + * How long do we wait AT MOST when retrying? + */ +#define MAX_BACKOFF GNUNET_TIME_relative_multiply ( \ + GNUNET_TIME_UNIT_MILLISECONDS, 100) + /** * State for a "deposit" CMD. @@ -205,7 +211,8 @@ deposit_cb (void *cls, if (TALER_EC_DB_COMMIT_FAILED_ON_RETRY == ec) ds->backoff = GNUNET_TIME_UNIT_ZERO; else - ds->backoff = EXCHANGE_LIB_BACKOFF (ds->backoff); + ds->backoff = GNUNET_TIME_randomized_backoff (ds->backoff, + MAX_BACKOFF); ds->retry_task = GNUNET_SCHEDULER_add_delayed (ds->backoff, &do_retry, @@ -355,7 +362,6 @@ deposit_run (void *cls, &coin_sig, &deposit_cb, ds); - if (NULL == ds->dh) { GNUNET_break (0); diff --git a/src/testing/testing_api_cmd_refresh.c b/src/testing/testing_api_cmd_refresh.c index 2f91df377..51c3890ba 100644 --- a/src/testing/testing_api_cmd_refresh.c +++ b/src/testing/testing_api_cmd_refresh.c @@ -28,11 +28,23 @@ #include "taler_signatures.h" #include "backoff.h" +/** + * How long do we wait AT MOST when retrying? + */ +#define MAX_BACKOFF GNUNET_TIME_relative_multiply ( \ + GNUNET_TIME_UNIT_MILLISECONDS, 100) + /** * How often do we retry before giving up? */ #define NUM_RETRIES 5 +/** + * How long do we wait AT MOST when retrying? + */ +#define MAX_BACKOFF GNUNET_TIME_relative_multiply ( \ + GNUNET_TIME_UNIT_MILLISECONDS, 100) + /** * Information about a fresh coin generated by the refresh * operation. @@ -119,6 +131,11 @@ struct RefreshMeltState */ struct GNUNET_TIME_Relative backoff; + /** + * How long did we wait in total for retries? + */ + struct GNUNET_TIME_Relative total_backoff; + /** * Number of bytes in @e refresh_data. */ @@ -201,6 +218,11 @@ struct RefreshRevealState */ struct GNUNET_TIME_Relative backoff; + /** + * How long did we wait in total for retries? + */ + struct GNUNET_TIME_Relative total_backoff; + /** * Number of fresh coins withdrawn, set by the * reveal callback as it comes from the exchange, @@ -251,6 +273,11 @@ struct RefreshLinkState */ struct GNUNET_TIME_Relative backoff; + /** + * How long did we wait in total for retries? + */ + struct GNUNET_TIME_Relative total_backoff; + /** * Expected HTTP response code. */ @@ -341,7 +368,10 @@ reveal_cb (void *cls, if (TALER_EC_DB_COMMIT_FAILED_ON_RETRY == ec) rrs->backoff = GNUNET_TIME_UNIT_ZERO; else - rrs->backoff = EXCHANGE_LIB_BACKOFF (rrs->backoff); + rrs->backoff = GNUNET_TIME_randomized_backoff (rrs->backoff, + MAX_BACKOFF); + rrs->total_backoff = GNUNET_TIME_relative_add (rrs->total_backoff, + rrs->backoff); rrs->retry_task = GNUNET_SCHEDULER_add_delayed (rrs->backoff, &do_reveal_retry, rrs); @@ -391,6 +421,14 @@ reveal_cb (void *cls, fc->sig.rsa_signature = GNUNET_CRYPTO_rsa_signature_dup (sigs[i].rsa_signature); } + if (0 != rrs->total_backoff.rel_value_us) + { + GNUNET_log (GNUNET_ERROR_TYPE_INFO, + "Total reveal backoff for %s was %s\n", + rrs->is->commands[rrs->is->ip].label, + GNUNET_STRINGS_relative_time_to_string (rrs->total_backoff, + GNUNET_YES)); + } break; default: GNUNET_log (GNUNET_ERROR_TYPE_WARNING, @@ -568,7 +606,10 @@ link_cb (void *cls, if (TALER_EC_DB_COMMIT_FAILED_ON_RETRY == ec) rls->backoff = GNUNET_TIME_UNIT_ZERO; else - rls->backoff = EXCHANGE_LIB_BACKOFF (rls->backoff); + rls->backoff = GNUNET_TIME_randomized_backoff (rls->backoff, + MAX_BACKOFF); + rls->total_backoff = GNUNET_TIME_relative_add (rls->total_backoff, + rls->backoff); rls->retry_task = GNUNET_SCHEDULER_add_delayed (rls->backoff, &do_link_retry, rls); @@ -663,6 +704,14 @@ link_cb (void *cls, TALER_TESTING_interpreter_fail (rls->is); return; } + if (0 != rls->total_backoff.rel_value_us) + { + GNUNET_log (GNUNET_ERROR_TYPE_INFO, + "Total link backoff for %s was %s\n", + rls->is->commands[rls->is->ip].label, + GNUNET_STRINGS_relative_time_to_string (rls->total_backoff, + GNUNET_YES)); + } break; default: GNUNET_log (GNUNET_ERROR_TYPE_ERROR, @@ -851,7 +900,10 @@ melt_cb (void *cls, if (TALER_EC_DB_COMMIT_FAILED_ON_RETRY == ec) rms->backoff = GNUNET_TIME_UNIT_ZERO; else - rms->backoff = EXCHANGE_LIB_BACKOFF (rms->backoff); + rms->backoff = GNUNET_TIME_randomized_backoff (rms->backoff, + MAX_BACKOFF); + rms->total_backoff = GNUNET_TIME_relative_add (rms->total_backoff, + rms->backoff); rms->retry_task = GNUNET_SCHEDULER_add_delayed (rms->backoff, &do_melt_retry, @@ -872,7 +924,14 @@ melt_cb (void *cls, return; } rms->noreveal_index = noreveal_index; - + if (0 != rms->total_backoff.rel_value_us) + { + GNUNET_log (GNUNET_ERROR_TYPE_INFO, + "Total melt backoff for %s was %s\n", + rms->is->commands[rms->is->ip].label, + GNUNET_STRINGS_relative_time_to_string (rms->total_backoff, + GNUNET_YES)); + } if (GNUNET_YES == rms->double_melt) { TALER_LOG_DEBUG ("Doubling the melt (%s)\n", diff --git a/src/testing/testing_api_cmd_stat.c b/src/testing/testing_api_cmd_stat.c new file mode 100644 index 000000000..3640490ce --- /dev/null +++ b/src/testing/testing_api_cmd_stat.c @@ -0,0 +1,190 @@ +/* + This file is part of TALER + (C) 2018 Taler Systems SA + + TALER is free software; you can redistribute it and/or modify + it under the terms of the GNU General Public License as + published by the Free Software Foundation; either version 3, or + (at your option) any later version. + + TALER is distributed in the hope that it will be useful, but + WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public + License along with TALER; see the file COPYING. If not, see + +*/ +/** + * @file testing/testing_api_cmd_stat.c + * @brief command(s) to get performance statistics on other commands + * @author Christian Grothoff + */ +#include "platform.h" +#include "taler_json_lib.h" +#include +#include "taler_testing_lib.h" + + +/** + * Cleanup the state from a "stat service" CMD. + * + * @param cls closure. + * @param cmd the command which is being cleaned up. + */ +static void +stat_cleanup (void *cls, + const struct TALER_TESTING_Command *cmd) +{ + (void) cls; + (void) cmd; + /* nothing to clean. */ + return; +} + + +/** + * No traits to offer, just provide a stub to be called when + * some CMDs iterates through the list of all the commands. + * + * @param cls closure. + * @param[out] ret result. + * @param trait name of the trait. + * @param index index number of the trait to return. + * @return #GNUNET_OK on success. + */ +static int +stat_traits (void *cls, + const void **ret, + const char *trait, + unsigned int index) +{ + (void) cls; + (void) ret; + (void) trait; + (void) index; + return GNUNET_NO; +} + + +/** + * Add the time @a cmd took to the respective duration in @a timings. + * + * @param timings where to add up times + * @param cmd command to evaluate + */ +static void +stat_cmd (struct TALER_TESTING_Timer *timings, + const struct TALER_TESTING_Command *cmd) +{ + struct GNUNET_TIME_Relative duration; + + if (cmd->start_time.abs_value_us > cmd->finish_time.abs_value_us) + { + GNUNET_break (0); + return; + } + duration = GNUNET_TIME_absolute_get_difference (cmd->start_time, + cmd->finish_time); + for (unsigned int i = 0; + NULL != timings[i].prefix; + i++) + { + if (0 == strncmp (timings[i].prefix, + cmd->label, + strlen (timings[i].prefix))) + { + timings[i].total_duration + = GNUNET_TIME_relative_add (duration, + timings[i].total_duration); + timings[i].num_commands++; + break; + } + } +} + + +/** + * Obtain statistics for @a timings of @a cmd + * + * @param timings what timings to get + * @param cmd command to process + */ +static void +do_stat (struct TALER_TESTING_Timer *timings, + const struct TALER_TESTING_Command *cmd) +{ + if (TALER_TESTING_cmd_is_batch (cmd)) + { +#define BATCH_INDEX 1 + struct TALER_TESTING_Command *bcmd; + + if (GNUNET_OK != + TALER_TESTING_get_trait_cmd (cmd, + BATCH_INDEX, + &bcmd)) + { + GNUNET_break (0); + return; + } + + for (unsigned int j = 0; NULL != bcmd[j].label; j++) + do_stat (timings, + &bcmd[j]); + } + else + { + stat_cmd (timings, + cmd); + } +} + + +/** + * Run a "stat" CMD. + * + * @param cls closure. + * @param cmd the command being run. + * @param is the interpreter state. + */ +static void +stat_run (void *cls, + const struct TALER_TESTING_Command *cmd, + struct TALER_TESTING_Interpreter *is) +{ + struct TALER_TESTING_Timer *timings = cls; + + for (unsigned int i = 0; NULL != is->commands[i].label; i++) + { + if (cmd == &is->commands[i]) + break; /* skip at our current command */ + do_stat (timings, + &is->commands[i]); + } + TALER_TESTING_interpreter_next (is); +} + + +/** + * Obtain performance data from the interpreter. + * + * @param timers what commands (by label) to obtain runtimes for + * @return the command + */ +struct TALER_TESTING_Command +TALER_TESTING_cmd_stat (struct TALER_TESTING_Timer *timers) +{ + struct TALER_TESTING_Command cmd = { + .label = "stat", + .run = stat_run, + .cleanup = stat_cleanup, + .traits = stat_traits, + .cls = (void *) timers + }; + + return cmd; +} + + +/* end of testing_api_cmd_sleep.c */ diff --git a/src/testing/testing_api_cmd_withdraw.c b/src/testing/testing_api_cmd_withdraw.c index b2fc272e3..1ef341e0a 100644 --- a/src/testing/testing_api_cmd_withdraw.c +++ b/src/testing/testing_api_cmd_withdraw.c @@ -40,6 +40,12 @@ * How long do we wait AT LEAST if the exchange says the reserve is unknown? */ #define UNKNOWN_MIN_BACKOFF GNUNET_TIME_relative_multiply ( \ + GNUNET_TIME_UNIT_MILLISECONDS, 10) + +/** + * How long do we wait AT MOST if the exchange says the reserve is unknown? + */ +#define UNKNOWN_MAX_BACKOFF GNUNET_TIME_relative_multiply ( \ GNUNET_TIME_UNIT_MILLISECONDS, 100) /** @@ -103,6 +109,11 @@ struct WithdrawState */ struct GNUNET_TIME_Relative backoff; + /** + * Total withdraw backoff applied. + */ + struct GNUNET_TIME_Relative total_backoff; + /** * Expected HTTP response code to the request. */ @@ -193,6 +204,10 @@ reserve_withdraw_cb (void *cls, else ws->backoff = GNUNET_TIME_relative_max (UNKNOWN_MIN_BACKOFF, ws->backoff); + ws->backoff = GNUNET_TIME_relative_min (ws->backoff, + UNKNOWN_MAX_BACKOFF); + ws->total_backoff = GNUNET_TIME_relative_add (ws->total_backoff, + ws->backoff); ws->retry_task = GNUNET_SCHEDULER_add_delayed (ws->backoff, &do_retry, ws); @@ -224,6 +239,14 @@ reserve_withdraw_cb (void *cls, } ws->sig.rsa_signature = GNUNET_CRYPTO_rsa_signature_dup (sig->rsa_signature); + if (0 != ws->total_backoff.rel_value_us) + { + GNUNET_log (GNUNET_ERROR_TYPE_INFO, + "Total withdraw backoff for %s was %s\n", + is->commands[is->ip].label, + GNUNET_STRINGS_relative_time_to_string (ws->total_backoff, + GNUNET_YES)); + } break; case MHD_HTTP_FORBIDDEN: /* nothing to check */ diff --git a/src/testing/testing_api_loop.c b/src/testing/testing_api_loop.c index 1053e6f78..33b5cf077 100644 --- a/src/testing/testing_api_loop.c +++ b/src/testing/testing_api_loop.c @@ -169,9 +169,14 @@ TALER_TESTING_interpreter_next (struct TALER_TESTING_Interpreter *is) if (GNUNET_SYSERR == is->result) return; /* ignore, we already failled! */ if (TALER_TESTING_cmd_is_batch (cmd)) + { TALER_TESTING_cmd_batch_next (is); + } else + { + cmd->finish_time = GNUNET_TIME_absolute_get (); is->ip++; + } if (0 == (ipc % 1000)) { if (0 != ipc) @@ -267,7 +272,7 @@ interpreter_run (void *cls) GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "Running command `%s'\n", cmd->label); - + cmd->start_time = GNUNET_TIME_absolute_get (); cmd->run (cmd->cls, cmd, is); -- cgit v1.2.3