Ensuring we produce a valid JSON in case of empty string and -nan (#273)

* Ensuring we produce a valid JSON in case of empty string and -nan

* 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

* Added the latency test (command taking longer than 1 second) to CI

* Cleaned up test_valid_json_using_debug_command

* Ensuring that the per second metrics are numeric non negative

Author: filipecosta90

JSON_handler.cpp

@@ -22,7 +22,7 @@
 
 #include <stdlib.h>
 #include <string.h>
-
+#include <cmath>  // 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, ",");

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)
@@ -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<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);
-        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,