metrics: Add HS service side circuit build time metrics.

This adds 2 histogram metrics for hidden services:
* `tor_hs_rend_circ_build_time` - the rendezvous circuit build time in milliseconds
* `tor_hs_intro_circ_build_time` - the introduction circuit build time in milliseconds

The text representation representation of the new metrics looks like this:
```
# HELP tor_hs_rend_circ_build_time The rendezvous circuit build time in milliseconds
# TYPE tor_hs_rend_circ_build_time histogram
tor_hs_rend_circ_build_time_bucket{onion="<elided>",le="1000.00"} 2
tor_hs_rend_circ_build_time_bucket{onion="<elided>",le="5000.00"} 10
tor_hs_rend_circ_build_time_bucket{onion="<elided>",le="10000.00"} 10
tor_hs_rend_circ_build_time_bucket{onion="<elided>",le="30000.00"} 10
tor_hs_rend_circ_build_time_bucket{onion="<elided>",le="60000.00"} 10
tor_hs_rend_circ_build_time_bucket{onion="<elided>",le="+Inf"} 10
tor_hs_rend_circ_build_time_sum{onion="<elided>"} 10824
tor_hs_rend_circ_build_time_count{onion="<elided>"} 10
# HELP tor_hs_intro_circ_build_time The introduction circuit build time in milliseconds
# TYPE tor_hs_intro_circ_build_time histogram
tor_hs_intro_circ_build_time_bucket{onion="<elided>",le="1000.00"} 0
tor_hs_intro_circ_build_time_bucket{onion="<elided>",le="5000.00"} 6
tor_hs_intro_circ_build_time_bucket{onion="<elided>",le="10000.00"} 6
tor_hs_intro_circ_build_time_bucket{onion="<elided>",le="30000.00"} 6
tor_hs_intro_circ_build_time_bucket{onion="<elided>",le="60000.00"} 6
tor_hs_intro_circ_build_time_bucket{onion="<elided>",le="+Inf"} 6
tor_hs_intro_circ_build_time_sum{onion="<elided>"} 9843
tor_hs_intro_circ_build_time_count{onion="<elided>"} 6
```

Signed-off-by: Gabriela Moldovan <gabi@torproject.org>

changes/ticket40757

@@ -1,3 +1,8 @@
   o Minor features (metrics):
     - Add support for histograms.
       Part of ticket 40757.
+  o Minor features (hs, metrics):
+    - Add tor_hs_rend_circ_build_time and tor_hs_intro_circ_build_time
+      histograms to measure hidden service rend/intro circuit build time
+      durations.
+      Part of ticket 40757.

src/feature/hs/hs_metrics.c

@@ -68,6 +68,8 @@ add_metric_with_labels(hs_service_t *service, hs_metrics_key_t metric,
     case HS_METRICS_NUM_ESTABLISHED_RDV: FALLTHROUGH;
     case HS_METRICS_NUM_RDV: FALLTHROUGH;
     case HS_METRICS_NUM_ESTABLISHED_INTRO: FALLTHROUGH;
+    case HS_METRICS_INTRO_CIRC_BUILD_TIME: FALLTHROUGH;
+    case HS_METRICS_REND_CIRC_BUILD_TIME: FALLTHROUGH;
     default:
       break;
   }
@@ -144,7 +146,7 @@ void
 hs_metrics_update_by_service(const hs_metrics_key_t key,
                              const hs_service_t *service,
                              uint16_t port, const char *reason,
-                             int64_t n)
+                             int64_t n, int64_t obs)
 {
   tor_assert(service);
 
@@ -165,7 +167,13 @@ hs_metrics_update_by_service(const hs_metrics_key_t key,
              entry, metrics_format_label("port", port_to_str(port)))) &&
         ((!reason || metrics_store_entry_has_label(
                          entry, metrics_format_label("reason", reason))))) {
+
+      if (metrics_store_entry_is_histogram(entry)) {
+        metrics_store_hist_entry_update(entry, n, obs);
+      } else {
         metrics_store_entry_update(entry, n);
+      }
+
       break;
     }
   } SMARTLIST_FOREACH_END(entry);
