improving benchmarking logic, including more timings

src/benchmark/benchmark.conf

@@ -30,7 +30,7 @@ base_url = "http://localhost:8081/"
 lookahead_sign = 12 h
 
 [auditor]
-BASE_URL = "http://localhost:8085/"
+BASE_URL = "http://localhost:8083/"
 
 [exchangedb-postgres]
 config = "postgres:///talercheck"

src/benchmark/taler-exchange-benchmark.c

@@ -211,6 +211,19 @@ static unsigned int label_off;
  */
 static int linger;
 
+/**
+ * Performance counters.
+ */
+static struct TALER_TESTING_Timer timings[] = {
+  { .prefix = "createreserve" },
+  { .prefix = "withdraw" },
+  { .prefix = "deposit" },
+  { .prefix = "melt" },
+  { .prefix = "reveal" },
+  { .prefix = "link" },
+  { .prefix = NULL }
+};
+
 
 /**
  * Add label to the #labels table and return it.
@@ -304,6 +317,7 @@ run (void *cls,
   (void) cls;
   all_commands = GNUNET_new_array (howmany_reserves * (1     /* Withdraw block */
                                                        + howmany_coins)   /* All units */
+                                   + 1 /* stat CMD */
                                    + 1 /* End CMD */,
                                    struct TALER_TESTING_Command);
   GNUNET_asprintf (&amount_5, "%s:5", currency);
