From b3e4159c2e5048a2d2c87b6d158aad54b0d975e0 Mon Sep 17 00:00:00 2001
From: Christian Grothoff <christian@grothoff.org>
Date: Thu, 2 Dec 2021 14:11:14 +0100
Subject: more perf debug messages

---
 src/exchange/taler-exchange-httpd_refreshes_reveal.c |  8 ++++++++
 src/util/taler-exchange-secmod-rsa.c                 | 20 +++++++++++++++++++-
 2 files changed, 27 insertions(+), 1 deletion(-)

(limited to 'src')

diff --git a/src/exchange/taler-exchange-httpd_refreshes_reveal.c b/src/exchange/taler-exchange-httpd_refreshes_reveal.c
index 4ec703136..4631a2b92 100644
--- a/src/exchange/taler-exchange-httpd_refreshes_reveal.c
+++ b/src/exchange/taler-exchange-httpd_refreshes_reveal.c
@@ -271,6 +271,7 @@ refreshes_reveal_transaction (void *cls,
 
   /* Obtain basic information about the refresh operation and what
      gamma we committed to. */
+  // FIXME: why do we do 'get_melt' twice?
   qs = TEH_plugin->get_melt (TEH_plugin->cls,
                              &rctx->rc,
                              &melt);
@@ -611,6 +612,7 @@ resolve_refreshes_reveal_denominations (struct MHD_Connection *connection,
   {
     enum GNUNET_DB_QueryStatus qs;
 
+    // FIXME: why do we do 'get_melt' twice?
     if (GNUNET_DB_STATUS_SUCCESS_ONE_RESULT !=
         (qs = TEH_plugin->get_melt (TEH_plugin->cls,
                                     &rctx->rc,
@@ -682,9 +684,13 @@ resolve_refreshes_reveal_denominations (struct MHD_Connection *connection,
   rctx->dks = dks;
   rctx->link_sigs = link_sigs;
 
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Optimistically creating %u signatures\n",
+              (unsigned int) rctx->num_fresh_coins);
   /* sign _early_ (optimistic!) to keep out of transaction scope! */
   rctx->ev_sigs = GNUNET_new_array (rctx->num_fresh_coins,
                                     struct TALER_BlindedDenominationSignature);
+  // FIXME: this is sequential, modify logic to enable parallel signing!
   for (unsigned int i = 0; i<rctx->num_fresh_coins; i++)
   {
     enum TALER_ErrorCode ec = TALER_EC_NONE;
@@ -705,6 +711,8 @@ resolve_refreshes_reveal_denominations (struct MHD_Connection *connection,
     }
   }
 
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Signatures ready, starting DB interaction\n");
   /* We try the three transactions a few times, as theoretically
      the pre-check might be satisfied by a concurrent transaction
      voiding our final commit due to uniqueness violation; naturally,
diff --git a/src/util/taler-exchange-secmod-rsa.c b/src/util/taler-exchange-secmod-rsa.c
index 5fd6049a7..54cf3d9a5 100644
--- a/src/util/taler-exchange-secmod-rsa.c
+++ b/src/util/taler-exchange-secmod-rsa.c
@@ -251,6 +251,7 @@ notify_client_dk_add (struct TES_Client *client,
   GNUNET_assert (nlen < UINT16_MAX);
   tlen = buf_len + nlen + sizeof (*an);
   GNUNET_assert (tlen < UINT16_MAX);
+  // FIXME: do not re-calculate this message for every client!
   an = GNUNET_malloc (tlen);
   an->header.size = htons ((uint16_t) tlen);
   an->header.type = htons (TALER_HELPER_RSA_MT_AVAIL);
@@ -342,6 +343,7 @@ handle_sign_request (struct TES_Client *client,
   const void *blinded_msg = &sr[1];
   size_t blinded_msg_size = ntohs (sr->header.size) - sizeof (*sr);
   struct GNUNET_CRYPTO_RsaSignature *rsa_signature;
+  struct GNUNET_TIME_Absolute now = GNUNET_TIME_absolute_get ();
 
   GNUNET_assert (0 == pthread_mutex_lock (&keys_lock));
   dk = GNUNET_CONTAINER_multihashmap_get (keys,
@@ -427,7 +429,10 @@ handle_sign_request (struct TES_Client *client,
             buf_size);
     GNUNET_free (buf);
     GNUNET_log (GNUNET_ERROR_TYPE_INFO,
-                "Sending RSA signature\n");
+                "Sending RSA signature after %s\n",
+                GNUNET_STRINGS_relative_time_to_string (
+                  GNUENT_TIME_absolute_get_duration (now)),
+                GNUNET_YES);
     ret = TES_transmit (client->csock,
                         &sr->header);
     GNUNET_free (sr);
@@ -660,6 +665,9 @@ rsa_work_dispatch (struct TES_Client *client,
 static enum GNUNET_GenericReturnValue
 rsa_client_init (struct TES_Client *client)
 {
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Initializing new client %p\n",
+              client);
   GNUNET_assert (0 == pthread_mutex_lock (&keys_lock));
   for (struct Denomination *denom = denom_head;
        NULL != denom;
@@ -669,6 +677,9 @@ rsa_client_init (struct TES_Client *client)
          NULL != dk;
          dk = dk->next)
     {
+      // FIXME: avoid holding keys_lock while
+      // doing the IPC with client and the signing!
+      // => lock contention candidate!
       if (GNUNET_OK !=
           notify_client_dk_add (client,
                                 dk))
@@ -737,6 +748,9 @@ rsa_update_client_keys (struct TES_Client *client)
       }
       else
       {
+        // FIXME: avoid holding keys_lock while
+        // doing the IPC with client and the signing!
+        // => lock contention candidate!
         if (GNUNET_OK !=
             notify_client_dk_add (client,
                                   key))
@@ -943,6 +957,8 @@ update_denominations (void *cls)
   keygen_task = NULL;
   now = GNUNET_TIME_absolute_get ();
   (void) GNUNET_TIME_round_abs (&now);
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Updating denominations ...\n");
   GNUNET_assert (0 == pthread_mutex_lock (&keys_lock));
   do {
     denom = denom_head;
@@ -953,6 +969,8 @@ update_denominations (void *cls)
       return;
   } while (denom != denom_head);
   GNUNET_assert (0 == pthread_mutex_unlock (&keys_lock));
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Updating denominations finished ...\n");
   if (wake)
     TES_wake_clients ();
   keygen_task = GNUNET_SCHEDULER_add_at (denomination_action_time (denom),
-- 
cgit v1.2.3