@@ -182,7 +190,7 @@ void
 hs_metrics_update_by_ident(const hs_metrics_key_t key,
                            const ed25519_public_key_t *ident_pk,
                            const uint16_t port, const char *reason,
-                           int64_t n)
+                           int64_t n, int64_t obs)
 {
   hs_service_t *service;
 
@@ -196,7 +204,7 @@ hs_metrics_update_by_ident(const hs_metrics_key_t key,
      * service and thus the only way to know is to lookup the service. */
     return;
   }
-  hs_metrics_update_by_service(key, service, port, reason, n);
+  hs_metrics_update_by_service(key, service, port, reason, n, obs);
 }
 
 /** Return a list of all the onion service metrics stores. This is the

src/feature/hs/hs_metrics.h

@@ -27,58 +27,75 @@ const smartlist_t *hs_metrics_get_stores(void);
 void hs_metrics_update_by_ident(const hs_metrics_key_t key,
                                 const ed25519_public_key_t *ident_pk,
                                 const uint16_t port, const char *reason,
-                                int64_t n);
+                                int64_t n, int64_t obs);
 void hs_metrics_update_by_service(const hs_metrics_key_t key,
                                   const hs_service_t *service,
                                   uint16_t port, const char *reason,
-                                  int64_t n);
+                                  int64_t n, int64_t obs);
 
 /** New introducion request received. */
 #define hs_metrics_new_introduction(s)                                        \
-  hs_metrics_update_by_service(HS_METRICS_NUM_INTRODUCTIONS, (s), 0, NULL, 1)
+  hs_metrics_update_by_service(HS_METRICS_NUM_INTRODUCTIONS, (s), 0, NULL, 1, \
+                               0)
 
 /** Introducion request rejected. */
 #define hs_metrics_reject_intro_req(s, reason)                            \
   hs_metrics_update_by_service(HS_METRICS_NUM_REJECTED_INTRO_REQ, (s), 0, \
-                               (reason), 1)
+                               (reason), 1, 0)
 
 /** Number of bytes written to the application from the service. */
 #define hs_metrics_app_write_bytes(i, port, n)                              \
   hs_metrics_update_by_ident(HS_METRICS_APP_WRITE_BYTES, (i), (port), NULL, \
-                             (n))
+                             (n), 0)
 
 /** Number of bytes read from the application to the service. */
 #define hs_metrics_app_read_bytes(i, port, n)                              \
-  hs_metrics_update_by_ident(HS_METRICS_APP_READ_BYTES, (i), (port), NULL, (n))
+  hs_metrics_update_by_ident(HS_METRICS_APP_READ_BYTES, (i), (port), NULL, \
+                             (n), 0)
 
 /** Newly established rendezvous. This is called as soon as the circuit purpose
  * is REND_JOINED which is when the RENDEZVOUS2 cell is sent. */
 #define hs_metrics_new_established_rdv(s)                                    \
-  hs_metrics_update_by_service(HS_METRICS_NUM_ESTABLISHED_RDV, (s), 0, NULL, 1)
+  hs_metrics_update_by_service(HS_METRICS_NUM_ESTABLISHED_RDV, (s), 0, NULL, \
+                               1, 0)
 
 /** New rendezvous circuit failure. */
 #define hs_metrics_failed_rdv(i, reason) \
-  hs_metrics_update_by_ident(HS_METRICS_NUM_FAILED_RDV, (i), 0, (reason), 1)
+  hs_metrics_update_by_ident(HS_METRICS_NUM_FAILED_RDV, (i), 0, (reason), 1, 0)
 
 /** Established rendezvous closed. This is called when the circuit in
  * REND_JOINED state is marked for close. */
 #define hs_metrics_close_established_rdv(i)                                \
