From 1b24e2f9bb84d64ff07f28a330e1913de790df0c Mon Sep 17 00:00:00 2001 From: Christian Grothoff Date: Fri, 20 Mar 2020 18:38:57 +0100 Subject: [PATCH] more statistics, make explicit table lock optional, can hurt performance badly --- doc/prebuilt | 2 +- src/benchmark/taler-exchange-benchmark.c | 35 ++++++++++++++----- src/exchangedb/plugin_exchangedb_postgres.c | 27 ++++++++++---- src/include/taler_testing_lib.h | 24 +++++++++++++ ...ing_api_cmd_auditor_deposit_confirmation.c | 7 ++-- .../testing_api_cmd_auditor_exchanges.c | 3 ++ .../testing_api_cmd_bank_admin_add_incoming.c | 3 ++ src/testing/testing_api_cmd_bank_transfer.c | 11 +++--- src/testing/testing_api_cmd_batch.c | 5 ++- src/testing/testing_api_cmd_deposit.c | 3 ++ src/testing/testing_api_cmd_refresh.c | 9 +++++ src/testing/testing_api_cmd_stat.c | 7 ++++ src/testing/testing_api_cmd_withdraw.c | 3 ++ src/testing/testing_api_loop.c | 5 ++- 14 files changed, 120 insertions(+), 24 deletions(-) diff --git a/doc/prebuilt b/doc/prebuilt index ca53235cc..934a6a183 160000 --- a/doc/prebuilt +++ b/doc/prebuilt @@ -1 +1 @@ -Subproject commit ca53235ccfa0458ebf11c204888ca370e20ec3f5 +Subproject commit 934a6a18301e81c4fd1b3a8cda2dc13dca4741cc diff --git a/src/benchmark/taler-exchange-benchmark.c b/src/benchmark/taler-exchange-benchmark.c index 8bfbc42a5..307b0f378 100644 --- a/src/benchmark/taler-exchange-benchmark.c +++ b/src/benchmark/taler-exchange-benchmark.c @@ -175,6 +175,11 @@ static enum BenchmarkMode mode; */ static struct GNUNET_CONFIGURATION_Handle *cfg; +/** + * Should we create all of the reserves at the beginning? + */ +static int reserves_first; + /** * Currency used. */ @@ -297,9 +302,6 @@ eval_probability (float probability) } -static int reserves_first = 1; - - /** * Actual commands construction and execution. * @@ -467,14 +469,27 @@ static void print_stats (void) { for (unsigned int i = 0; NULL != timings[i].prefix; i++) + { + char *total; + char *latency; + + total = GNUNET_strdup ( + GNUNET_STRINGS_relative_time_to_string (timings[i].total_duration, + GNUNET_YES)); + latency = GNUNET_strdup ( + GNUNET_STRINGS_relative_time_to_string (timings[i].success_latency, + GNUNET_YES)); fprintf (stderr, - "%s-%d took %s in total for %u executions\n", + "%s-%d took %s in total with %s for latency for %u executions (%u repeats)\n", timings[i].prefix, (int) getpid (), - GNUNET_STRINGS_relative_time_to_string ( - timings[i].total_duration, - GNUNET_YES), - timings[i].num_commands); + total, + latency, + timings[i].num_commands, + timings[i].num_retries); + GNUNET_free (total); + GNUNET_free (latency); + } } @@ -959,6 +974,10 @@ main (int argc, "fakebank", "start a fakebank instead of the Python bank", &use_fakebank), + GNUNET_GETOPT_option_flag ('F', + "reserves-first", + "should all reserves be created first, before starting normal operations", + &reserves_first), GNUNET_GETOPT_option_flag ('K', "linger", "linger around until key press", diff --git a/src/exchangedb/plugin_exchangedb_postgres.c b/src/exchangedb/plugin_exchangedb_postgres.c index b3139a86c..a353dba96 100644 --- a/src/exchangedb/plugin_exchangedb_postgres.c +++ b/src/exchangedb/plugin_exchangedb_postgres.c @@ -38,6 +38,12 @@ */ #define AUTO_EXPLAIN 1 +/** + * Should we explicitly lock certain individual tables prior to SELECT+INSERT + * combis? + */ +#define EXPLICIT_LOCKS 0 + /** * Wrapper macro to add the currency from the plugin's state * when fetching amounts from the database. @@ -568,7 +574,8 @@ postgres_get_session (void *cls) "SELECT" " denom_pub_hash" " FROM known_coins" - " WHERE coin_pub=$1", + " WHERE coin_pub=$1" + " FOR SHARE;", 1), /* Lock deposit table; NOTE: we may want to eventually shard the deposit table to avoid this lock being the main point of @@ -2056,9 +2063,6 @@ postgres_get_withdraw_info ( struct TALER_EXCHANGEDB_CollectableBlindcoin *collectable) { struct PostgresClosure *pg = cls; - struct GNUNET_PQ_QueryParam no_params[] = { - GNUNET_PQ_query_param_end - }; struct GNUNET_PQ_QueryParam params[] = { GNUNET_PQ_query_param_auto_from_type (h_blind), GNUNET_PQ_query_param_end @@ -2078,12 +2082,17 @@ postgres_get_withdraw_info ( &collectable->withdraw_fee), GNUNET_PQ_result_spec_end }; +#if EXPLICIT_LOCKS + struct GNUNET_PQ_QueryParam no_params[] = { + GNUNET_PQ_query_param_end + }; enum GNUNET_DB_QueryStatus qs; if (0 > (qs = GNUNET_PQ_eval_prepared_non_select (session->conn, "lock_withdraw", no_params))) return qs; +#endif collectable->h_coin_envelope = *h_blind; return GNUNET_PQ_eval_prepared_singleton_select (session->conn, "get_withdraw_info", @@ -2576,9 +2585,6 @@ postgres_have_deposit (void *cls, GNUNET_PQ_query_param_auto_from_type (&deposit->merchant_pub), GNUNET_PQ_query_param_end }; - struct GNUNET_PQ_QueryParam no_params[] = { - GNUNET_PQ_query_param_end - }; struct TALER_EXCHANGEDB_Deposit deposit2; struct GNUNET_PQ_ResultSpec rs[] = { TALER_PQ_RESULT_SPEC_AMOUNT ("amount_with_fee", @@ -2594,11 +2600,16 @@ postgres_have_deposit (void *cls, GNUNET_PQ_result_spec_end }; enum GNUNET_DB_QueryStatus qs; +#if EXPLICIT_LOCKS + struct GNUNET_PQ_QueryParam no_params[] = { + GNUNET_PQ_query_param_end + }; if (0 > (qs = GNUNET_PQ_eval_prepared_non_select (session->conn, "lock_deposit", no_params))) return qs; +#endif GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "Getting deposits for coin %s\n", TALER_B2S (&deposit->coin.coin_pub)); @@ -3149,6 +3160,7 @@ postgres_ensure_coin_known (void *cls, struct PostgresClosure *pc = cls; enum GNUNET_DB_QueryStatus qs; struct TALER_CoinPublicInfo known_coin; +#if EXPLICIT_LOCKS struct GNUNET_PQ_QueryParam no_params[] = { GNUNET_PQ_query_param_end }; @@ -3157,6 +3169,7 @@ postgres_ensure_coin_known (void *cls, "lock_known_coins", no_params))) return qs; +#endif /* check if the coin is already known */ qs = postgres_get_known_coin (pc, diff --git a/src/include/taler_testing_lib.h b/src/include/taler_testing_lib.h index 6066aa5ee..a7c91ca4b 100644 --- a/src/include/taler_testing_lib.h +++ b/src/include/taler_testing_lib.h @@ -505,6 +505,19 @@ struct TALER_TESTING_Command */ struct GNUNET_TIME_Absolute finish_time; + /** + * When did we start the last request of this command? + * Delta to @e finish_time gives the latency for the last + * successful request. + */ + struct GNUNET_TIME_Absolute last_req_time; + + /** + * How often did we try to execute this command? (In case + * it is a request that is repated.) + */ + unsigned int num_tries; + }; @@ -1846,10 +1859,21 @@ struct TALER_TESTING_Timer */ struct GNUNET_TIME_Relative total_duration; + /** + * Total time spend waiting for the *successful* exeuction + * in all commands of this type. + */ + struct GNUNET_TIME_Relative success_latency; + /** * Number of commands summed up. */ unsigned int num_commands; + + /** + * Number of retries summed up. + */ + unsigned int num_retries; }; diff --git a/src/testing/testing_api_cmd_auditor_deposit_confirmation.c b/src/testing/testing_api_cmd_auditor_deposit_confirmation.c index 9981bc593..b3ca4dd48 100644 --- a/src/testing/testing_api_cmd_auditor_deposit_confirmation.c +++ b/src/testing/testing_api_cmd_auditor_deposit_confirmation.c @@ -125,6 +125,8 @@ do_retry (void *cls) struct DepositConfirmationState *dcs = cls; dcs->retry_task = NULL; + dcs->is->commands[dcs->is->ip].last_req_time + = GNUNET_TIME_absolute_get (); deposit_confirmation_run (dcs, NULL, dcs->is); @@ -168,6 +170,7 @@ deposit_confirmation_cb (void *cls, else dcs->backoff = GNUNET_TIME_randomized_backoff (dcs->backoff, MAX_BACKOFF); + dcs->is->commands[dcs->is->ip].num_tries++; dcs->retry_task = GNUNET_SCHEDULER_add_delayed (dcs->backoff, &do_retry, dcs); @@ -442,8 +445,8 @@ TALER_TESTING_cmd_deposit_confirmation (const char *label, * @return the command with retries enabled */ struct TALER_TESTING_Command -TALER_TESTING_cmd_deposit_confirmation_with_retry (struct TALER_TESTING_Command - cmd) +TALER_TESTING_cmd_deposit_confirmation_with_retry ( + struct TALER_TESTING_Command cmd) { struct DepositConfirmationState *dcs; diff --git a/src/testing/testing_api_cmd_auditor_exchanges.c b/src/testing/testing_api_cmd_auditor_exchanges.c index 688d5830b..4b143f106 100644 --- a/src/testing/testing_api_cmd_auditor_exchanges.c +++ b/src/testing/testing_api_cmd_auditor_exchanges.c @@ -115,6 +115,8 @@ do_retry (void *cls) struct ExchangesState *es = cls; es->retry_task = NULL; + es->is->commands[es->is->ip].last_req_time + = GNUNET_TIME_absolute_get (); exchanges_run (es, NULL, es->is); @@ -161,6 +163,7 @@ exchanges_cb (void *cls, else es->backoff = GNUNET_TIME_randomized_backoff (es->backoff, MAX_BACKOFF); + es->is->commands[es->is->ip].num_tries++; 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 ddd27babb..cf90e50e0 100644 --- a/src/testing/testing_api_cmd_bank_admin_add_incoming.c +++ b/src/testing/testing_api_cmd_bank_admin_add_incoming.c @@ -162,6 +162,8 @@ do_retry (void *cls) struct AdminAddIncomingState *fts = cls; fts->retry_task = NULL; + fts->is->commands[fts->is->ip].last_req_time + = GNUNET_TIME_absolute_get (); admin_add_incoming_run (fts, NULL, fts->is); @@ -214,6 +216,7 @@ confirmation_cb (void *cls, else fts->backoff = GNUNET_TIME_randomized_backoff (fts->backoff, MAX_BACKOFF); + fts->is->commands[fts->is->ip].num_tries++; fts->retry_task = GNUNET_SCHEDULER_add_delayed (fts->backoff, &do_retry, diff --git a/src/testing/testing_api_cmd_bank_transfer.c b/src/testing/testing_api_cmd_bank_transfer.c index 03bf5973c..6da7c99b0 100644 --- a/src/testing/testing_api_cmd_bank_transfer.c +++ b/src/testing/testing_api_cmd_bank_transfer.c @@ -149,6 +149,8 @@ do_retry (void *cls) struct TransferState *fts = cls; fts->retry_task = NULL; + fts->is->commands[fts->is->ip].last_req_time + = GNUNET_TIME_absolute_get (); transfer_run (fts, NULL, fts->is); @@ -197,10 +199,11 @@ confirmation_cb (void *cls, fts->backoff = GNUNET_TIME_UNIT_ZERO; else fts->backoff = EXCHANGE_LIB_BACKOFF (fts->backoff); - fts->retry_task = GNUNET_SCHEDULER_add_delayed - (fts->backoff, - &do_retry, - fts); + fts->is->commands[fts->is->ip].num_tries++; + fts->retry_task + = GNUNET_SCHEDULER_add_delayed (fts->backoff, + &do_retry, + fts); return; } } diff --git a/src/testing/testing_api_cmd_batch.c b/src/testing/testing_api_cmd_batch.c index ebb4e6d9a..5de923f7f 100644 --- a/src/testing/testing_api_cmd_batch.c +++ b/src/testing/testing_api_cmd_batch.c @@ -70,7 +70,10 @@ 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].start_time + = bs->batch[bs->batch_ip].last_req_time + = GNUNET_TIME_absolute_get (); + bs->batch[bs->batch_ip].num_tries = 1; bs->batch[bs->batch_ip].run (bs->batch[bs->batch_ip].cls, &bs->batch[bs->batch_ip], is); diff --git a/src/testing/testing_api_cmd_deposit.c b/src/testing/testing_api_cmd_deposit.c index 6404a94a4..7e97f544c 100644 --- a/src/testing/testing_api_cmd_deposit.c +++ b/src/testing/testing_api_cmd_deposit.c @@ -164,6 +164,8 @@ do_retry (void *cls) struct DepositState *ds = cls; ds->retry_task = NULL; + ds->is->commands[ds->is->ip].last_req_time + = GNUNET_TIME_absolute_get (); deposit_run (ds, NULL, ds->is); @@ -213,6 +215,7 @@ deposit_cb (void *cls, else ds->backoff = GNUNET_TIME_randomized_backoff (ds->backoff, MAX_BACKOFF); + ds->is->commands[ds->is->ip].num_tries++; ds->retry_task = GNUNET_SCHEDULER_add_delayed (ds->backoff, &do_retry, diff --git a/src/testing/testing_api_cmd_refresh.c b/src/testing/testing_api_cmd_refresh.c index 51c3890ba..f290a5add 100644 --- a/src/testing/testing_api_cmd_refresh.c +++ b/src/testing/testing_api_cmd_refresh.c @@ -315,6 +315,8 @@ do_reveal_retry (void *cls) struct RefreshRevealState *rrs = cls; rrs->retry_task = NULL; + rrs->is->commands[rrs->is->ip].last_req_time + = GNUNET_TIME_absolute_get (); refresh_reveal_run (rrs, NULL, rrs->is); @@ -372,6 +374,7 @@ reveal_cb (void *cls, MAX_BACKOFF); rrs->total_backoff = GNUNET_TIME_relative_add (rrs->total_backoff, rrs->backoff); + rrs->is->commands[rrs->is->ip].num_tries++; rrs->retry_task = GNUNET_SCHEDULER_add_delayed (rrs->backoff, &do_reveal_retry, rrs); @@ -545,6 +548,8 @@ do_link_retry (void *cls) struct RefreshLinkState *rls = cls; rls->retry_task = NULL; + rls->is->commands[rls->is->ip].last_req_time + = GNUNET_TIME_absolute_get (); refresh_link_run (rls, NULL, rls->is); @@ -610,6 +615,7 @@ link_cb (void *cls, MAX_BACKOFF); rls->total_backoff = GNUNET_TIME_relative_add (rls->total_backoff, rls->backoff); + rls->is->commands[rls->is->ip].num_tries++; rls->retry_task = GNUNET_SCHEDULER_add_delayed (rls->backoff, &do_link_retry, rls); @@ -853,6 +859,8 @@ do_melt_retry (void *cls) struct RefreshMeltState *rms = cls; rms->retry_task = NULL; + rms->is->commands[rms->is->ip].last_req_time + = GNUNET_TIME_absolute_get (); melt_run (rms, NULL, rms->is); @@ -904,6 +912,7 @@ melt_cb (void *cls, MAX_BACKOFF); rms->total_backoff = GNUNET_TIME_relative_add (rms->total_backoff, rms->backoff); + rms->is->commands[rms->is->ip].num_tries++; rms->retry_task = GNUNET_SCHEDULER_add_delayed (rms->backoff, &do_melt_retry, diff --git a/src/testing/testing_api_cmd_stat.c b/src/testing/testing_api_cmd_stat.c index 3640490ce..cf6d0b484 100644 --- a/src/testing/testing_api_cmd_stat.c +++ b/src/testing/testing_api_cmd_stat.c @@ -79,6 +79,7 @@ stat_cmd (struct TALER_TESTING_Timer *timings, const struct TALER_TESTING_Command *cmd) { struct GNUNET_TIME_Relative duration; + struct GNUNET_TIME_Relative lat; if (cmd->start_time.abs_value_us > cmd->finish_time.abs_value_us) { @@ -87,6 +88,8 @@ stat_cmd (struct TALER_TESTING_Timer *timings, } duration = GNUNET_TIME_absolute_get_difference (cmd->start_time, cmd->finish_time); + lat = GNUNET_TIME_absolute_get_difference (cmd->last_req_time, + cmd->finish_time); for (unsigned int i = 0; NULL != timings[i].prefix; i++) @@ -98,7 +101,11 @@ stat_cmd (struct TALER_TESTING_Timer *timings, timings[i].total_duration = GNUNET_TIME_relative_add (duration, timings[i].total_duration); + timings[i].success_latency + = GNUNET_TIME_relative_add (lat, + timings[i].success_latency); timings[i].num_commands++; + timings[i].num_retries += cmd->num_tries; break; } } diff --git a/src/testing/testing_api_cmd_withdraw.c b/src/testing/testing_api_cmd_withdraw.c index 1ef341e0a..8ecf52011 100644 --- a/src/testing/testing_api_cmd_withdraw.c +++ b/src/testing/testing_api_cmd_withdraw.c @@ -152,6 +152,8 @@ do_retry (void *cls) struct WithdrawState *ws = cls; ws->retry_task = NULL; + ws->is->commands[ws->is->ip].last_req_time + = GNUNET_TIME_absolute_get (); withdraw_run (ws, NULL, ws->is); @@ -208,6 +210,7 @@ reserve_withdraw_cb (void *cls, UNKNOWN_MAX_BACKOFF); ws->total_backoff = GNUNET_TIME_relative_add (ws->total_backoff, ws->backoff); + ws->is->commands[ws->is->ip].num_tries++; ws->retry_task = GNUNET_SCHEDULER_add_delayed (ws->backoff, &do_retry, ws); diff --git a/src/testing/testing_api_loop.c b/src/testing/testing_api_loop.c index 33b5cf077..4e1399174 100644 --- a/src/testing/testing_api_loop.c +++ b/src/testing/testing_api_loop.c @@ -272,7 +272,10 @@ interpreter_run (void *cls) GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "Running command `%s'\n", cmd->label); - cmd->start_time = GNUNET_TIME_absolute_get (); + cmd->start_time + = cmd->last_req_time + = GNUNET_TIME_absolute_get (); + cmd->num_tries = 1; cmd->run (cmd->cls, cmd, is);