@@ -328,7 +342,7 @@ run (void *cls,
     char *create_reserve_label;
 
     GNUNET_asprintf (&create_reserve_label,
-                     "create-reserve-%u",
+                     "createreserve-%u",
                      j);
     {
       struct TALER_TESTING_Command make_reserve[] = {
@@ -351,24 +365,26 @@ run (void *cls,
       char *order_enc;
       struct TALER_TESTING_Command unit[UNITY_SIZE];
       char *unit_label;
+      const char *wl;
 
       GNUNET_asprintf (&withdraw_label,
                        "withdraw-%u-%u",
                        i,
                        j);
+      wl = add_label (withdraw_label);
       GNUNET_asprintf (&order_enc,
                        "{\"nonce\": %llu}",
                        i + (howmany_coins * j));
       unit[0] =
         TALER_TESTING_cmd_withdraw_with_retry
-          (TALER_TESTING_cmd_withdraw_amount (add_label (withdraw_label),
+          (TALER_TESTING_cmd_withdraw_amount (wl,
                                               create_reserve_label,
                                               amount_5,
                                               MHD_HTTP_OK));
       unit[1] =
         TALER_TESTING_cmd_deposit_with_retry
           (TALER_TESTING_cmd_deposit ("deposit",
-                                      add_label (withdraw_label),
+                                      wl,
                                       0, /* Index of the one withdrawn coin in the traits.  */
                                       user_payto_uri,
                                       add_label (order_enc),
@@ -379,34 +395,35 @@ run (void *cls,
       {
         char *melt_label;
         char *reveal_label;
+        const char *ml;
+        const char *rl;
 
         GNUNET_asprintf (&melt_label,
-                         "refresh-melt-%u-%u",
+                         "melt-%u-%u",
                          i,
                          j);
+        ml = add_label (melt_label);
         GNUNET_asprintf (&reveal_label,
-                         "refresh-reveal-%u-%u",
+                         "reveal-%u-%u",
                          i,
                          j);
+        rl = add_label (reveal_label);
         unit[2] =
           TALER_TESTING_cmd_melt_with_retry
-            (TALER_TESTING_cmd_melt
+            (TALER_TESTING_cmd_melt (ml,
-              (add_label (melt_label),
+                                     wl,
-              withdraw_label,
+                                     MHD_HTTP_OK,
-              MHD_HTTP_OK,
+                                     NULL));
-              NULL));
         unit[3] =
           TALER_TESTING_cmd_refresh_reveal_with_retry
-            (TALER_TESTING_cmd_refresh_reveal
+            (TALER_TESTING_cmd_refresh_reveal (rl,
-              (add_label (reveal_label),
+                                               ml,
-              melt_label,
+                                               MHD_HTTP_OK));
-              MHD_HTTP_OK));
         unit[4] =
           TALER_TESTING_cmd_refresh_link_with_retry
-            (TALER_TESTING_cmd_refresh_link
+            (TALER_TESTING_cmd_refresh_link ("link",
-              ("refresh-link",
+                                             rl,
-              reveal_label,
+                                             MHD_HTTP_OK));
-              MHD_HTTP_OK));
         unit[5] = TALER_TESTING_cmd_end ();
       }
       else
@@ -422,6 +439,8 @@ run (void *cls,
     }
   }
   all_commands[howmany_reserves * (1 + howmany_coins)]
+    = TALER_TESTING_cmd_stat (timings);
+  all_commands[howmany_reserves * (1 + howmany_coins) + 1]
     = TALER_TESTING_cmd_end ();
   TALER_TESTING_run2 (is,
                       all_commands,
@@ -434,6 +453,24 @@ run (void *cls,
 }
 
 
+/**
+ * Print performance statistics for this process.
+ */
+static void
+print_stats (void)
+{
+  for (unsigned int i = 0; NULL != timings[i].prefix; i++)
+    fprintf (stderr,
+             "%s-%d took %s in total for %u executions\n",
+             timings[i].prefix,
+             (int) getpid (),
+             GNUNET_STRINGS_relative_time_to_string (
+               timings[i].total_duration,
+               GNUNET_YES),
+             timings[i].num_commands);
+}
+
+
 /**
  * Stop the fakebank.
  *
@@ -712,53 +749,68 @@ parallel_benchmark (TALER_TESTING_Main main_cb,
   }
   if ( (MODE_CLIENT == mode) || (MODE_BOTH == mode) )
   {
-    sleep (1); /* make sure fakebank process is ready before continuing */
+    if (-1 != fakebank)
+      sleep (1); /* make sure fakebank process is ready before continuing */
 
     start_time = GNUNET_TIME_absolute_get ();
     result = GNUNET_OK;
-    for (unsigned int i = 0; i<howmany_clients; i++)
-    {
-      if (0 == (cpids[i] = fork ()))
-      {
-        /* I am the child, do the work! */
-        GNUNET_log_setup ("benchmark-worker",
-                          NULL == loglev ? "INFO" : loglev,
-                          logfile);
 
-        result = TALER_TESTING_setup (main_cb,
+    if (1 == howmany_clients)
-                                      main_cb_cls,
-                                      cfg,
-                                      exchanged,
-                                      GNUNET_YES);
-        if (GNUNET_OK != result)
-          GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
-                      "Failure in child process test suite!\n");
-        if (GNUNET_OK == result)
-          exit (0);
-        else
-          exit (1);
-      }
-      if (-1 == cpids[i])
-      {
-        GNUNET_log_strerror (GNUNET_ERROR_TYPE_ERROR,
-                             "fork");
-        howmany_clients = i;
-        result = GNUNET_SYSERR;
-        break;
-      }
-      /* fork() success, continue starting more processes! */
-    }
-    /* collect all children */
-    for (unsigned int i = 0; i<howmany_clients; i++)
     {
-      waitpid (cpids[i],
+      result = TALER_TESTING_setup (main_cb,
-               &wstatus,
+                                    main_cb_cls,
-               0);
+                                    cfg,
-      if ( (! WIFEXITED (wstatus)) ||
+                                    exchanged,
-           (0 != WEXITSTATUS (wstatus)) )
+                                    GNUNET_YES);
+      print_stats ();
+    }
+    else
+    {
+      for (unsigned int i = 0; i<howmany_clients; i++)
       {
-        GNUNET_break (0);
+        if (0 == (cpids[i] = fork ()))
-        result = GNUNET_SYSERR;
+        {
+          /* I am the child, do the work! */
+          GNUNET_log_setup ("benchmark-worker",
+                            NULL == loglev ? "INFO" : loglev,
+                            logfile);
+
+          result = TALER_TESTING_setup (main_cb,
+                                        main_cb_cls,
+                                        cfg,
+                                        exchanged,
+                                        GNUNET_YES);
+          print_stats ();
+          if (GNUNET_OK != result)
+            GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
+                        "Failure in child process test suite!\n");
+          if (GNUNET_OK == result)
+            exit (0);
+          else
+            exit (1);
+        }
+        if (-1 == cpids[i])
+        {
+          GNUNET_log_strerror (GNUNET_ERROR_TYPE_ERROR,
+                               "fork");
+          howmany_clients = i;
+          result = GNUNET_SYSERR;
+          break;
+        }
+        /* fork() success, continue starting more processes! */
+      }
+      /* collect all children */
+      for (unsigned int i = 0; i<howmany_clients; i++)
+      {
+        waitpid (cpids[i],
+                 &wstatus,
+                 0);
+        if ( (! WIFEXITED (wstatus)) ||
+             (0 != WEXITSTATUS (wstatus)) )
+        {
+          GNUNET_break (0);
+          result = GNUNET_SYSERR;
+        }
       }
     }
   }

src/include/taler_error_codes.h

@@ -388,6 +388,13 @@ enum TALER_ErrorCode
    */
   TALER_EC_WITHDRAW_RESERVE_BALANCE_CORRUPT = 1117,
 
+  /**
+   * The exchange responded with a reply that did not satsify the
+   * protocol. This error is not used in the protocol but created
+   * client-side.
+   */
+  TALER_EC_WITHDRAW_REPLY_MALFORMED = 1118,
+
   /**
    * The exchange failed to obtain the transaction history of the given
    * reserve from the database. This response is provided with HTTP
@@ -401,6 +408,13 @@ enum TALER_ErrorCode
    */
   TALER_EC_RESERVE_STATUS_UNKNOWN = 1151,
 
+  /**
+   * The exchange responded with a reply that did not satsify the
+   * protocol. This error is not used in the protocol but created
+   * client-side.
+   */
+  TALER_EC_RESERVE_STATUS_REPLY_MALFORMED = 1152,
+
   /**
    * The respective coin did not have sufficient residual value for the
    * /deposit operation (i.e. due to double spending). The "history" in
@@ -752,12 +766,26 @@ enum TALER_ErrorCode
    */
   TALER_EC_REFRESHES_INVALID_RCH = 1384,
 
+  /**
+   * The exchange responded with a reply that did not satsify the
+   * protocol. This error is not used in the protocol but created
+   * client-side.
+   */
+  TALER_EC_REFRESH_REVEAL_REPLY_MALFORMED = 1385,
+
   /**
    * The coin specified in the link request is unknown to the exchange.
    * This response is provided with HTTP status code MHD_HTTP_NOT_FOUND.
    */
   TALER_EC_REFRESH_LINK_COIN_UNKNOWN = 1400,
 
+  /**
+   * The exchange responded with a reply that did not satsify the
+   * protocol. This error is not used in the protocol but created
+   * client-side.
+   */
+  TALER_EC_REFRESH_LINK_REPLY_MALFORMED = 1401,
+
   /**
    * The exchange knows literally nothing about the coin we were asked
    * to refund. But without a transaction history, we cannot issue a
@@ -928,6 +956,13 @@ enum TALER_ErrorCode
    */
   TALER_EC_TRACK_TRANSFER_WIRE_FEE_INCONSISTENT = 1704,
 
+  /**
+   * The exchange responded with a reply that did not satsify the
+   * protocol. This error is not used in the protocol but created
+   * client-side.
+   */
+  TALER_EC_TRACK_TRANSFER_REPLY_MALFORMED = 1705,
+
   /**
    * The exchange found internally inconsistent fee data when resolving
    * a transaction in the database.  This response is provided with HTTP
@@ -1039,6 +1074,13 @@ enum TALER_ErrorCode
    */
   TALER_EC_RECOUP_DENOMINATION_VALIDITY_IN_FUTURE = 1860,
 
+  /**
+   * The exchange responded with a reply that did not satsify the
+   * protocol. This error is not used in the protocol but created
+   * client-side.
+   */
+  TALER_EC_RECOUP_REPLY_MALFORMED = 1861,
+
   /**
    * The "have" parameter was not a natural number. This reponse is
    * provied with an HTTP status code of MHD_HTTP_BAD_REQUEST.
@@ -1732,6 +1774,13 @@ enum TALER_ErrorCode
    */
   TALER_EC_AUDITOR_EXCHANGE_STORE_DB_ERROR = 3003,
 
+  /**
+   * The auditor (!) responded with a reply that did not satsify the
+   * protocol. This error is not used in the protocol but created
+   * client-side.
+   */
+  TALER_EC_AUDITOR_EXCHANGES_REPLY_MALFORMED = 3004,
+
   /**
    * The exchange failed to compute ECDH.  This response is provided
    * with HTTP status code MHD_HTTP_INTERNAL_SERVER_ERROR.

src/include/taler_testing_lib.h

@@ -495,6 +495,16 @@ struct TALER_TESTING_Command
             const char *trait,
             unsigned int index);
 
+  /**
+   * When did the execution of this command start?
+   */
+  struct GNUNET_TIME_Absolute start_time;
+
+  /**
+   * When did the execution of this command finish?
+   */
+  struct GNUNET_TIME_Absolute finish_time;
+
 };
 
 
@@ -1822,6 +1832,39 @@ TALER_TESTING_cmd_insert_deposit (const char *label,
                                   const char *amount_with_fee,
                                   const char *deposit_fee);
 
+
+/**
+ * Performance counter.
+ */
+struct TALER_TESTING_Timer
+{
+  /**
+   * For which type of commands.
+   */
+  const char *prefix;
+
+  /**
+   * Total time spend in all commands of this type.
+   */
+  struct GNUNET_TIME_Relative total_duration;
+
+  /**
+   * Number of commands summed up.
+   */
+  unsigned int num_commands;
+};
+
+
+/**
+ * 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);
+
+
 /* *** Generic trait logic for implementing traits ********* */
 
 /**

src/json/json.c

@@ -73,7 +73,6 @@ TALER_JSON_get_error_code (const json_t *json)
 
   if (NULL == json)
   {
-    abort ();
     GNUNET_break_op (0);
     return TALER_EC_INVALID_RESPONSE;
   }

src/lib/auditor_api_exchanges.c

@@ -89,11 +89,13 @@ handle_exchanges_finished (void *cls,
   const json_t *ja;
   unsigned int ja_len;
   struct TALER_AUDITOR_ListExchangesHandle *leh = cls;
+  enum TALER_ErrorCode ec;
 
   leh->job = NULL;
   switch (response_code)
   {
   case 0:
+    ec = TALER_EC_INVALID_RESPONSE;
     break;
   case MHD_HTTP_OK:
     ja = json_object_get (json,
@@ -102,6 +104,7 @@ handle_exchanges_finished (void *cls,
          (! json_is_array (ja)) )
     {
       GNUNET_break (0);
+      ec = TALER_EC_AUDITOR_EXCHANGES_REPLY_MALFORMED;
       response_code = 0;
       break;
     }
@@ -110,6 +113,7 @@ handle_exchanges_finished (void *cls,
     if (ja_len > MAX_EXCHANGES)
     {
       GNUNET_break (0);
+      ec = TALER_EC_AUDITOR_EXCHANGES_REPLY_MALFORMED;
       response_code = 0;
       break;
     }
@@ -134,6 +138,7 @@ handle_exchanges_finished (void *cls,
         {
           GNUNET_break_op (0);
           ok = GNUNET_NO;
+          ec = TALER_EC_AUDITOR_EXCHANGES_REPLY_MALFORMED;
           break;
         }
       }
@@ -145,26 +150,31 @@ handle_exchanges_finished (void *cls,
                ja_len,
                ei,
                json);
-      leh->cb = NULL;
+      TALER_AUDITOR_list_exchanges_cancel (leh);
+      return;
     }
-    break;
   case MHD_HTTP_BAD_REQUEST:
     /* This should never happen, either us or the auditor is buggy
        (or API version conflict); just pass JSON reply to the application */
+    ec = TALER_JSON_get_error_code (json);
     break;
   case MHD_HTTP_NOT_FOUND:
     /* Nothing really to verify, this should never
        happen, we should pass the JSON reply to the application */
+    ec = TALER_JSON_get_error_code (json);
     break;
   case MHD_HTTP_INTERNAL_SERVER_ERROR:
     /* Server had an internal issue; we should retry, but this API
        leaves this to the application */
+    ec = TALER_JSON_get_error_code (json);
     break;
   default:
     /* unexpected response code */
+    ec = TALER_JSON_get_error_code (json);
     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
-                "Unexpected response code %u\n",
+                "Unexpected response code %u/%d\n",
-                (unsigned int) response_code);
+                (unsigned int) response_code,
+                (int) ec);
     GNUNET_break (0);
     response_code = 0;
     break;

src/lib/exchange_api_deposit.c

@@ -38,10 +38,10 @@
  * 1:#AUDITOR_CHANCE is the probability that we report deposits
  * to the auditor.
  *
- * 2==50% of going to auditor. This is way too high, but set
+ * 20==5% of going to auditor. This is possibly still too high, but set
  * deliberately this high for testing
  */
-#define AUDITOR_CHANCE 2
+#define AUDITOR_CHANCE 20
 
 /**
  * @brief A Deposit Handle

src/lib/exchange_api_link.c

@@ -365,8 +365,12 @@ handle_link_finished (void *cls,
     {
       GNUNET_break_op (0);
       response_code = 0;
+      ec = TALER_EC_REFRESH_LINK_REPLY_MALFORMED;
+      break;
     }
-    break;
+    GNUNET_assert (NULL == lh->link_cb);
+    TALER_EXCHANGE_link_cancel (lh);
+    return;
   case MHD_HTTP_BAD_REQUEST:
     ec = TALER_JSON_get_error_code (j);
     /* This should never happen, either us or the exchange is buggy

src/lib/exchange_api_melt.c

@@ -304,9 +304,9 @@ handle_melt_finished (void *cls,
     }
     break;
   case MHD_HTTP_BAD_REQUEST:
-    ec = TALER_JSON_get_error_code (j);
     /* This should never happen, either us or the exchange is buggy
        (or API version conflict); just pass JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_CONFLICT:
     /* Double spending; check signatures on transaction history */
@@ -322,20 +322,20 @@ handle_melt_finished (void *cls,
       ec = TALER_EC_NONE;
     break;
   case MHD_HTTP_FORBIDDEN:
-    ec = TALER_JSON_get_error_code (j);
     /* Nothing really to verify, exchange says one of the signatures is
        invalid; assuming we checked them, this should never happen, we
        should pass the JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_NOT_FOUND:
-    ec = TALER_JSON_get_error_code (j);
     /* Nothing really to verify, this should never
        happen, we should pass the JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_INTERNAL_SERVER_ERROR:
-    ec = TALER_JSON_get_error_code (j);
     /* Server had an internal issue; we should retry, but this API
        leaves this to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   default:
     /* unexpected response code */

src/lib/exchange_api_recoup.c

@@ -206,18 +206,22 @@ handle_recoup_finished (void *cls,
 {
   struct TALER_EXCHANGE_RecoupHandle *ph = cls;
   const json_t *j = response;
+  enum TALER_ErrorCode ec;
 
   ph->job = NULL;
   switch (response_code)
   {
   case 0:
+    ec = TALER_EC_INVALID_RESPONSE;
     break;
   case MHD_HTTP_OK:
+    ec = TALER_EC_NONE;
     if (GNUNET_OK !=
         verify_recoup_signature_ok (ph,
                                     j))
     {
       GNUNET_break_op (0);
+      ec = TALER_EC_RECOUP_REPLY_MALFORMED;
       response_code = 0;
       break;
     }
@@ -226,6 +230,7 @@ handle_recoup_finished (void *cls,
   case MHD_HTTP_BAD_REQUEST:
     /* This should never happen, either us or the exchange is buggy
        (or API version conflict); just pass JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_CONFLICT:
     {
@@ -247,9 +252,10 @@ handle_recoup_finished (void *cls,
         GNUNET_break_op (0);
         response_code = 0;
       }
+      ec = TALER_JSON_get_error_code (j);
       ph->cb (ph->cb_cls,
               response_code,
-              TALER_JSON_get_error_code (j),
+              ec,
               &total,
               GNUNET_TIME_UNIT_FOREVER_ABS,
               NULL,
@@ -262,21 +268,26 @@ handle_recoup_finished (void *cls,
     /* Nothing really to verify, exchange says one of the signatures is
        invalid; as we checked them, this should never happen, we
        should pass the JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_NOT_FOUND:
     /* Nothing really to verify, this should never
        happen, we should pass the JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_GONE:
     /* Kind of normal: the money was already sent to the merchant
        (it was too late for the refund). */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_INTERNAL_SERVER_ERROR:
     /* Server had an internal issue; we should retry, but this API
        leaves this to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   default:
     /* unexpected response code */
+    ec = TALER_JSON_get_error_code (j);
     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
                 "Unexpected response code %u\n",
                 (unsigned int) response_code);
@@ -286,7 +297,7 @@ handle_recoup_finished (void *cls,
   }
   ph->cb (ph->cb_cls,
           response_code,
-          TALER_JSON_get_error_code (j),
+          ec,
           NULL,
           GNUNET_TIME_UNIT_FOREVER_ABS,
           NULL,

src/lib/exchange_api_refreshes_reveal.c

@@ -202,11 +202,13 @@ handle_refresh_reveal_finished (void *cls,
 {
   struct TALER_EXCHANGE_RefreshesRevealHandle *rrh = cls;
   const json_t *j = response;
+  enum TALER_ErrorCode ec;
 
   rrh->job = NULL;
   switch (response_code)
   {
   case 0:
+    ec = TALER_EC_INVALID_RESPONSE;
     break;
   case MHD_HTTP_OK:
     {
@@ -220,12 +222,14 @@ handle_refresh_reveal_finished (void *cls,
       if (GNUNET_OK != ret)
       {
         response_code = 0;
+        ec = TALER_EC_REFRESH_REVEAL_REPLY_MALFORMED;
       }
       else
       {
+        ec = TALER_EC_NONE;
         rrh->reveal_cb (rrh->reveal_cb_cls,
                         MHD_HTTP_OK,
-                        TALER_EC_NONE,
+                        ec,
                         rrh->md->num_fresh_coins,
                         rrh->md->fresh_coins[rrh->noreveal_index],
                         sigs,
@@ -235,20 +239,23 @@ handle_refresh_reveal_finished (void *cls,
       for (unsigned int i = 0; i<rrh->md->num_fresh_coins; i++)
         if (NULL != sigs[i].rsa_signature)
           GNUNET_CRYPTO_rsa_signature_free (sigs[i].rsa_signature);
+      return;
     }
-    break;
   case MHD_HTTP_BAD_REQUEST:
     /* This should never happen, either us or the exchange is buggy
        (or API version conflict); just pass JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_CONFLICT:
     /* Nothing really to verify, exchange says our reveal is inconsitent
        with our commitment, so either side is buggy; we
        should pass the JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_INTERNAL_SERVER_ERROR:
     /* Server had an internal issue; we should retry, but this API
        leaves this to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   default:
     /* unexpected response code */
@@ -257,12 +264,13 @@ handle_refresh_reveal_finished (void *cls,
                 (unsigned int) response_code);
     GNUNET_break (0);
     response_code = 0;
+    ec = TALER_JSON_get_error_code (j);
     break;
   }
   if (NULL != rrh->reveal_cb)
     rrh->reveal_cb (rrh->reveal_cb_cls,
                     response_code,
-                    TALER_JSON_get_error_code (j),
+                    ec,
                     0,
                     NULL,
                     NULL,

src/lib/exchange_api_reserves_get.c

@@ -171,32 +171,42 @@ handle_reserves_get_finished (void *cls,
 {
   struct TALER_EXCHANGE_ReservesGetHandle *rgh = cls;
   const json_t *j = response;
+  enum TALER_ErrorCode ec;
 
   rgh->job = NULL;
   switch (response_code)
   {
   case 0:
+    ec = TALER_EC_INVALID_RESPONSE;
     break;
   case MHD_HTTP_OK:
+    ec = TALER_EC_NONE;
     if (GNUNET_OK !=
         handle_reserves_get_ok (rgh,
                                 j))
+    {
       response_code = 0;
+      ec = TALER_EC_RESERVE_STATUS_REPLY_MALFORMED;
+    }
     break;
   case MHD_HTTP_BAD_REQUEST:
     /* This should never happen, either us or the exchange is buggy
        (or API version conflict); just pass JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_NOT_FOUND:
     /* Nothing really to verify, this should never
        happen, we should pass the JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_INTERNAL_SERVER_ERROR:
     /* Server had an internal issue; we should retry, but this API
        leaves this to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   default:
     /* unexpected response code */
+    ec = TALER_JSON_get_error_code (j);
     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
                 "Unexpected response code %u\n",
                 (unsigned int) response_code);
@@ -208,7 +218,7 @@ handle_reserves_get_finished (void *cls,
   {
     rgh->cb (rgh->cb_cls,
              response_code,
-             TALER_JSON_get_error_code (j),
+             ec,
              j,
              NULL,
              0, NULL);

src/lib/exchange_api_transfers_get.c

@@ -261,11 +261,13 @@ handle_transfers_get_finished (void *cls,
 {
   struct TALER_EXCHANGE_TransfersGetHandle *wdh = cls;
   const json_t *j = response;
+  enum TALER_ErrorCode ec;
 
   wdh->job = NULL;
   switch (response_code)
   {
   case 0:
+    ec = TALER_EC_INVALID_RESPONSE;
     break;
   case MHD_HTTP_OK:
     if (GNUNET_OK ==
@@ -273,27 +275,33 @@ handle_transfers_get_finished (void *cls,
                                          j))
       return;
     GNUNET_break_op (0);
+    ec = TALER_EC_TRACK_TRANSFER_REPLY_MALFORMED;
     response_code = 0;
     break;
   case MHD_HTTP_BAD_REQUEST:
     /* This should never happen, either us or the exchange is buggy
        (or API version conflict); just pass JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_FORBIDDEN:
     /* Nothing really to verify, exchange says one of the signatures is
        invalid; as we checked them, this should never happen, we
        should pass the JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_NOT_FOUND:
     /* Exchange does not know about transaction;
        we should pass the reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_INTERNAL_SERVER_ERROR:
     /* Server had an internal issue; we should retry, but this API
        leaves this to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   default:
     /* unexpected response code */
+    ec = TALER_JSON_get_error_code (j);
     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
                 "Unexpected response code %u\n",
                 (unsigned int) response_code);
@@ -303,7 +311,7 @@ handle_transfers_get_finished (void *cls,
   }
   wdh->cb (wdh->cb_cls,
            response_code,
-           TALER_JSON_get_error_code (j),
+           ec,
            NULL,
            j,
            NULL,

src/lib/exchange_api_wire.c

@@ -213,10 +213,10 @@ handle_wire_finished (void *cls,
 
   TALER_LOG_DEBUG ("Checking raw /wire response\n");
   wh->job = NULL;
-  ec = TALER_EC_NONE;
   switch (response_code)
   {
   case 0:
+    ec = TALER_EC_INVALID_RESPONSE;
     break;
   case MHD_HTTP_OK:
     {
@@ -261,6 +261,7 @@ handle_wire_finished (void *cls,
         break;
       }
 
+      ec = TALER_EC_NONE;
       key_state = TALER_EXCHANGE_get_keys (wh->exchange);
       /* parse accounts */
       {
@@ -325,7 +326,7 @@ handle_wire_finished (void *cls,
         {
           wh->cb (wh->cb_cls,
                   response_code,
-                  TALER_EC_NONE,
+                  ec,
                   num_accounts,
                   was);
           wh->cb = NULL;
@@ -338,20 +339,25 @@ handle_wire_finished (void *cls,
   case MHD_HTTP_BAD_REQUEST:
     /* This should never happen, either us or the exchange is buggy
        (or API version conflict); just pass JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_NOT_FOUND:
     /* Nothing really to verify, this should never
        happen, we should pass the JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_INTERNAL_SERVER_ERROR:
     /* Server had an internal issue; we should retry, but this API
        leaves this to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   default:
     /* unexpected response code */
+    ec = TALER_JSON_get_error_code (j);
     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
-                "Unexpected response code %u\n",
+                "Unexpected response code %u/%d\n",
-                (unsigned int) response_code);
+                (unsigned int) response_code,
+                (int) ec);
     GNUNET_break (0);
     response_code = 0;
     break;
@@ -359,7 +365,7 @@ handle_wire_finished (void *cls,
   if (NULL != wh->cb)
     wh->cb (wh->cb_cls,
             response_code,
-            (0 == response_code) ? ec : TALER_JSON_get_error_code (j),
+            ec,
             0,
             NULL);
   TALER_EXCHANGE_wire_cancel (wh);

src/lib/exchange_api_withdraw.c

@@ -277,11 +277,13 @@ handle_reserve_withdraw_finished (void *cls,
 {
   struct TALER_EXCHANGE_WithdrawHandle *wh = cls;
   const json_t *j = response;
+  enum TALER_ErrorCode ec;
 
   wh->job = NULL;
   switch (response_code)
   {
   case 0:
+    ec = TALER_EC_INVALID_RESPONSE;
     break;
   case MHD_HTTP_OK:
     if (GNUNET_OK !=
@@ -290,11 +292,16 @@ handle_reserve_withdraw_finished (void *cls,
     {
       GNUNET_break_op (0);
       response_code = 0;
+      ec = TALER_EC_WITHDRAW_REPLY_MALFORMED;
+      break;
     }
-    break;
+    GNUNET_assert (NULL == wh->cb);
+    TALER_EXCHANGE_withdraw_cancel (wh);
+    return;
   case MHD_HTTP_BAD_REQUEST:
     /* This should never happen, either us or the exchange is buggy
        (or API version conflict); just pass JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_CONFLICT:
     /* The exchange says that the reserve has insufficient funds;
@@ -305,6 +312,11 @@ handle_reserve_withdraw_finished (void *cls,
     {
       GNUNET_break_op (0);
       response_code = 0;
+      ec = TALER_EC_WITHDRAW_REPLY_MALFORMED;
+    }
+    else
+    {
+      ec = TALER_JSON_get_error_code (j);
     }
     break;
   case MHD_HTTP_FORBIDDEN:
@@ -312,22 +324,27 @@ handle_reserve_withdraw_finished (void *cls,
     /* Nothing really to verify, exchange says one of the signatures is
        invalid; as we checked them, this should never happen, we
        should pass the JSON reply to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_NOT_FOUND:
     /* Nothing really to verify, the exchange basically just says
        that it doesn't know this reserve.  Can happen if we
        query before the wire transfer went through.
        We should simply pass the JSON reply to the application. */
+    ec = TALER_JSON_get_error_code (j);
     break;
   case MHD_HTTP_INTERNAL_SERVER_ERROR:
     /* Server had an internal issue; we should retry, but this API
        leaves this to the application */
+    ec = TALER_JSON_get_error_code (j);
     break;
   default:
     /* unexpected response code */
+    ec = TALER_JSON_get_error_code (j);
     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
-                "Unexpected response code %u\n",
+                "Unexpected response code %u/%d\n",
-                (unsigned int) response_code);
+                (unsigned int) response_code,
+                (int) ec);
     GNUNET_break (0);
     response_code = 0;
     break;
@@ -336,7 +353,7 @@ handle_reserve_withdraw_finished (void *cls,
   {
     wh->cb (wh->cb_cls,
             response_code,
-            TALER_JSON_get_error_code (j),
+            ec,
             NULL,
             j);
     wh->cb = NULL;

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 \

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

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

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,

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

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

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",

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
+  <http://www.gnu.org/licenses/>
+*/
+/**
+ * @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 <gnunet/gnunet_curl_lib.h>
+#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  */

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 */

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