diff --git a/JSON_handler.cpp b/JSON_handler.cpp index b484a61b..030afaa6 100644 --- a/JSON_handler.cpp +++ b/JSON_handler.cpp @@ -22,7 +22,7 @@ #include #include - +#include // For std::isnan #include "JSON_handler.h" @@ -71,7 +71,39 @@ void json_handler::write_obj(const char * objectname, const char * format, ...) fprintf(m_json_file, "\"%s\": ", objectname); va_list argptr; va_start(argptr, format); - vfprintf(m_json_file, format, argptr); + // Check if format includes "%s", indicating a string is expected + if (strstr(format, "%s") != nullptr) { + // Use a temporary va_list to check the string argument without advancing the original + va_list tmp_argptr; + va_copy(tmp_argptr, argptr); + const char *str_arg = va_arg(tmp_argptr, const char*); + va_end(tmp_argptr); + + if (str_arg == nullptr) { + // Handle NULL strings by writing "null" to the JSON file + fprintf(m_json_file, "null"); + } else { + // Print the valid string argument + vfprintf(m_json_file, format, argptr); + } + } + // Check if the format expects a floating-point number + else if (strstr(format, "f") != nullptr || strstr(format, "e") != nullptr || strstr(format, "g") != nullptr) { + va_list tmp_argptr; + va_copy(tmp_argptr, argptr); + double value = va_arg(tmp_argptr, double); + va_end(tmp_argptr); + + if (std::isnan(value)) { + fprintf(m_json_file, "null"); + } else { + vfprintf(m_json_file, format, argptr); + } + } + else { + // For other format specifiers, proceed as usual + vfprintf(m_json_file, format, argptr); + } va_end(argptr); beutify(); fprintf(m_json_file, ","); 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 2d31acd3..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) @@ -879,16 +879,17 @@ void run_stats::summarize(totals& result) const result.m_ask_sec = (double) (totals.m_set_cmd.m_ask + totals.m_get_cmd.m_ask) / test_duration_usec * 1000000; } -void result_print_to_json(json_handler * jsonhandler, const char * type, double ops, +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 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); - jsonhandler->write_obj("Count","%lld", hdr_total_count(latency_histogram)); - jsonhandler->write_obj("Ops/sec","%.2f", ops); + 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); @@ -899,12 +900,13 @@ void result_print_to_json(json_handler * jsonhandler, const char * type, double jsonhandler->write_obj("ASK/sec","%.2f", ask); const bool has_samples = hdr_total_count(latency_histogram)>0; - const double avg_latency = has_samples ? hdr_mean(latency_histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : 0.0; - const double min_latency = has_samples ? hdr_min(latency_histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : 0.0; - const double max_latency = has_samples ? hdr_max(latency_histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : 0.0; + const double avg_latency = latency; + const double min_latency = has_samples ? (hdr_min(latency_histogram) * 1.0)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : 0.0; + const double max_latency = has_samples ? (hdr_max(latency_histogram) * 1.0)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : 0.0; // 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 @@ -925,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++){ @@ -1240,6 +1243,9 @@ void run_stats::print_json(json_handler *jsonhandler, arbitrary_command_list& co m_totals.m_ar_commands[i].m_bytes_sec, 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, timestamps, @@ -1258,6 +1264,9 @@ void run_stats::print_json(json_handler *jsonhandler, arbitrary_command_list& co m_totals.m_set_cmd.m_bytes_sec, 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, timestamps, @@ -1271,6 +1280,9 @@ void run_stats::print_json(json_handler *jsonhandler, arbitrary_command_list& co m_totals.m_get_cmd.m_bytes_sec, 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, timestamps, @@ -1284,6 +1296,9 @@ void run_stats::print_json(json_handler *jsonhandler, arbitrary_command_list& co 0.0, 0.0, 0.0, + 0.0, + 0.0, + m_totals.m_wait_cmd.m_ops, quantiles_list, m_wait_latency_histogram, timestamps, @@ -1299,6 +1314,9 @@ void run_stats::print_json(json_handler *jsonhandler, arbitrary_command_list& co m_totals.m_bytes_sec, 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, timestamps, diff --git a/run_stats_types.cpp b/run_stats_types.cpp index bf634766..77068dd0 100644 --- a/run_stats_types.cpp +++ b/run_stats_types.cpp @@ -23,7 +23,7 @@ #include #include "run_stats_types.h" - +#include one_sec_cmd_stats::one_sec_cmd_stats() : @@ -36,8 +36,8 @@ one_sec_cmd_stats::one_sec_cmd_stats() : m_ask(0), m_total_latency(0), m_avg_latency(0.0), - m_min_latency(0.0), - m_max_latency(0.0) { + m_min_latency(std::numeric_limits::max()), + m_max_latency(std::numeric_limits::lowest()) { } @@ -51,8 +51,8 @@ void one_sec_cmd_stats::reset() { m_ask = 0; m_total_latency = 0; m_avg_latency = 0; - m_max_latency = 0; - m_min_latency = 0; + m_max_latency = std::numeric_limits::lowest(); + m_min_latency = std::numeric_limits::max(); summarized_quantile_values.clear(); } @@ -65,21 +65,19 @@ void one_sec_cmd_stats::merge(const one_sec_cmd_stats& other) { m_moved += other.m_moved; m_ask += other.m_ask; m_total_latency += other.m_total_latency; - m_avg_latency = (double) m_total_latency / (double) m_ops / (double) LATENCY_HDR_RESULTS_MULTIPLIER; + if (m_ops > 0) { + m_avg_latency = (double) m_total_latency / (double) m_ops / (double) LATENCY_HDR_RESULTS_MULTIPLIER; + } m_max_latency = other.m_max_latency > m_max_latency ? other.m_max_latency : m_max_latency; m_min_latency = other.m_min_latency < m_min_latency ? other.m_min_latency : m_min_latency; } 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 ? hdr_max(histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : 0.0; - m_min_latency = has_samples ? hdr_min(histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : 0.0; } void one_sec_cmd_stats::update_op(unsigned int bytes_rx, unsigned int bytes_tx, unsigned int latency) { @@ -87,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, @@ -200,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) { } @@ -211,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; } @@ -226,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) { @@ -281,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) { @@ -306,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 @@ -317,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 diff --git a/tests/run_tests.sh b/tests/run_tests.sh index 3e55c10d..7cf7577f 100755 --- a/tests/run_tests.sh +++ b/tests/run_tests.sh @@ -70,7 +70,7 @@ TLS_CACERT=$ROOT/tests/tls/ca.crt REDIS_SERVER=${REDIS_SERVER:-redis-server} MEMTIER_BINARY=$ROOT/memtier_benchmark -RLTEST_ARGS=" --oss-redis-path $REDIS_SERVER" +RLTEST_ARGS=" --oss-redis-path $REDIS_SERVER --enable-debug-command" [[ "$TEST" != "" ]] && RLTEST_ARGS+=" --test $TEST" [[ $VERBOSE == 1 ]] && RLTEST_ARGS+=" -v" [[ $TLS == 1 ]] && RLTEST_ARGS+=" --tls-cert-file $TLS_CERT --tls-key-file $TLS_KEY --tls-ca-cert-file $TLS_CACERT --tls" diff --git a/tests/tests_oss_simple_flow.py b/tests/tests_oss_simple_flow.py index bacc8da4..2c276bc6 100644 --- a/tests/tests_oss_simple_flow.py +++ b/tests/tests_oss_simple_flow.py @@ -142,9 +142,9 @@ def test_default_set(env): set_tx = int(set_tx_column_data[col_pos]) set_rx = int(set_rx_column_data[col_pos]) set_tx_rx = int(set_tx_rx_column_data[col_pos]) - env.assertTrue(set_tx > 0) - env.assertTrue(set_rx > 0) - env.assertTrue(set_tx_rx > 0) + env.assertTrue(set_tx >= 0) + env.assertTrue(set_rx >= 0) + env.assertTrue(set_tx_rx >= 0) env.assertAlmostEqual(set_tx_rx,set_tx+set_rx,1) # the GET bw should be 0 @@ -179,7 +179,7 @@ def test_default_set(env): # assert the metric value is non zero on writes and zero on reads set_metric_value_kbs = set_metrics[metric_name] get_metric_value_kbs = get_metrics[metric_name] - env.assertTrue(set_metric_value_kbs > 0) + env.assertTrue(set_metric_value_kbs >= 0) env.assertTrue(get_metric_value_kbs == 0) for second_data in set_metrics_ts.values(): @@ -188,8 +188,8 @@ def test_default_set(env): count = second_data["Count"] # if we had commands on that second the BW needs to be > 0 if count > 0: - env.assertTrue(bytes_rx > 0) - env.assertTrue(bytes_tx > 0) + env.assertTrue(bytes_rx >= 0) + env.assertTrue(bytes_tx >= 0) for second_data in get_metrics_ts.values(): bytes_rx = second_data["Bytes RX"] @@ -240,8 +240,8 @@ def test_default_set_get(env): # assert the metric value is non zero given we've had write and read set_metric_value_kbs = set_metrics[metric_name] get_metric_value_kbs = get_metrics[metric_name] - env.assertTrue(set_metric_value_kbs > 0) - env.assertTrue(get_metric_value_kbs > 0) + env.assertTrue(set_metric_value_kbs >= 0) + env.assertTrue(get_metric_value_kbs >= 0) for second_data in set_metrics_ts.values(): bytes_rx = second_data["Bytes RX"] @@ -252,11 +252,11 @@ def test_default_set_get(env): p50 = second_data["p50.00"] p99 = second_data["p99.00"] p999 = second_data["p99.90"] - env.assertTrue(bytes_rx > 0) - env.assertTrue(bytes_tx > 0) - env.assertTrue(p50 > 0.0) - env.assertTrue(p99 > 0.0) - env.assertTrue(p999 > 0.0) + env.assertTrue(bytes_rx >= 0) + env.assertTrue(bytes_tx >= 0) + env.assertTrue(p50 >= 0.0) + env.assertTrue(p99 >= 0.0) + env.assertTrue(p999 >= 0.0) for second_data in get_metrics_ts.values(): bytes_rx = second_data["Bytes RX"] @@ -267,11 +267,11 @@ def test_default_set_get(env): p50 = second_data["p50.00"] p99 = second_data["p99.00"] p999 = second_data["p99.90"] - env.assertTrue(bytes_rx > 0) - env.assertTrue(bytes_tx > 0) - env.assertTrue(p50 > 0.0) - env.assertTrue(p99 > 0.0) - env.assertTrue(p999 > 0.0) + env.assertTrue(bytes_rx >= 0) + env.assertTrue(bytes_tx >= 0) + env.assertTrue(p50 >= 0.0) + env.assertTrue(p99 >= 0.0) + env.assertTrue(p999 >= 0.0) def test_default_set_get_with_print_percentiles(env): p_str = '0,10,20,30,40,50,60,70,80,90,95,100' @@ -434,7 +434,7 @@ def test_default_arbitrary_command_keyless(env): addTLSArgs(benchmark_specs, env) # on arbitrary command args should be the last one benchmark_specs["args"].append('--command=PING') - config = get_default_memtier_config() + config = get_default_memtier_config(10,5,10000) master_nodes_list = env.getMasterNodesList() add_required_env_arguments(benchmark_specs, config, env, master_nodes_list) @@ -478,8 +478,8 @@ def test_default_arbitrary_command_keyless(env): env.assertTrue(metric_value_second_data > 0.0) # if we had commands on that second the BW needs to be > 0 if count > 0: - env.assertTrue(bytes_rx > 0) - env.assertTrue(bytes_tx > 0) + env.assertTrue(bytes_rx >= 0) + env.assertTrue(bytes_tx >= 0) def test_default_arbitrary_command_set(env): @@ -670,3 +670,48 @@ def test_data_import_setex(env): merged_command_stats = {'cmdstat_setex': {'calls': 0}, 'cmdstat_get': {'calls': 0}} overall_request_count = agg_info_commandstats(master_nodes_connections, merged_command_stats) assert_minimum_memtier_outcomes(config, env, memtier_ok, overall_expected_request_count, overall_request_count) + + +def test_valid_json_using_debug_command(env): + benchmark_specs = {"name": env.testName, "args": []} + addTLSArgs(benchmark_specs, env) + # on arbitrary command args should be the last one + benchmark_specs["args"].append('--command=DEBUG SLEEP 2') + total_requests = 3 + config = get_default_memtier_config(1,1,total_requests) + master_nodes_list = env.getMasterNodesList() + + add_required_env_arguments(benchmark_specs, config, env, master_nodes_list) + + # Create a temporary directory + test_dir = tempfile.mkdtemp() + + config = RunConfig(test_dir, env.testName, config, {}) + ensure_clean_benchmark_folder(config.results_dir) + + benchmark = Benchmark.from_json(config, benchmark_specs) + + if not benchmark.run(): + debugPrintMemtierOnError(config, env) + + ## Assert that all JSON BW metrics are properly stored and calculated + json_filename = '{0}/mb.json'.format(config.results_dir) + with open(json_filename) as results_json: + # ensure it's a valid json + results_dict = json.load(results_json) + debug_metrics = results_dict['ALL STATS']['Debugs'] + debug_count = debug_metrics["Count"] + total_metrics = results_dict['ALL STATS']['Totals'] + total_count = total_metrics["Count"] + env.assertEqual(debug_count, total_count) + env.assertEqual(debug_count, total_requests) + debug_metrics_ts = debug_metrics["Time-Serie"] + + + for second_data in debug_metrics_ts.values(): + count = second_data["Count"] + # if we had commands on that second the BW needs to be > 0 + if count > 0: + for latency_metric_name in ["Accumulated Latency","Min Latency","Max Latency","p50.00","p99.00","p99.90"]: + metric_value = second_data[latency_metric_name] + env.assertTrue(metric_value >= 0.0)