/* * Copyright (C) 2011-2017 Redis Labs Ltd. * * This file is part of memtier_benchmark. * * memtier_benchmark is free software: you can redistribute it and/or modify * it under the terms of the GNU General Public License as published by * the Free Software Foundation, version 2. * * memtier_benchmark is distributed in the hope that it will be useful, * but WITHOUT ANY WARRANTY; without even the implied warranty of * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the * GNU General Public License for more details. * * You should have received a copy of the GNU General Public License * along with memtier_benchmark. If not, see . */ #ifdef HAVE_CONFIG_H #include "config.h" #endif #include #include #include #include #include #include #include #ifdef HAVE_ASSERT_H #include #endif #include "run_stats.h" #define MIN(a,b) (((a)<(b))?(a):(b)) #define MAX(a,b) (((a)>(b))?(a):(b)) void output_table::add_column(table_column& col) { assert(columns.empty() || columns[0].elements.size() == col.elements.size()); columns.push_back(col); } void output_table::print_header(FILE *out, const char * header) { if (header == NULL) return; fprintf(out, "\n\n"); fprintf(out, "%s\n", header); for (unsigned int i=0; itype) { case string_el: snprintf(buf, 100, el->format.c_str(), el->str_value.c_str()); break; case double_el: snprintf(buf, 100, el->format.c_str(), el->double_value); break; } line += buf; } fprintf(out, "%s\n", line.c_str()); } } /////////////////////////////////////////////////////////////////////////// inline unsigned long int ts_diff_now(struct timeval a) { struct timeval b; gettimeofday(&b, NULL); unsigned long long aval = a.tv_sec * 1000000 + a.tv_usec; unsigned long long bval = b.tv_sec * 1000000 + b.tv_usec; return bval - aval; } inline timeval timeval_factorial_average(timeval a, timeval b, unsigned int weight) { timeval tv; double factor = ((double)weight - 1) / weight; tv.tv_sec = factor * a.tv_sec + (double)b.tv_sec / weight ; tv.tv_usec = factor * a.tv_usec + (double)b.tv_usec / weight ; return (tv); } run_stats::run_stats(benchmark_config *config) : m_config(config), m_totals(), m_cur_stats(0) { memset(&m_start_time, 0, sizeof(m_start_time)); memset(&m_end_time, 0, sizeof(m_end_time)); hdr_init( LATENCY_HDR_MIN_VALUE, // Minimum value LATENCY_HDR_MAX_VALUE, // Maximum value LATENCY_HDR_SIGDIGTS, // Number of significant figures &m_get_latency_histogram); // Pointer to initialise hdr_init( LATENCY_HDR_MIN_VALUE, // Minimum value LATENCY_HDR_MAX_VALUE, // Maximum value LATENCY_HDR_SIGDIGTS, // Number of significant figures &m_set_latency_histogram); // Pointer to initialise hdr_init( LATENCY_HDR_MIN_VALUE, // Minimum value LATENCY_HDR_MAX_VALUE, // Maximum value LATENCY_HDR_SIGDIGTS, // Number of significant figures &m_wait_latency_histogram); // Pointer to initialise if (config->arbitrary_commands->is_defined()) { setup_arbitrary_commands(config->arbitrary_commands->size()); } } void run_stats::setup_arbitrary_commands(size_t n_arbitrary_commands) { m_totals.setup_arbitrary_commands(n_arbitrary_commands); m_cur_stats.setup_arbitrary_commands(n_arbitrary_commands); m_ar_commands_latency_histograms.resize(n_arbitrary_commands); for (unsigned int i=0; i m_cur_stats.m_second) { m_stats.push_back(m_cur_stats); m_cur_stats.reset(sec); } } void run_stats::update_get_op(struct timeval* ts, unsigned int bytes, unsigned int latency, unsigned int hits, unsigned int misses) { roll_cur_stats(ts); m_cur_stats.m_get_cmd.update_op(bytes, latency, hits, misses); m_totals.update_op(bytes, latency); hdr_record_value(m_get_latency_histogram,latency); } void run_stats::update_set_op(struct timeval* ts, unsigned int bytes, unsigned int latency) { roll_cur_stats(ts); m_cur_stats.m_set_cmd.update_op(bytes, latency); m_totals.update_op(bytes, latency); hdr_record_value(m_set_latency_histogram,latency); } void run_stats::update_moved_get_op(struct timeval* ts, unsigned int bytes, unsigned int latency) { roll_cur_stats(ts); m_cur_stats.m_get_cmd.update_moved_op(bytes, latency); m_totals.update_op(bytes, latency); hdr_record_value(m_get_latency_histogram,latency); } void run_stats::update_moved_set_op(struct timeval* ts, unsigned int bytes, unsigned int latency) { roll_cur_stats(ts); m_cur_stats.m_set_cmd.update_moved_op(bytes, latency); m_totals.update_op(bytes, latency); hdr_record_value(m_set_latency_histogram,latency); } void run_stats::update_ask_get_op(struct timeval* ts, unsigned int bytes, unsigned int latency) { roll_cur_stats(ts); m_cur_stats.m_get_cmd.update_ask_op(bytes, latency); m_totals.update_op(bytes, latency); hdr_record_value(m_get_latency_histogram,latency); } void run_stats::update_ask_set_op(struct timeval* ts, unsigned int bytes, unsigned int latency) { roll_cur_stats(ts); m_cur_stats.m_set_cmd.update_ask_op(bytes, latency); m_totals.update_op(bytes, latency); hdr_record_value(m_set_latency_histogram,latency); } void run_stats::update_wait_op(struct timeval *ts, unsigned int latency) { roll_cur_stats(ts); m_cur_stats.m_wait_cmd.update_op(0, latency); m_totals.update_op(0, latency); hdr_record_value(m_wait_latency_histogram,latency); } void run_stats::update_arbitrary_op(struct timeval *ts, unsigned int bytes, unsigned int latency, size_t request_index) { roll_cur_stats(ts); m_cur_stats.m_ar_commands.at(request_index).update_op(bytes, latency); m_totals.update_op(bytes, latency); struct hdr_histogram* hist = m_ar_commands_latency_histograms.at(request_index); hdr_record_value(hist,latency); } unsigned int run_stats::get_duration(void) { return m_cur_stats.m_second; } unsigned long int run_stats::get_duration_usec(void) { if (!m_start_time.tv_sec) return 0; if (m_end_time.tv_sec > 0) { return ts_diff(m_start_time, m_end_time); } else { return ts_diff_now(m_start_time); } } unsigned long int run_stats::get_total_bytes(void) { return m_totals.m_bytes; } unsigned long int run_stats::get_total_ops(void) { return m_totals.m_ops; } unsigned long int run_stats::get_total_latency(void) { return m_totals.m_latency; } #define AVERAGE(total, count) \ ((unsigned int) ((count) > 0 ? (total) / (count) : 0)) #define USEC_FORMAT(value) \ (value) / 1000000, (value) % 1000000 void run_stats::save_csv_one_sec(FILE *f, unsigned long int& total_get_ops, unsigned long int& total_set_ops, unsigned long int& total_wait_ops) { fprintf(f, "Per-Second Benchmark Data\n"); fprintf(f, "Second,SET Requests,SET Average Latency,SET Total Bytes," "GET Requests,GET Average Latency,GET Total Bytes,GET Misses,GET Hits," "WAIT Requests,WAIT Average Latency\n"); total_get_ops = 0; total_set_ops = 0; total_wait_ops = 0; for (std::vector::iterator i = m_stats.begin(); i != m_stats.end(); i++) { fprintf(f, "%u,%lu,%u.%06u,%lu,%lu,%u.%06u,%lu,%u,%u,%lu,%u.%06u\n", i->m_second, i->m_set_cmd.m_ops, USEC_FORMAT(AVERAGE(i->m_set_cmd.m_total_latency, i->m_set_cmd.m_ops)), i->m_set_cmd.m_bytes, i->m_get_cmd.m_ops, USEC_FORMAT(AVERAGE(i->m_get_cmd.m_total_latency, i->m_get_cmd.m_ops)), i->m_get_cmd.m_bytes, i->m_get_cmd.m_misses, i->m_get_cmd.m_hits, i->m_wait_cmd.m_ops, USEC_FORMAT(AVERAGE(i->m_wait_cmd.m_total_latency, i->m_wait_cmd.m_ops))); total_set_ops += i->m_set_cmd.m_ops; total_get_ops += i->m_get_cmd.m_ops; total_wait_ops += i->m_wait_cmd.m_ops; } } std::vector run_stats::get_one_sec_cmd_stats_get() { std::vector result; result.reserve(m_stats.size()); for (std::vector::iterator i = m_stats.begin(); i != m_stats.end(); i++) { result.push_back(i->m_get_cmd); } return result; } std::vector run_stats::get_one_sec_cmd_stats_set() { std::vector result; result.reserve(m_stats.size()); for (std::vector::iterator i = m_stats.begin(); i != m_stats.end(); i++) { result.push_back(i->m_set_cmd); } return result; } std::vector run_stats::get_one_sec_cmd_stats_wait() { std::vector result; result.reserve(m_stats.size()); for (std::vector::iterator i = m_stats.begin(); i != m_stats.end(); i++) { result.push_back(i->m_wait_cmd); } return result; } std::vector run_stats::get_one_sec_cmd_stats_totals() { std::vector result; result.reserve(m_stats.size()); for (size_t i = 0; i < m_stats.size(); i++) { one_second_stats current_second_stats = m_stats.at(i); one_sec_cmd_stats total_stat = one_sec_cmd_stats(current_second_stats.m_get_cmd); total_stat.merge(current_second_stats.m_set_cmd); total_stat.merge(current_second_stats.m_wait_cmd); for (size_t j = 0; j < current_second_stats.m_ar_commands.size(); j++) { total_stat.merge(current_second_stats.m_ar_commands.at(j)); } result.push_back(total_stat); } return result; } std::vector run_stats::get_one_sec_cmd_stats_arbitrary_command( unsigned int pos ){ std::vector result; result.reserve(m_stats.size()); for (std::vector::iterator i = m_stats.begin(); i != m_stats.end(); i++) { result.push_back(i->m_ar_commands.at(pos)); } return result; } std::vector run_stats::get_one_sec_cmd_stats_timestamp() { std::vector result; result.reserve(m_stats.size()); for (std::vector::iterator i = m_stats.begin(); i != m_stats.end(); i++) { result.push_back(i->m_second); } return result; } void run_stats::save_csv_one_sec_cluster(FILE *f) { fprintf(f, "\nPer-Second Benchmark Cluster Data\n"); fprintf(f, "Second,SET Moved,SET Ask,GET Moved,GET Ask\n"); for (std::vector::iterator i = m_stats.begin(); i != m_stats.end(); i++) { fprintf(f, "%u,%u,%u,%u,%u\n", i->m_second, i->m_set_cmd.m_moved, i->m_set_cmd.m_ask, i->m_get_cmd.m_moved, i->m_get_cmd.m_ask); } } void run_stats::save_csv_set_get_commands(FILE *f, bool cluster_mode) { unsigned long int total_get_ops; unsigned long int total_set_ops; unsigned long int total_wait_ops; // save per second data save_csv_one_sec(f, total_get_ops, total_set_ops, total_wait_ops); // save latency data fprintf(f, "\n" "Full-Test GET Latency\n"); fprintf(f, "Latency (<= msec),Percent\n"); struct hdr_iter iter; struct hdr_iter_percentiles * percentiles; hdr_iter_percentile_init(&iter, m_get_latency_histogram, LATENCY_HDR_GRANULARITY); percentiles = &iter.specifics.percentiles; while (hdr_iter_next(&iter)){ double value = iter.highest_equivalent_value / (double) LATENCY_HDR_RESULTS_MULTIPLIER; fprintf(f, "%8.3f,%.2f\n", value,percentiles->percentile); } fprintf(f, "\n" "Full-Test SET Latency\n"); fprintf(f, "Latency (<= msec),Percent\n"); hdr_iter_percentile_init(&iter, m_set_latency_histogram, LATENCY_HDR_GRANULARITY); percentiles = &iter.specifics.percentiles; while (hdr_iter_next(&iter)){ double value = iter.highest_equivalent_value / (double) LATENCY_HDR_RESULTS_MULTIPLIER; fprintf(f, "%8.3f,%.2f\n", value,percentiles->percentile); } fprintf(f, "\n" "Full-Test WAIT Latency\n"); fprintf(f, "Latency (<= msec),Percent\n"); hdr_iter_percentile_init(&iter, m_wait_latency_histogram, LATENCY_HDR_GRANULARITY); percentiles = &iter.specifics.percentiles; while (hdr_iter_next(&iter)){ double value = iter.highest_equivalent_value / (double) LATENCY_HDR_RESULTS_MULTIPLIER; fprintf(f, "%8.3f,%.2f\n", value,percentiles->percentile); } // cluster mode data if (cluster_mode) { save_csv_one_sec_cluster(f); } } void run_stats::save_csv_arbitrary_commands_one_sec(FILE *f, arbitrary_command_list& command_list, std::vector& total_arbitrary_commands_ops) { fprintf(f, "Per-Second Benchmark Arbitrary Commands Data\n"); // print header fprintf(f, "Second"); for (unsigned int i=0; i::iterator stat = m_stats.begin(); stat != m_stats.end(); stat++) { fprintf(f, "%u,", stat->m_second); for (unsigned int i=0; im_ar_commands.size(); i++) { one_sec_cmd_stats& arbitrary_command_stats = stat->m_ar_commands[i]; fprintf(f, "%lu,%u.%06u,%lu,", arbitrary_command_stats.m_ops, USEC_FORMAT(AVERAGE(arbitrary_command_stats.m_total_latency, arbitrary_command_stats.m_ops)), arbitrary_command_stats.m_bytes); total_arbitrary_commands_ops.at(i) += arbitrary_command_stats.m_ops; } fprintf(f, "\n"); } } void run_stats::save_csv_arbitrary_commands(FILE *f, arbitrary_command_list& command_list) { std::vector total_arbitrary_commands_ops(command_list.size()); // save per second data save_csv_arbitrary_commands_one_sec(f, command_list, total_arbitrary_commands_ops); // save latency data for (unsigned int i=0; ipercentile); } } } bool run_stats::save_hdr_percentiles_print_format(struct hdr_histogram* hdr, char* filename){ bool result = false; if(hdr_total_count( hdr )>0){ // Prepare output file FILE *hdr_outfile; hdr_outfile = fopen(filename, "w"); if (!hdr_outfile){ perror(filename); return result; } hdr_percentiles_print( hdr, hdr_outfile, // File to write to LATENCY_HDR_GRANULARITY, // Granularity of printed values LATENCY_HDR_RESULTS_MULTIPLIER, // Multiplier for results CLASSIC); // Format CLASSIC/CSV supported. fclose(hdr_outfile); result=true; } return result; } bool run_stats::save_hdr_log_format(struct hdr_histogram* hdr, char* filename, char* header){ bool result = false; if(hdr_total_count( hdr )>0){ // Prepare output file FILE *hdr_outfile; struct timespec start_timespec; struct timespec end_timespec; TIMEVAL_TO_TIMESPEC(&m_start_time, &start_timespec); TIMEVAL_TO_TIMESPEC(&m_end_time, &end_timespec); hdr_outfile = fopen(filename, "w"); if (!hdr_outfile){ perror(filename); return result; } struct hdr_log_writer w; hdr_log_writer_init(&w); hdr_log_write_header(&w, hdr_outfile, header, &start_timespec); hdr_log_write(&w, hdr_outfile, &start_timespec, &end_timespec, hdr); fclose(hdr_outfile); result = true; } return result; } bool run_stats::save_hdr_full_run(benchmark_config *config,int run_number){ if (strcmp(config->hdr_prefix,"") && (hdr_total_count( m_totals.latency_histogram )>0) ){ // Prepare output file char fmtbuf[1024]; snprintf(fmtbuf, sizeof(fmtbuf) - 1, "%s_FULL_RUN_%d.txt", config->hdr_prefix, run_number); fprintf(stderr, "Writing Full Run command HDR latency histogram results to %s...\n", fmtbuf); save_hdr_percentiles_print_format(m_totals.latency_histogram,fmtbuf); snprintf(fmtbuf, sizeof(fmtbuf) - 1, "%s_FULL_RUN_%d.hgrm", config->hdr_prefix, run_number); fprintf(stderr, "Writing Full Run command HDR latency histogram results in HistogramLogProcessor format to %s...\n", fmtbuf); save_hdr_log_format(m_totals.latency_histogram,fmtbuf,(char*)"Full Run command HDR latency histogram results"); } return true; } bool run_stats::save_hdr_set_command(benchmark_config *config,int run_number) { if (strcmp(config->hdr_prefix,"") && (hdr_total_count( m_set_latency_histogram )>0) ){ // Prepare output file char fmtbuf[1024]; snprintf(fmtbuf, sizeof(fmtbuf) - 1, "%s_SET_command_run_%d.txt", config->hdr_prefix, run_number); fprintf(stderr, "Writing SET command HDR latency histogram results to %s...\n", fmtbuf); save_hdr_percentiles_print_format(m_set_latency_histogram,fmtbuf); snprintf(fmtbuf, sizeof(fmtbuf) - 1, "%s_SET_command_run_%d.hgrm", config->hdr_prefix, run_number); fprintf(stderr, "Writing SET command HDR latency histogram results in HistogramLogProcessor format to %s...\n", fmtbuf); save_hdr_log_format(m_set_latency_histogram,fmtbuf,(char*)"SET command HDR latency histogram results"); } return true; } bool run_stats::save_hdr_get_command(benchmark_config *config, int run_number){ if (strcmp(config->hdr_prefix,"") && (hdr_total_count( m_get_latency_histogram )>0) ){ // Prepare output file char fmtbuf[1024]; snprintf(fmtbuf, sizeof(fmtbuf) - 1, "%s_GET_command_run_%d.txt", config->hdr_prefix, run_number); fprintf(stderr, "Writing GET command HDR latency histogram results to %s...\n", fmtbuf); save_hdr_percentiles_print_format(m_get_latency_histogram,fmtbuf); snprintf(fmtbuf, sizeof(fmtbuf) - 1, "%s_GET_command_run_%d.hgrm", config->hdr_prefix, run_number); fprintf(stderr, "Writing GET command HDR latency histogram results in HistogramLogProcessor format to %s...\n", fmtbuf); save_hdr_log_format(m_get_latency_histogram,fmtbuf,(char*)"GET command HDR latency histogram results"); } return true; } bool run_stats::save_hdr_arbitrary_commands(benchmark_config *config,int run_number) { // save latency datacommand_list if (strcmp(config->hdr_prefix,"")) { arbitrary_command_list& command_list = *config->arbitrary_commands; for (unsigned int i=0; ihdr_prefix, command_name.c_str(),run_number); fprintf(stderr, "Writing %s command HDR latency histogram results to %s...\n", command_name.c_str(), fmtbuf); save_hdr_percentiles_print_format(hist,fmtbuf); snprintf(fmtbuf, sizeof(fmtbuf) - 1, "%s_%s_command_run_%d.hgrm", config->hdr_prefix, command_name.c_str(), run_number); fprintf(stderr, "Writing %s command HDR latency histogram results in HistogramLogProcessor format to %s...\n", command_name.c_str(), fmtbuf); char header[1024]; snprintf(header, sizeof(header) - 1, "%s command HDR latency histogram results", command_name.c_str()); save_hdr_log_format(hist,fmtbuf,header); } } return true; } bool run_stats::save_csv(const char *filename, benchmark_config *config) { FILE *f = fopen(filename, "w"); if (!f) { perror(filename); return false; } if (print_arbitrary_commands_results()) { save_csv_arbitrary_commands(f, *config->arbitrary_commands); } else { save_csv_set_get_commands(f, config->cluster_mode); } fclose(f); return true; } void run_stats::debug_dump(void) { benchmark_debug_log("run_stats: start_time={%u,%u} end_time={%u,%u}\n", m_start_time.tv_sec, m_start_time.tv_usec, m_end_time.tv_sec, m_end_time.tv_usec); for (std::vector::iterator i = m_stats.begin(); i != m_stats.end(); i++) { benchmark_debug_log(" %u: get latency=%u.%ums, set latency=%u.%ums, wait latency=%u.%ums" "m_ops_set/get/wait=%u/%u/%u, m_bytes_set/get=%u/%u, m_get_hit/miss=%u/%u\n", i->m_second, USEC_FORMAT(AVERAGE(i->m_get_cmd.m_total_latency, i->m_get_cmd.m_ops)), USEC_FORMAT(AVERAGE(i->m_set_cmd.m_total_latency, i->m_set_cmd.m_ops)), USEC_FORMAT(AVERAGE(i->m_wait_cmd.m_total_latency, i->m_wait_cmd.m_ops)), i->m_set_cmd.m_ops, i->m_get_cmd.m_ops, i->m_wait_cmd.m_ops, i->m_set_cmd.m_bytes, i->m_get_cmd.m_bytes, i->m_get_cmd.m_hits, i->m_get_cmd.m_misses); } } bool one_second_stats_predicate(const one_second_stats& a, const one_second_stats& b) { return a.m_second < b.m_second; } void run_stats::aggregate_average(const std::vector& all_stats) { for (std::vector::const_iterator i = all_stats.begin(); i != all_stats.end(); i++) { totals i_totals; i_totals.setup_arbitrary_commands(m_totals.m_ar_commands.size()); i->summarize(i_totals); m_totals.add(i_totals); // aggregate latency data hdr_add(m_get_latency_histogram,i->m_get_latency_histogram); hdr_add(m_set_latency_histogram,i->m_set_latency_histogram); hdr_add(m_wait_latency_histogram,i->m_wait_latency_histogram); for (unsigned int j=0; j < i->m_ar_commands_latency_histograms.size(); j++) { hdr_add(m_ar_commands_latency_histograms.at(j),i->m_ar_commands_latency_histograms.at(j)); } } m_totals.m_set_cmd.aggregate_average(all_stats.size()); m_totals.m_get_cmd.aggregate_average(all_stats.size()); m_totals.m_wait_cmd.aggregate_average(all_stats.size()); m_totals.m_ar_commands.aggregate_average(all_stats.size()); m_totals.m_ops_sec /= all_stats.size(); m_totals.m_hits_sec /= all_stats.size(); m_totals.m_misses_sec /= all_stats.size(); m_totals.m_moved_sec /= all_stats.size(); m_totals.m_ask_sec /= all_stats.size(); m_totals.m_bytes_sec /= all_stats.size(); m_totals.m_latency /= all_stats.size(); } void run_stats::merge(const run_stats& other, int iteration) { bool new_stats = false; m_start_time = timeval_factorial_average( m_start_time, other.m_start_time, iteration ); m_end_time = timeval_factorial_average( m_end_time, other.m_end_time, iteration ); // aggregate the one_second_stats vectors. this is not efficient // but it's not really important (small numbers, not realtime) for (std::vector::const_iterator other_i = other.m_stats.begin(); other_i != other.m_stats.end(); other_i++) { // find ours bool merged = false; for (std::vector::iterator i = m_stats.begin(); i != m_stats.end(); i++) { if (i->m_second == other_i->m_second) { i->merge(*other_i); merged = true; break; } } if (!merged) { m_stats.push_back(*other_i); new_stats = true; } } if (new_stats) { sort(m_stats.begin(), m_stats.end(), one_second_stats_predicate); } // aggregate totals m_totals.add(other.m_totals); // aggregate latency data // hdr_add(m_totals.latency_histogram,other.m_totals.latency_histogram); hdr_add(m_get_latency_histogram,other.m_get_latency_histogram); hdr_add(m_set_latency_histogram,other.m_set_latency_histogram); hdr_add(m_wait_latency_histogram,other.m_wait_latency_histogram); for (unsigned int j=0; j < other.m_ar_commands_latency_histograms.size(); j++) { hdr_add(m_ar_commands_latency_histograms.at(j),other.m_ar_commands_latency_histograms.at(j)); } } void run_stats::summarize(totals& result) const { // aggregate all one_second_stats one_second_stats totals(0); totals.setup_arbitrary_commands(m_cur_stats.m_ar_commands.size()); for (std::vector::const_iterator i = m_stats.begin(); i != m_stats.end(); i++) { totals.merge(*i); } unsigned long int test_duration_usec = ts_diff(m_start_time, m_end_time); // total ops, bytes result.m_ops = totals.m_set_cmd.m_ops + totals.m_get_cmd.m_ops + totals.m_wait_cmd.m_ops + totals.m_ar_commands.ops(); result.m_bytes = totals.m_set_cmd.m_bytes + totals.m_get_cmd.m_bytes + totals.m_ar_commands.bytes(); // cmd/sec result.m_set_cmd.summarize(totals.m_set_cmd, test_duration_usec); result.m_get_cmd.summarize(totals.m_get_cmd, test_duration_usec); result.m_wait_cmd.summarize(totals.m_wait_cmd, test_duration_usec); result.m_ar_commands.summarize(totals.m_ar_commands, test_duration_usec); // hits,misses / sec result.m_hits_sec = (double) totals.m_get_cmd.m_hits / test_duration_usec * 1000000; result.m_misses_sec = (double) totals.m_get_cmd.m_misses / test_duration_usec * 1000000; // total/sec result.m_ops_sec = (double) result.m_ops / test_duration_usec * 1000000; if (result.m_ops > 0) { result.m_latency = (double) ((totals.m_set_cmd.m_total_latency + totals.m_get_cmd.m_total_latency + totals.m_wait_cmd.m_total_latency + totals.m_ar_commands.total_latency()) / result.m_ops) / 1000; } else { result.m_latency = 0; } result.m_bytes_sec = (result.m_bytes / 1024.0) / test_duration_usec * 1000000; result.m_moved_sec = (double) (totals.m_set_cmd.m_moved + totals.m_get_cmd.m_moved) / test_duration_usec * 1000000; 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, double hits, double miss, double moved, double ask, double kbs, 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("Hits/sec","%.2f", hits); jsonhandler->write_obj("Misses/sec","%.2f", miss); if (moved >= 0) jsonhandler->write_obj("MOVED/sec","%.2f", moved); if (ask >= 0) 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; // to be retrocompatible jsonhandler->write_obj("Latency","%.3f", avg_latency); jsonhandler->write_obj("Average Latency","%.3f", avg_latency); jsonhandler->write_obj("Min Latency","%.3f", min_latency); jsonhandler->write_obj("Max Latency","%.3f", max_latency); jsonhandler->write_obj("KB/sec","%.2f", kbs); jsonhandler->open_nesting("Time-Serie"); for (std::size_t i = 0; i < timeserie_stats.size(); i++){ char timestamp_str[16]; one_sec_cmd_stats cmd_stats = timeserie_stats[i]; const unsigned int timestamp = timestamps[i]; const bool sec_has_samples = hdr_total_count(cmd_stats.latency_histogram)>0; const double sec_avg_latency = sec_has_samples ? hdr_mean(cmd_stats.latency_histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : 0.0; const double sec_min_latency = has_samples ? hdr_min(cmd_stats.latency_histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : 0.0; const double sec_max_latency = has_samples ? hdr_max(cmd_stats.latency_histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER : 0.0; snprintf(timestamp_str,sizeof(timestamp_str)-1,"%d", timestamp); jsonhandler->open_nesting(timestamp_str); jsonhandler->write_obj("Count","%lld", hdr_total_count(cmd_stats.latency_histogram)); jsonhandler->write_obj("Average Latency","%.2f", sec_avg_latency); jsonhandler->write_obj("Min Latency","%.2f", sec_min_latency); jsonhandler->write_obj("Max Latency","%.2f", sec_max_latency); for (std::size_t i = 0; i < quantile_list.size(); i++){ const float quantile = quantile_list[i]; char quantile_header[8]; snprintf(quantile_header,sizeof(quantile_header)-1,"p%.2f", quantile); const double value = hdr_value_at_percentile(cmd_stats.latency_histogram, quantile )/ (double) LATENCY_HDR_RESULTS_MULTIPLIER; jsonhandler->write_obj((char *)quantile_header,"%.2f", value); } jsonhandler->close_nesting(); } jsonhandler->close_nesting(); jsonhandler->open_nesting("Percentile Latencies"); for (std::size_t i = 0; i < quantile_list.size(); i++){ const float quantile = quantile_list[i]; char quantile_header[8]; snprintf(quantile_header,sizeof(quantile_header)-1,"p%.3f", quantile); const double value = hdr_value_at_percentile(latency_histogram, quantile )/ (double) LATENCY_HDR_RESULTS_MULTIPLIER; jsonhandler->write_obj((char *)quantile_header,"%.3f", value); } jsonhandler->open_nesting("Histogram log format"); char* encoded_histogram; hdr_string_write(&encoded_histogram,latency_histogram); jsonhandler->write_obj("Compressed Histogram","\"%s\"", encoded_histogram); free(encoded_histogram); jsonhandler->close_nesting(); jsonhandler->close_nesting(); jsonhandler->close_nesting(); } } void histogram_print(FILE * out, json_handler * jsonhandler, const char * type, float msec, float percent) { fprintf(out, "%-6s %8.3f %12.2f\n", type, msec, percent); if (jsonhandler != NULL){ jsonhandler->open_nesting(NULL); jsonhandler->write_obj("<=msec","%.3f", msec); jsonhandler->write_obj("percent","%.2f", percent); jsonhandler->close_nesting(); } } bool run_stats::print_arbitrary_commands_results() { return m_totals.m_ar_commands.size() > 0; } void run_stats::print_type_column(output_table &table, arbitrary_command_list& command_list) { table_el el; table_column column; // Type column column.column_size = MAX(6, command_list.get_max_command_name_length()) + 1; assert(column.column_size < 100 && "command name too long"); // set enough space according to size of command name char buf[200]; snprintf(buf, sizeof(buf), "%%-%us ", column.column_size); std::string type_col_format(buf); memset(buf, '-', column.column_size + 1); buf[column.column_size + 1] = '\0'; column.elements.push_back(*el.init_str(type_col_format, "Type")); column.elements.push_back(*el.init_str("%s", buf)); if (print_arbitrary_commands_results()) { for (unsigned int i=0; i(toupper(command_name[0])); command_name.append("s"); column.elements.push_back(*el.init_str(type_col_format, command_name)); } } else { column.elements.push_back(*el.init_str(type_col_format, "Sets")); column.elements.push_back(*el.init_str(type_col_format, "Gets")); column.elements.push_back(*el.init_str(type_col_format, "Waits")); } column.elements.push_back(*el.init_str(type_col_format, "Totals")); table.add_column(column); } void run_stats::print_ops_sec_column(output_table &table) { table_el el; table_column column(12); column.elements.push_back(*el.init_str("%12s ", "Ops/sec")); column.elements.push_back(*el.init_str("%s", "-------------")); if (print_arbitrary_commands_results()) { for (unsigned int i=0; i 0; const bool has_get_ops = hdr_total_count(m_get_latency_histogram) > 0; const bool has_wait_ops = hdr_total_count(m_wait_latency_histogram) > 0; if(has_set_ops){ column.elements.push_back(*el.init_double("%15.05f ", hdr_mean(m_set_latency_histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER)); } else { column.elements.push_back(*el.init_str("%15s ", "---")); } if(has_get_ops){ column.elements.push_back(*el.init_double("%15.05f ", hdr_mean(m_get_latency_histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER)); } else { column.elements.push_back(*el.init_str("%15s ", "---")); } if(has_wait_ops){ column.elements.push_back(*el.init_double("%15.05f ", hdr_mean(m_wait_latency_histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER)); } else { column.elements.push_back(*el.init_str("%15s ", "---")); } } column.elements.push_back(*el.init_double("%15.05f ", hdr_mean(m_totals_latency_histogram)/ (double) LATENCY_HDR_RESULTS_MULTIPLIER)); table.add_column(column); } void run_stats::print_quantile_latency_column(output_table &table, double quantile, char* label) { table_el el; table_column column(15); struct hdr_histogram* m_totals_latency_histogram; hdr_init( LATENCY_HDR_MIN_VALUE, // Minimum value LATENCY_HDR_MAX_VALUE, // Maximum value LATENCY_HDR_SIGDIGTS, // Number of significant figures &m_totals_latency_histogram); // Pointer to initialise hdr_add(m_totals_latency_histogram,m_set_latency_histogram); hdr_add(m_totals_latency_histogram,m_get_latency_histogram); hdr_add(m_totals_latency_histogram,m_wait_latency_histogram); column.elements.push_back(*el.init_str("%15s ", label )); column.elements.push_back(*el.init_str("%s", "----------------")); if (print_arbitrary_commands_results()) { for (unsigned int i=0; i 0; const bool has_get_ops = hdr_total_count(m_get_latency_histogram) > 0; const bool has_wait_ops = hdr_total_count(m_wait_latency_histogram) > 0; if(has_set_ops){ column.elements.push_back(*el.init_double("%15.05f ", hdr_value_at_percentile(m_set_latency_histogram, quantile )/ (double) LATENCY_HDR_RESULTS_MULTIPLIER)); } else { column.elements.push_back(*el.init_str("%15s ", "---")); } if(has_get_ops){ column.elements.push_back(*el.init_double("%15.05f ", hdr_value_at_percentile(m_get_latency_histogram, quantile )/ (double) LATENCY_HDR_RESULTS_MULTIPLIER)); } else { column.elements.push_back(*el.init_str("%15s ", "---")); } if(has_wait_ops){ column.elements.push_back(*el.init_double("%15.05f ", hdr_value_at_percentile(m_wait_latency_histogram, quantile )/ (double) LATENCY_HDR_RESULTS_MULTIPLIER)); } else { column.elements.push_back(*el.init_str("%15s ", "---")); } } column.elements.push_back(*el.init_double("%15.05f ", hdr_value_at_percentile(m_totals_latency_histogram, quantile )/ (double) LATENCY_HDR_RESULTS_MULTIPLIER)); table.add_column(column); } void run_stats::print_kb_sec_column(output_table &table) { table_el el; table_column column(12); column.elements.push_back(*el.init_str("%12s ", "KB/sec")); column.elements.push_back(*el.init_str("%s", "-------------")); if (print_arbitrary_commands_results()) { for (unsigned int i=0; i quantile_list) { if (jsonhandler != NULL){ // Added for double verification in case someone accidently send NULL. jsonhandler->open_nesting("Runtime"); const unsigned long long start_time_ms = (m_start_time.tv_sec * 1000000 + m_start_time.tv_usec)/1000; const unsigned long long end_time_ms = (m_end_time.tv_sec * 1000000 + m_end_time.tv_usec)/1000; jsonhandler->write_obj("Start time","%lld", start_time_ms); jsonhandler->write_obj("Finish time","%lld", end_time_ms); jsonhandler->write_obj("Total duration","%lld", end_time_ms-start_time_ms); jsonhandler->write_obj("Time unit","\"%s\"","MILLISECONDS"); jsonhandler->close_nesting(); } std::vector timestamps = get_one_sec_cmd_stats_timestamp(); if (print_arbitrary_commands_results()) { for (unsigned int i=0; i(toupper(command_name[0])); command_name.append("s"); struct hdr_histogram* arbitrary_command_latency_histogram = m_ar_commands_latency_histograms.at(i); std::vector arbitrary_command_stats = get_one_sec_cmd_stats_arbitrary_command(i); result_print_to_json(jsonhandler, command_name.c_str(), m_totals.m_ar_commands[i].m_ops_sec, 0.0, 0.0, cluster_mode ? m_totals.m_ar_commands[i].m_moved_sec : -1, cluster_mode ? m_totals.m_ar_commands[i].m_ask_sec : -1, m_totals.m_ar_commands[i].m_bytes_sec, quantile_list, arbitrary_command_latency_histogram, timestamps, arbitrary_command_stats ); } } else { std::vector get_stats = get_one_sec_cmd_stats_get(); std::vector set_stats = get_one_sec_cmd_stats_set(); std::vector wait_stats = get_one_sec_cmd_stats_wait(); result_print_to_json(jsonhandler, "Sets",m_totals.m_set_cmd.m_ops_sec, 0.0, 0.0, cluster_mode ? m_totals.m_set_cmd.m_moved_sec : -1, cluster_mode ? m_totals.m_set_cmd.m_ask_sec : -1, m_totals.m_set_cmd.m_bytes_sec, quantile_list, m_set_latency_histogram, timestamps, set_stats ); result_print_to_json(jsonhandler,"Gets",m_totals.m_get_cmd.m_ops_sec, m_totals.m_hits_sec, m_totals.m_misses_sec, cluster_mode ? m_totals.m_get_cmd.m_moved_sec : -1, cluster_mode ? m_totals.m_get_cmd.m_ask_sec : -1, m_totals.m_get_cmd.m_bytes_sec, quantile_list, m_get_latency_histogram, timestamps, get_stats ); result_print_to_json(jsonhandler,"Waits",m_totals.m_wait_cmd.m_ops_sec, 0.0, 0.0, cluster_mode ? 0.0 : -1, cluster_mode ? 0.0 : -1, 0.0, quantile_list, m_wait_latency_histogram, timestamps, wait_stats ); } std::vector total_stats = get_one_sec_cmd_stats_totals(); result_print_to_json(jsonhandler,"Totals",m_totals.m_ops_sec, m_totals.m_hits_sec, m_totals.m_misses_sec, cluster_mode ? m_totals.m_moved_sec : -1, cluster_mode ? m_totals.m_ask_sec : -1, m_totals.m_bytes_sec, quantile_list, m_totals.latency_histogram, timestamps, total_stats ); } void run_stats::print_histogram(FILE *out, json_handler *jsonhandler, arbitrary_command_list& command_list) { fprintf(out, "\n\n" "Request Latency Distribution\n" "%-6s %12s %12s\n" "------------------------------------------------------------------------\n", "Type", "<= msec ", "Percent"); struct hdr_iter iter; struct hdr_iter_percentiles * percentiles; if (print_arbitrary_commands_results()) { for (unsigned int i = 0; i < command_list.size(); i++) { std::string command_name = command_list[i].command_name; if (jsonhandler != NULL) { jsonhandler->open_nesting(command_name.c_str(), NESTED_ARRAY); } struct hdr_histogram* arbitrary_command_latency_histogram = m_ar_commands_latency_histograms.at(i); hdr_iter_percentile_init(&iter, arbitrary_command_latency_histogram, LATENCY_HDR_GRANULARITY); percentiles = &iter.specifics.percentiles; while (hdr_iter_next(&iter)){ double value = iter.highest_equivalent_value / (double) LATENCY_HDR_RESULTS_MULTIPLIER; histogram_print(out, jsonhandler, command_name.c_str(), value,percentiles->percentile); } if (jsonhandler != NULL) { jsonhandler->close_nesting(); } fprintf(out, "---\n"); } } else { // SETs // ---- if (jsonhandler != NULL){ jsonhandler->open_nesting("SET",NESTED_ARRAY);} hdr_iter_percentile_init(&iter, m_set_latency_histogram, LATENCY_HDR_GRANULARITY); percentiles = &iter.specifics.percentiles; while (hdr_iter_next(&iter)) { double value = iter.highest_equivalent_value / (double) LATENCY_HDR_RESULTS_MULTIPLIER; histogram_print(out, jsonhandler, "SET", value,percentiles->percentile); } if (jsonhandler != NULL){ jsonhandler->close_nesting();} fprintf(out, "---\n"); // GETs // ---- if (jsonhandler != NULL){ jsonhandler->open_nesting("GET",NESTED_ARRAY);} hdr_iter_percentile_init(&iter, m_get_latency_histogram, LATENCY_HDR_GRANULARITY); percentiles = &iter.specifics.percentiles; while (hdr_iter_next(&iter)) { double value = iter.highest_equivalent_value / (double) LATENCY_HDR_RESULTS_MULTIPLIER; histogram_print(out, jsonhandler, "GET", value,percentiles->percentile); } if (jsonhandler != NULL){ jsonhandler->close_nesting();} fprintf(out, "---\n"); // WAITs // ---- if (jsonhandler != NULL){ jsonhandler->open_nesting("WAIT",NESTED_ARRAY);} hdr_iter_percentile_init(&iter, m_wait_latency_histogram, LATENCY_HDR_GRANULARITY); percentiles = &iter.specifics.percentiles; while (hdr_iter_next(&iter)) { double value = iter.highest_equivalent_value / (double) LATENCY_HDR_RESULTS_MULTIPLIER; histogram_print(out, jsonhandler, "WAIT", value,percentiles->percentile); } if (jsonhandler != NULL){ jsonhandler->close_nesting();} } } void run_stats::print(FILE *out, benchmark_config *config, const char * header/*=NULL*/, json_handler * jsonhandler/*=NULL*/) { // aggregate all one_second_stats; we do this only if we have // one_second_stats, otherwise it means we're probably printing previously // aggregated data if (m_stats.size() > 0) { summarize(m_totals); } output_table table; // Type column print_type_column(table, *config->arbitrary_commands); // Ops/sec column print_ops_sec_column(table); // Hits/sec column (not relevant for arbitrary commands) if (!print_arbitrary_commands_results()) { print_hits_sec_column(table); } // Misses/sec column (not relevant for arbitrary commands) if (!print_arbitrary_commands_results()) { print_missess_sec_column(table); } // Moved & ASK column (relevant only for cluster mode) if (config->cluster_mode) { print_moved_sec_column(table); print_ask_sec_column(table); } // Latency column print_avg_latency_column(table); for (std::size_t i = 0; i < config->print_percentiles.quantile_list.size(); i++){ float quantile = config->print_percentiles.quantile_list[i]; char average_header[50]; int ndigts = 0; float num = abs(quantile); num = num - int(num); while (abs(num)>0.001 && ndigts < 3 ) { num = num * 10; ndigts++; num = num - int(num); } snprintf(average_header,sizeof(average_header)-1,"p%.*f Latency", ndigts, quantile); print_quantile_latency_column(table,quantile,(char *)average_header); } // KB/sec column print_kb_sec_column(table); // print results table.print(out, header); //////////////////////////////////////// // JSON print handling // ------------------ if (jsonhandler != NULL) { if (header != NULL) { jsonhandler->open_nesting(header); } else { jsonhandler->open_nesting("UNKNOWN STATS"); } print_json(jsonhandler, *config->arbitrary_commands, config->cluster_mode, config->print_percentiles.quantile_list); } if (!config->hide_histogram) { print_histogram(out, jsonhandler, *config->arbitrary_commands); } // This close_nesting closes either: // jsonhandler->open_nesting(header); or // jsonhandler->open_nesting("UNKNOWN STATS"); // From the top (beginning of function). if (jsonhandler != NULL){ jsonhandler->close_nesting();} }