From 21ede2f9a4d173e999933444e543b98febdee29f Mon Sep 17 00:00:00 2001 From: filipecosta90 Date: Thu, 7 Nov 2024 15:40:15 +0000 Subject: [PATCH] Ensuring latency tracing is capped both on smallest and largest latency tracking value. recording min/max outside of hdr_histogram to avoid caps. increased per second rotated histogram precision --- deps/hdr_histogram/hdr_histogram.c | 6 ++ deps/hdr_histogram/hdr_histogram.h | 12 ++++ run_stats.cpp | 89 ++++++++++++++++-------------- run_stats_types.cpp | 16 ++++-- run_stats_types.h | 8 ++- 5 files changed, 81 insertions(+), 50 deletions(-) diff --git a/deps/hdr_histogram/hdr_histogram.c b/deps/hdr_histogram/hdr_histogram.c index 489d79ea..7bb64224 100644 --- a/deps/hdr_histogram/hdr_histogram.c +++ b/deps/hdr_histogram/hdr_histogram.c @@ -448,6 +448,12 @@ size_t hdr_get_memory_size(struct hdr_histogram *h) /* ## ## ## ## ## ## ## ## ## ## ## */ /* ####### ## ######## ## ## ## ######## ###### */ +bool hdr_record_value_capped(struct hdr_histogram* h, int64_t value) +{ + int64_t capped_value = (value > h->highest_trackable_value) ? h->highest_trackable_value : value; + capped_value = (capped_value < h->lowest_trackable_value) ? h->lowest_trackable_value : capped_value; + return hdr_record_value(h, capped_value); +} bool hdr_record_value(struct hdr_histogram* h, int64_t value) { diff --git a/deps/hdr_histogram/hdr_histogram.h b/deps/hdr_histogram/hdr_histogram.h index d58e56ac..dc354163 100644 --- a/deps/hdr_histogram/hdr_histogram.h +++ b/deps/hdr_histogram/hdr_histogram.h @@ -110,6 +110,18 @@ size_t hdr_get_memory_size(struct hdr_histogram* h); */ bool hdr_record_value(struct hdr_histogram* h, int64_t value); +/** + * Records a value in the histogram, rounding the value to the specified precision + * (based on the significant figure set during histogram creation). This function + * will cap the recorded value at the histogram's highest_trackable_value if the input + * exceeds this threshold, and at the lowest_trackable_value if it falls below. + * + * @param h Pointer to the histogram structure + * @param value Value to add to the histogram + * @return false if the value cannot be recorded due to an error, true otherwise + */ +bool hdr_record_value_capped(struct hdr_histogram* h, int64_t value); + /** * Records a value in the histogram, will round this value of to a precision at or better * than the significant_figure specified at construction time. diff --git a/run_stats.cpp b/run_stats.cpp index 08470290..f9453770 100644 --- a/run_stats.cpp +++ b/run_stats.cpp @@ -185,10 +185,10 @@ void run_stats::update_get_op(struct timeval* ts, unsigned int bytes_rx, unsigne m_cur_stats.m_get_cmd.update_op(bytes_rx, bytes_tx, latency, hits, misses); m_cur_stats.m_total_cmd.update_op(bytes_rx, bytes_tx, latency, hits, misses); m_totals.update_op(bytes_rx, bytes_tx, latency); - hdr_record_value(m_get_latency_histogram,latency); - hdr_record_value(inst_m_get_latency_histogram,latency); - hdr_record_value(m_totals_latency_histogram,latency); - hdr_record_value(inst_m_totals_latency_histogram,latency); + hdr_record_value_capped(m_get_latency_histogram,latency); + hdr_record_value_capped(inst_m_get_latency_histogram,latency); + hdr_record_value_capped(m_totals_latency_histogram,latency); + hdr_record_value_capped(inst_m_totals_latency_histogram,latency); } void run_stats::update_set_op(struct timeval* ts, unsigned int bytes_rx, unsigned int bytes_tx, unsigned int latency) @@ -198,10 +198,10 @@ void run_stats::update_set_op(struct timeval* ts, unsigned int bytes_rx, unsigne m_cur_stats.m_set_cmd.update_op(bytes_rx, bytes_tx, latency); m_cur_stats.m_total_cmd.update_op(bytes_rx, bytes_tx, latency); m_totals.update_op(bytes_rx, bytes_tx, latency); - hdr_record_value(m_set_latency_histogram,latency); - hdr_record_value(inst_m_set_latency_histogram,latency); - hdr_record_value(m_totals_latency_histogram,latency); - hdr_record_value(inst_m_totals_latency_histogram,latency); + hdr_record_value_capped(m_set_latency_histogram,latency); + hdr_record_value_capped(inst_m_set_latency_histogram,latency); + hdr_record_value_capped(m_totals_latency_histogram,latency); + hdr_record_value_capped(inst_m_totals_latency_histogram,latency); } void run_stats::update_moved_get_op(struct timeval* ts, unsigned int bytes_rx, unsigned int bytes_tx, unsigned int latency) @@ -211,10 +211,10 @@ void run_stats::update_moved_get_op(struct timeval* ts, unsigned int bytes_rx, u m_cur_stats.m_get_cmd.update_moved_op(bytes_rx, bytes_tx, latency); m_cur_stats.m_total_cmd.update_op(bytes_rx, bytes_tx, latency); m_totals.update_op(bytes_rx, bytes_tx, latency); - hdr_record_value(m_get_latency_histogram,latency); - hdr_record_value(inst_m_get_latency_histogram,latency); - hdr_record_value(m_totals_latency_histogram,latency); - hdr_record_value(inst_m_totals_latency_histogram,latency); + hdr_record_value_capped(m_get_latency_histogram,latency); + hdr_record_value_capped(inst_m_get_latency_histogram,latency); + hdr_record_value_capped(m_totals_latency_histogram,latency); + hdr_record_value_capped(inst_m_totals_latency_histogram,latency); } void run_stats::update_moved_set_op(struct timeval* ts, unsigned int bytes_rx, unsigned int bytes_tx, unsigned int latency) @@ -224,10 +224,10 @@ void run_stats::update_moved_set_op(struct timeval* ts, unsigned int bytes_rx, u m_cur_stats.m_set_cmd.update_moved_op(bytes_rx, bytes_tx, latency); m_cur_stats.m_total_cmd.update_moved_op(bytes_rx, bytes_tx, latency); m_totals.update_op(bytes_rx, bytes_tx, latency); - hdr_record_value(m_set_latency_histogram,latency); - hdr_record_value(inst_m_set_latency_histogram,latency); - hdr_record_value(m_totals_latency_histogram,latency); - hdr_record_value(inst_m_totals_latency_histogram,latency); + hdr_record_value_capped(m_set_latency_histogram,latency); + hdr_record_value_capped(inst_m_set_latency_histogram,latency); + hdr_record_value_capped(m_totals_latency_histogram,latency); + hdr_record_value_capped(inst_m_totals_latency_histogram,latency); } void run_stats::update_moved_arbitrary_op(struct timeval *ts, unsigned int bytes_rx, unsigned int bytes_tx, @@ -239,9 +239,9 @@ void run_stats::update_moved_arbitrary_op(struct timeval *ts, unsigned int bytes m_totals.update_op(bytes_rx, bytes_tx, latency); struct hdr_histogram* hist = m_ar_commands_latency_histograms.at(request_index); - hdr_record_value(hist,latency); - hdr_record_value(m_totals_latency_histogram,latency); - hdr_record_value(inst_m_totals_latency_histogram,latency); + hdr_record_value_capped(hist,latency); + hdr_record_value_capped(m_totals_latency_histogram,latency); + hdr_record_value_capped(inst_m_totals_latency_histogram,latency); } void run_stats::update_ask_get_op(struct timeval* ts, unsigned int bytes_rx, unsigned int bytes_tx, unsigned int latency) @@ -251,10 +251,10 @@ void run_stats::update_ask_get_op(struct timeval* ts, unsigned int bytes_rx, uns m_cur_stats.m_get_cmd.update_ask_op(bytes_rx, bytes_tx, latency); m_cur_stats.m_total_cmd.update_ask_op(bytes_rx, bytes_tx, latency); m_totals.update_op(bytes_rx, bytes_tx, latency); - hdr_record_value(m_get_latency_histogram,latency); - hdr_record_value(inst_m_get_latency_histogram,latency); - hdr_record_value(m_totals_latency_histogram,latency); - hdr_record_value(inst_m_totals_latency_histogram,latency); + hdr_record_value_capped(m_get_latency_histogram,latency); + hdr_record_value_capped(inst_m_get_latency_histogram,latency); + hdr_record_value_capped(m_totals_latency_histogram,latency); + hdr_record_value_capped(inst_m_totals_latency_histogram,latency); } void run_stats::update_ask_set_op(struct timeval* ts, unsigned int bytes_rx, unsigned int bytes_tx, unsigned int latency) @@ -264,10 +264,10 @@ void run_stats::update_ask_set_op(struct timeval* ts, unsigned int bytes_rx, uns m_cur_stats.m_set_cmd.update_ask_op(bytes_rx, bytes_tx, latency); m_cur_stats.m_total_cmd.update_ask_op(bytes_rx, bytes_tx, latency); m_totals.update_op(bytes_rx, bytes_tx, latency); - hdr_record_value(m_set_latency_histogram,latency); - hdr_record_value(inst_m_set_latency_histogram,latency); - hdr_record_value(m_totals_latency_histogram,latency); - hdr_record_value(inst_m_totals_latency_histogram,latency); + hdr_record_value_capped(m_set_latency_histogram,latency); + hdr_record_value_capped(inst_m_set_latency_histogram,latency); + hdr_record_value_capped(m_totals_latency_histogram,latency); + hdr_record_value_capped(inst_m_totals_latency_histogram,latency); } void run_stats::update_ask_arbitrary_op(struct timeval *ts, unsigned int bytes_rx, unsigned int bytes_tx, @@ -279,9 +279,9 @@ void run_stats::update_ask_arbitrary_op(struct timeval *ts, unsigned int bytes_r m_totals.update_op(bytes_rx, bytes_tx, latency); struct hdr_histogram* hist = m_ar_commands_latency_histograms.at(request_index); - hdr_record_value(hist,latency); - hdr_record_value(m_totals_latency_histogram,latency); - hdr_record_value(inst_m_totals_latency_histogram,latency); + hdr_record_value_capped(hist,latency); + hdr_record_value_capped(m_totals_latency_histogram,latency); + hdr_record_value_capped(inst_m_totals_latency_histogram,latency); } void run_stats::update_wait_op(struct timeval *ts, unsigned int latency) @@ -291,10 +291,10 @@ void run_stats::update_wait_op(struct timeval *ts, unsigned int latency) m_cur_stats.m_wait_cmd.update_op(0,0, latency); m_cur_stats.m_total_cmd.update_op(0,0, latency); m_totals.update_op(0,0, latency); - hdr_record_value(m_wait_latency_histogram,latency); - hdr_record_value(inst_m_wait_latency_histogram,latency); - hdr_record_value(m_totals_latency_histogram,latency); - hdr_record_value(inst_m_totals_latency_histogram,latency); + hdr_record_value_capped(m_wait_latency_histogram,latency); + hdr_record_value_capped(inst_m_wait_latency_histogram,latency); + hdr_record_value_capped(m_totals_latency_histogram,latency); + hdr_record_value_capped(inst_m_totals_latency_histogram,latency); } void run_stats::update_arbitrary_op(struct timeval *ts, unsigned int bytes_rx, unsigned int bytes_tx, @@ -307,10 +307,10 @@ void run_stats::update_arbitrary_op(struct timeval *ts, unsigned int bytes_rx, u struct hdr_histogram* hist = m_ar_commands_latency_histograms.at(request_index); struct hdr_histogram* inst_hist = inst_m_ar_commands_latency_histograms.at(request_index); - hdr_record_value(hist,latency); - hdr_record_value(inst_hist,latency); - hdr_record_value(m_totals_latency_histogram,latency); - hdr_record_value(inst_m_totals_latency_histogram,latency); + hdr_record_value_capped(hist,latency); + hdr_record_value_capped(inst_hist,latency); + hdr_record_value_capped(m_totals_latency_histogram,latency); + hdr_record_value_capped(inst_m_totals_latency_histogram,latency); } unsigned int run_stats::get_duration(void) @@ -881,16 +881,14 @@ void run_stats::summarize(totals& result) const void result_print_to_json(json_handler * jsonhandler, const char * type, double ops_sec, double hits, double miss, double moved, double ask, double kbs, double kbs_rx, double kbs_tx, - double latency, long ops, + double latency, long m_total_latency, long ops, std::vector quantile_list, struct hdr_histogram* latency_histogram, std::vector timestamps, std::vector timeserie_stats ) { if (jsonhandler != NULL){ // Added for double verification in case someone accidently send NULL. jsonhandler->open_nesting(type); - const long hdr_count = hdr_total_count(latency_histogram); - assert(hdr_count < ops && "reported ops and tracked ops via hdrhistogram are same"); - jsonhandler->write_obj("Count","%lld", hdr_count); + jsonhandler->write_obj("Count","%lld", ops); jsonhandler->write_obj("Ops/sec","%.2f", ops_sec); jsonhandler->write_obj("Hits/sec","%.2f", hits); jsonhandler->write_obj("Misses/sec","%.2f", miss); @@ -908,6 +906,7 @@ void result_print_to_json(json_handler * jsonhandler, const char * type, double // to be retrocompatible jsonhandler->write_obj("Latency","%.3f", avg_latency); jsonhandler->write_obj("Average Latency","%.3f", avg_latency); + jsonhandler->write_obj("Accumulated Latency","%lld", m_total_latency / LATENCY_HDR_RESULTS_MULTIPLIER); jsonhandler->write_obj("Min Latency","%.3f", min_latency); jsonhandler->write_obj("Max Latency","%.3f", max_latency); // preserve KB/sec for backwards compatibility @@ -928,6 +927,7 @@ void result_print_to_json(json_handler * jsonhandler, const char * type, double jsonhandler->write_obj("Count","%lld", cmd_stats.m_ops); if (sec_has_samples){ jsonhandler->write_obj("Average Latency","%.3f", cmd_stats.m_avg_latency); + jsonhandler->write_obj("Accumulated Latency","%lld", cmd_stats.m_total_latency / LATENCY_HDR_RESULTS_MULTIPLIER); jsonhandler->write_obj("Min Latency","%.3f", cmd_stats.m_min_latency); jsonhandler->write_obj("Max Latency","%.3f", cmd_stats.m_max_latency); for (std::size_t i = 0; i < quantile_list.size(); i++){ @@ -1244,6 +1244,7 @@ void run_stats::print_json(json_handler *jsonhandler, arbitrary_command_list& co m_totals.m_ar_commands[i].m_bytes_sec_rx, m_totals.m_ar_commands[i].m_bytes_sec_tx, m_totals.m_ar_commands[i].m_latency, + m_totals.m_ar_commands[i].m_total_latency, m_totals.m_ar_commands[i].m_ops, quantiles_list, arbitrary_command_latency_histogram, @@ -1264,6 +1265,7 @@ void run_stats::print_json(json_handler *jsonhandler, arbitrary_command_list& co m_totals.m_set_cmd.m_bytes_sec_rx, m_totals.m_set_cmd.m_bytes_sec_tx, m_totals.m_set_cmd.m_latency, + m_totals.m_set_cmd.m_total_latency, m_totals.m_set_cmd.m_ops, quantiles_list, m_set_latency_histogram, @@ -1279,6 +1281,7 @@ void run_stats::print_json(json_handler *jsonhandler, arbitrary_command_list& co m_totals.m_get_cmd.m_bytes_sec_rx, m_totals.m_get_cmd.m_bytes_sec_tx, m_totals.m_get_cmd.m_latency, + m_totals.m_get_cmd.m_total_latency, m_totals.m_get_cmd.m_ops, quantiles_list, m_get_latency_histogram, @@ -1294,6 +1297,7 @@ void run_stats::print_json(json_handler *jsonhandler, arbitrary_command_list& co 0.0, 0.0, 0.0, + 0.0, m_totals.m_wait_cmd.m_ops, quantiles_list, m_wait_latency_histogram, @@ -1311,6 +1315,7 @@ void run_stats::print_json(json_handler *jsonhandler, arbitrary_command_list& co m_totals.m_bytes_sec_rx, m_totals.m_bytes_sec_tx, m_totals.m_latency, + m_totals.m_total_latency, m_totals.m_ops, quantiles_list, m_totals.latency_histogram, diff --git a/run_stats_types.cpp b/run_stats_types.cpp index 5d5be1a9..77068dd0 100644 --- a/run_stats_types.cpp +++ b/run_stats_types.cpp @@ -73,15 +73,11 @@ void one_sec_cmd_stats::merge(const one_sec_cmd_stats& other) { } void one_sec_cmd_stats::summarize_quantiles(safe_hdr_histogram histogram, std::vector quantiles) { - const bool has_samples = m_ops>0; for (std::size_t i = 0; i < quantiles.size(); i++){ const float quantile = quantiles[i]; const double value = hdr_value_at_percentile(histogram, quantile)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER; summarized_quantile_values.push_back(value); } - m_avg_latency = has_samples ? hdr_mean(histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : 0.0; - m_max_latency = has_samples ? (1.0 * hdr_max(histogram))/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : std::numeric_limits::lowest(); - m_min_latency = has_samples ? (1.0 * hdr_min(histogram))/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : std::numeric_limits::max();; } void one_sec_cmd_stats::update_op(unsigned int bytes_rx, unsigned int bytes_tx, unsigned int latency) { @@ -89,6 +85,10 @@ void one_sec_cmd_stats::update_op(unsigned int bytes_rx, unsigned int bytes_tx, m_bytes_tx += bytes_tx; m_ops++; m_total_latency += latency; + const double latency_millis = latency / (double) LATENCY_HDR_RESULTS_MULTIPLIER; + m_avg_latency = (double) (m_total_latency) / (double) m_ops / (double) LATENCY_HDR_RESULTS_MULTIPLIER; + m_max_latency = (m_max_latency < latency_millis) ? latency_millis: m_max_latency; + m_min_latency = (m_min_latency > latency_millis) ? latency_millis: m_min_latency; } void one_sec_cmd_stats::update_op(unsigned int bytes_rx, unsigned int bytes_tx, unsigned int latency, @@ -202,6 +202,7 @@ totals_cmd::totals_cmd() : m_moved_sec(0), m_ask_sec(0), m_latency(0), + m_total_latency(0), m_ops(0) { } @@ -213,6 +214,7 @@ void totals_cmd::add(const totals_cmd& other) { m_bytes_sec_rx += other.m_bytes_sec_rx; m_bytes_sec_tx += other.m_bytes_sec_tx; m_latency += other.m_latency; + m_total_latency += other.m_total_latency; m_ops += other.m_ops; } @@ -228,6 +230,7 @@ void totals_cmd::aggregate_average(size_t stats_size) { void totals_cmd::summarize(const one_sec_cmd_stats& other, unsigned long test_duration_usec) { m_ops = other.m_ops; + m_total_latency = other.m_total_latency; m_ops_sec = (double) other.m_ops / test_duration_usec * 1000000; if (other.m_ops > 0) { @@ -283,6 +286,7 @@ totals::totals() : m_moved_sec(0), m_ask_sec(0), m_latency(0), + m_total_latency(0), m_bytes_rx(0), m_bytes_tx(0), m_ops(0) { @@ -308,6 +312,7 @@ void totals::add(const totals& other) { m_bytes_rx += other.m_bytes_rx; m_bytes_tx += other.m_bytes_tx; m_latency += other.m_latency; + m_total_latency += other.m_latency; m_ops += other.m_ops; // aggregate latency data @@ -319,5 +324,6 @@ void totals::update_op(unsigned long int bytes_rx, unsigned long int bytes_tx, u m_bytes_tx += bytes_tx; m_ops++; m_latency += latency; - hdr_record_value(latency_histogram,latency); + m_total_latency += latency; + hdr_record_value_capped(latency_histogram,latency); } diff --git a/run_stats_types.h b/run_stats_types.h index e4e1001e..827c86d4 100644 --- a/run_stats_types.h +++ b/run_stats_types.h @@ -20,11 +20,11 @@ #define MEMTIER_BENCHMARK_RUN_STATS_TYPES_H #define LATENCY_HDR_MIN_VALUE 10 -#define LATENCY_HDR_MAX_VALUE 60000000 ## LL +#define LATENCY_HDR_MAX_VALUE 6000000000 ## LL #define LATENCY_HDR_SIGDIGTS 3 #define LATENCY_HDR_SEC_MIN_VALUE 10 -#define LATENCY_HDR_SEC_MAX_VALUE 1000000 ## LL -#define LATENCY_HDR_SEC_SIGDIGTS 2 +#define LATENCY_HDR_SEC_MAX_VALUE 600000000 ## LL +#define LATENCY_HDR_SEC_SIGDIGTS 3 #define LATENCY_HDR_RESULTS_MULTIPLIER 1000 #define LATENCY_HDR_GRANULARITY 10 @@ -143,6 +143,7 @@ class totals_cmd { double m_moved_sec; double m_ask_sec; double m_latency; + unsigned long long int m_total_latency; unsigned long int m_ops; totals_cmd(); void add(const totals_cmd& other); @@ -186,6 +187,7 @@ class totals { double m_moved_sec; double m_ask_sec; unsigned long long int m_latency; + unsigned long long int m_total_latency; // number of bytes received unsigned long int m_bytes_rx; // number of bytes sent