Ensuring latency tracing is capped both on smallest and largest laten…

…cy tracking value. recording min/max outside of hdr_histogram to avoid caps. increased per second rotated histogram precision

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)
 {

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.

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<float> quantile_list, struct hdr_histogram* latency_histogram, 
                           std::vector<unsigned int> timestamps, 
                           std::vector<one_sec_cmd_stats> 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,

run_stats_types.cpp

@@ -73,22 +73,22 @@ 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<float> 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<double>::lowest();
-    m_min_latency = has_samples ? (1.0 * hdr_min(histogram))/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : std::numeric_limits<double>::max();;
 }
 
 void one_sec_cmd_stats::update_op(unsigned int bytes_rx, unsigned int bytes_tx, unsigned int latency) {
     m_bytes_rx += bytes_rx;
     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);
 }

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