-  hs_metrics_update_by_ident(HS_METRICS_NUM_ESTABLISHED_RDV, (i), 0, NULL, -1)
+  hs_metrics_update_by_ident(HS_METRICS_NUM_ESTABLISHED_RDV, (i), 0, NULL, \
+                             -1, 0)
 
 /** New rendezvous circuit being launched. */
 #define hs_metrics_new_rdv(i) \
-  hs_metrics_update_by_ident(HS_METRICS_NUM_RDV, (i), 0, NULL, 1)
+  hs_metrics_update_by_ident(HS_METRICS_NUM_RDV, (i), 0, NULL, 1, 0)
 
 /** New introduction circuit has been established. This is called when the
  * INTRO_ESTABLISHED has been received by the service. */
 #define hs_metrics_new_established_intro(s)                              \
   hs_metrics_update_by_service(HS_METRICS_NUM_ESTABLISHED_INTRO, (s), 0, \
-                               NULL, 1)
+                               NULL, 1, 0)
 
 /** Established introduction circuit closes. This is called when
  * INTRO_ESTABLISHED circuit is marked for close. */
 #define hs_metrics_close_established_intro(i)                                \
   hs_metrics_update_by_ident(HS_METRICS_NUM_ESTABLISHED_INTRO, (i), 0, NULL, \
-                             -1)
+                             -1, 0)
+
+/** Record an introduction circuit build time duration. This is called
+ * when the INTRO_ESTABLISHED has been received by the service. */
+#define hs_metrics_intro_circ_build_time(s, obs)                         \
+  hs_metrics_update_by_service(HS_METRICS_INTRO_CIRC_BUILD_TIME, (s), 0, \
+                               NULL, 1, obs)
+
+/** Record a rendezvous circuit build time duration. This is called as soon as
+ * the circuit purpose is REND_JOINED which is when the RENDEZVOUS2 cell is
+ * sent. */
+#define hs_metrics_rdv_circ_build_time(s, obs)                                \
+  hs_metrics_update_by_service(HS_METRICS_REND_CIRC_BUILD_TIME, (s), 0, NULL, \
+                               1, obs)
 
 #endif /* !defined(TOR_FEATURE_HS_HS_METRICS_H) */

src/feature/hs/hs_metrics_entry.c

@@ -18,6 +18,19 @@
 
 #include "feature/hs/hs_metrics_entry.h"
 
+/* Histogram time buckets (in milliseconds). */
+static const int64_t hs_metrics_circ_build_time_buckets[] =
+{
+  1000,  /* 1s */
+  5000,  /* 5s */
+  10000, /* 10s */
+  30000, /* 30s */
+  60000  /* 60s */
+};
+
+static const size_t hs_metrics_circ_build_time_buckets_size =
+  ARRAY_LENGTH(hs_metrics_circ_build_time_buckets);
+
 /** The base metrics that is a static array of metrics that are added to every
  * single new stores.
  *
@@ -75,6 +88,22 @@ const hs_metrics_entry_t base_metrics[] =
     .name = METRICS_NAME(hs_intro_rejected_intro_req_count),
     .help = "Total number of rejected introduction circuits",
   },
+  {
+    .key = HS_METRICS_INTRO_CIRC_BUILD_TIME,
+    .type = METRICS_TYPE_HISTOGRAM,
+    .name = METRICS_NAME(hs_intro_circ_build_time),
+    .buckets = hs_metrics_circ_build_time_buckets,
+    .bucket_count = hs_metrics_circ_build_time_buckets_size,
+    .help = "The introduction circuit build time in milliseconds",
+  },
+  {
+    .key = HS_METRICS_REND_CIRC_BUILD_TIME,
+    .type = METRICS_TYPE_HISTOGRAM,
+    .name = METRICS_NAME(hs_rend_circ_build_time),
+    .buckets = hs_metrics_circ_build_time_buckets,
+    .bucket_count = hs_metrics_circ_build_time_buckets_size,
+    .help = "The rendezvous circuit build time in milliseconds",
+  },
 };
 
 /** Size of base_metrics array that is number of entries. */

src/feature/hs/hs_metrics_entry.h

