This is an automated email from the git hooks/post-receive script.
dgoulet pushed a commit to branch main in repository tor.
commit 1a60fa547f5c061b1dd4dda4569ddcbb5bf3ad9a Author: Gabriela Moldovan gabi@torproject.org AuthorDate: Wed Mar 8 17:52:20 2023 +0000
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 | 5 ++++ src/feature/hs/hs_metrics.c | 16 +++++++++---- src/feature/hs/hs_metrics.h | 49 ++++++++++++++++++++++++++------------- src/feature/hs/hs_metrics_entry.c | 29 +++++++++++++++++++++++ src/feature/hs/hs_metrics_entry.h | 4 ++++ src/feature/hs/hs_service.c | 11 +++++++++ src/test/test_hs_metrics.c | 8 +++---- 7 files changed, 98 insertions(+), 24 deletions(-)
diff --git a/changes/ticket40757 b/changes/ticket40757 index e2d8c1ed47..68cd5ac19b 100644 --- a/changes/ticket40757 +++ b/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. diff --git a/src/feature/hs/hs_metrics.c b/src/feature/hs/hs_metrics.c index 38cdb49e40..46c72cf539 100644 --- a/src/feature/hs/hs_metrics.c +++ b/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,8 +167,14 @@ 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; + } + + 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 diff --git a/src/feature/hs/hs_metrics.h b/src/feature/hs/hs_metrics.h index a32f76e3bc..4eff4cb498 100644 --- a/src/feature/hs/hs_metrics.h +++ b/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) +#define hs_metrics_new_introduction(s) \ + 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)) +#define hs_metrics_app_read_bytes(i, port, 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) +#define hs_metrics_new_established_rdv(s) \ + 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) +#define hs_metrics_close_established_rdv(i) \ + 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) */ diff --git a/src/feature/hs/hs_metrics_entry.c b/src/feature/hs/hs_metrics_entry.c index 9181d770e0..3524d72334 100644 --- a/src/feature/hs/hs_metrics_entry.c +++ b/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. */ diff --git a/src/feature/hs/hs_metrics_entry.h b/src/feature/hs/hs_metrics_entry.h index b966f0c226..4c9abd06d7 100644 --- a/src/feature/hs/hs_metrics_entry.h +++ b/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. */ diff --git a/src/feature/hs/hs_service.c b/src/feature/hs/hs_service.c index b5a69b8d59..14cd9efec1 100644 --- a/src/feature/hs/hs_service.c +++ b/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", diff --git a/src/test/test_hs_metrics.c b/src/test/test_hs_metrics.c index b7c0ab53da..c3c7ef57bc 100644 --- a/src/test/test_hs_metrics.c +++ b/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: