more statistics, make explicit table lock optional, can hurt performance badly

doc/prebuilt

@@ -1 +1 @@
-Subproject commit ca53235ccfa0458ebf11c204888ca370e20ec3f5
+Subproject commit 934a6a18301e81c4fd1b3a8cda2dc13dca4741cc

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 (
+             total,
-               timings[i].total_duration,
+             latency,
-               GNUNET_YES),
+             timings[i].num_commands,
-             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",

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,

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;
 };
 
 

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
+TALER_TESTING_cmd_deposit_confirmation_with_retry (
-                                                   cmd)
+  struct TALER_TESTING_Command cmd)
 {
   struct DepositConfirmationState *dcs;
 

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);

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,

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->is->commands[fts->is->ip].num_tries++;
-                            (fts->backoff,
+        fts->retry_task
-                            &do_retry,
+          = GNUNET_SCHEDULER_add_delayed (fts->backoff,
-                            fts);
+                                          &do_retry,
+                                          fts);
         return;
       }
     }

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);

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,

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,

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;
     }
   }

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);

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);