Skip to content

Commit

Permalink
Ensuring we produce a valid JSON in case of empty string and -nan (#273)
Browse files Browse the repository at this point in the history 
* 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
  • Loading branch information
@filipecosta90
filipecosta90 authored Nov 18, 2024
1 parent 0c0c440 commit d6bc71f
Show file tree
Hide file tree
Showing 8 changed files with 205 additions and 82 deletions.
36 changes: 34 additions & 2 deletions JSON_handler.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,7 @@

#include <stdlib.h>
#include <string.h>

#include <cmath> // For std::isnan
#include "JSON_handler.h"


Expand Down Expand Up @@ -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, ",");
Expand Down
6 changes: 6 additions & 0 deletions deps/hdr_histogram/hdr_histogram.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
{
Expand Down
12 changes: 12 additions & 0 deletions deps/hdr_histogram/hdr_histogram.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
106 changes: 62 additions & 44 deletions run_stats.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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)
Expand All @@ -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)
Expand All @@ -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,
Expand All @@ -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)
Expand All @@ -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)
Expand All @@ -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,
Expand All @@ -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)
Expand All @@ -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,
Expand All @@ -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)
Expand Down Expand Up @@ -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);

Expand All @@ -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
Expand All @@ -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++){
Expand Down Expand Up @@ -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,
Expand All @@ -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,
Expand All @@ -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,
Expand All @@ -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,
Expand All @@ -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,
Expand Down
Loading

0 comments on commit d6bc71f

Please sign in to comment.