@@ -58,6 +58,10 @@ typedef enum {
   HS_METRICS_NUM_ESTABLISHED_INTRO = 6,
   /** Number of rejected introducton requests. */
   HS_METRICS_NUM_REJECTED_INTRO_REQ = 7,
+  /** Introduction circuit build time in milliseconds. */
+  HS_METRICS_INTRO_CIRC_BUILD_TIME = 8,
+  /** Rendezvous circuit build time in milliseconds. */
+  HS_METRICS_REND_CIRC_BUILD_TIME = 9,
 } hs_metrics_key_t;
 
 /** The metadata of an HS metrics. */

src/feature/hs/hs_service.c

@@ -33,6 +33,7 @@
 #include "lib/crypt_ops/crypto_ope.h"
 #include "lib/crypt_ops/crypto_rand.h"
 #include "lib/crypt_ops/crypto_util.h"
+#include "lib/time/tvdiff.h"
 
 #include "feature/hs/hs_circuit.h"
 #include "feature/hs/hs_common.h"
@@ -3412,6 +3413,11 @@ service_rendezvous_circ_has_opened(origin_circuit_t *circ)
    * will even out the metric. */
   if (TO_CIRCUIT(circ)->purpose == CIRCUIT_PURPOSE_S_REND_JOINED) {
     hs_metrics_new_established_rdv(service);
+
+    struct timeval now;
+    tor_gettimeofday(&now);
+    int64_t duration = tv_mdiff(&TO_CIRCUIT(circ)->timestamp_began, &now);
+    hs_metrics_rdv_circ_build_time(service, duration);
   }
 
   goto done;
@@ -3465,8 +3471,13 @@ service_handle_intro_established(origin_circuit_t *circ,
     goto err;
   }
 
+  struct timeval now;
+  tor_gettimeofday(&now);
+  int64_t duration = tv_mdiff(&TO_CIRCUIT(circ)->timestamp_began, &now);
+
   /* Update metrics. */
   hs_metrics_new_established_intro(service);
+  hs_metrics_intro_circ_build_time(service, duration);
 
   log_info(LD_REND, "Successfully received an INTRO_ESTABLISHED cell "
                     "on circuit %u for service %s",

src/test/test_hs_metrics.c

@@ -40,7 +40,7 @@ test_metrics(void *arg)
 
   /* Update entry by identifier. */
   hs_metrics_update_by_ident(HS_METRICS_NUM_INTRODUCTIONS,
-                             &service->keys.identity_pk, 0, NULL, 42);
+                             &service->keys.identity_pk, 0, NULL, 42, 0);
 
   /* Confirm the entry value. */
   const smartlist_t *entries = metrics_store_get_all(service->metrics.store,
@@ -53,14 +53,14 @@ test_metrics(void *arg)
 
   /* Update entry by service now. */
   hs_metrics_update_by_service(HS_METRICS_NUM_INTRODUCTIONS,
-                               service, 0, NULL, 42);
+                               service, 0, NULL, 42, 0);
   tt_int_op(metrics_store_entry_get_value(entry), OP_EQ, 84);
 
   const char *reason = HS_METRICS_ERR_INTRO_REQ_BAD_AUTH_KEY;
 
   /* Update tor_hs_intro_rejected_intro_req_count */
   hs_metrics_update_by_ident(HS_METRICS_NUM_REJECTED_INTRO_REQ,
-                             &service->keys.identity_pk, 0, reason, 112);
+                             &service->keys.identity_pk, 0, reason, 112, 0);
 
   entries = metrics_store_get_all(service->metrics.store,
                                   "tor_hs_intro_rejected_intro_req_count");
@@ -75,7 +75,7 @@ test_metrics(void *arg)
 
   /* Update tor_hs_intro_rejected_intro_req_count entry by service now. */
   hs_metrics_update_by_service(HS_METRICS_NUM_REJECTED_INTRO_REQ, service, 0,
-                               reason, 10);
+                               reason, 10, 0);
   tt_int_op(metrics_store_entry_get_value(entry), OP_EQ, 122);
 
  done: