diff options
Diffstat (limited to 'src/dnsperf.c')
| -rw-r--r-- | src/dnsperf.c | 264 |
1 files changed, 221 insertions, 43 deletions
diff --git a/src/dnsperf.c b/src/dnsperf.c index 7d10212..90b7874 100644 --- a/src/dnsperf.c +++ b/src/dnsperf.c @@ -1,5 +1,5 @@ /* - * Copyright 2019-2022 OARC, Inc. + * Copyright 2019-2023 OARC, Inc. * Copyright 2017-2018 Akamai Technologies * Copyright 2006-2016 Nominum, Inc. * All rights reserved. @@ -32,6 +32,10 @@ #include "util.h" #include "list.h" #include "buffer.h" +#if HAVE_STDATOMIC_H +#include "ext/hg64.h" +#define USE_HISTOGRAMS +#endif #include <inttypes.h> #include <errno.h> @@ -49,6 +53,8 @@ #include <openssl/conf.h> #include <openssl/err.h> +#define HISTOGRAM_SIGBITS 5 /* about 3 % latency precision */ + #define DEFAULT_SERVER_NAME "127.0.0.1" #define DEFAULT_SERVER_PORT 53 #define DEFAULT_SERVER_DOT_PORT 853 @@ -85,6 +91,7 @@ typedef struct { uint32_t max_outstanding; uint32_t max_qps; uint64_t stats_interval; + bool verbose_interval_stats; bool updates; bool binary_input; perf_input_format_t input_format; @@ -92,6 +99,9 @@ typedef struct { enum perf_net_mode mode; perf_suppress_t suppress; size_t num_queries_per_conn; +#ifdef USE_HISTOGRAMS + bool latency_histogram; +#endif } config_t; typedef struct { @@ -101,8 +111,9 @@ typedef struct { struct timespec stop_time_ns; } times_t; +#define DNSPERF_STATS_RCODECOUNTS 16 typedef struct { - uint64_t rcodecounts[16]; + uint64_t rcodecounts[DNSPERF_STATS_RCODECOUNTS]; uint64_t num_sent; uint64_t num_interrupted; @@ -124,6 +135,11 @@ typedef struct { uint64_t conn_latency_sum_squares; uint64_t conn_latency_min; uint64_t conn_latency_max; + +#ifdef USE_HISTOGRAMS + hg64* latency; + hg64* conn_latency; +#endif } stats_t; typedef perf_list(struct query_info) query_list; @@ -257,7 +273,86 @@ stddev(uint64_t sum_of_squares, uint64_t sum, uint64_t total) } static void -print_statistics(const config_t* config, const times_t* times, stats_t* stats) +diff_stats(const config_t* config, stats_t* last, stats_t* now, stats_t* diff) +{ + int i = 0; + for (; i < DNSPERF_STATS_RCODECOUNTS; i++) { + diff->rcodecounts[i] = now->rcodecounts[i] - last->rcodecounts[i]; + } + + diff->num_sent = now->num_sent - last->num_sent; + diff->num_interrupted = now->num_interrupted - last->num_interrupted; + diff->num_timedout = now->num_timedout - last->num_timedout; + diff->num_completed = now->num_completed - last->num_completed; + + diff->total_request_size = now->total_request_size - last->total_request_size; + diff->total_response_size = now->total_response_size - last->total_response_size; + + diff->latency_sum = now->latency_sum - last->latency_sum; + diff->latency_sum_squares = now->latency_sum_squares - last->latency_sum_squares; + diff->latency_min = 0; /* not enough data */ + diff->latency_max = 0; + + diff->num_conn_reconnect = now->num_conn_reconnect - last->num_conn_reconnect; + diff->num_conn_completed = now->num_conn_completed - last->num_conn_completed; + + diff->conn_latency_sum = now->conn_latency_sum - last->conn_latency_sum; + diff->conn_latency_sum_squares = now->conn_latency_sum_squares - last->conn_latency_sum_squares; + diff->conn_latency_min = 0; + diff->conn_latency_max = 0; + +#ifdef USE_HISTOGRAMS + if (config->latency_histogram) { + free(diff->latency); + diff->latency = hg64_create(HISTOGRAM_SIGBITS); + if (last->latency) { + hg64_diff(now->latency, last->latency, diff->latency); + } else { /* first sample */ + hg64_merge(diff->latency, now->latency); + } + hg64_get(diff->latency, hg64_min_key(diff->latency), &diff->latency_min, NULL, NULL); + hg64_get(diff->latency, hg64_max_key(diff->latency), NULL, &diff->latency_max, NULL); + + free(diff->conn_latency); + diff->conn_latency = hg64_create(HISTOGRAM_SIGBITS); + if (last->conn_latency) { + hg64_diff(now->conn_latency, last->conn_latency, diff->conn_latency); + } else { /* first sample */ + hg64_merge(diff->conn_latency, now->conn_latency); + } + hg64_get(diff->conn_latency, hg64_min_key(diff->conn_latency), &diff->conn_latency_min, NULL, NULL); + hg64_get(diff->conn_latency, hg64_max_key(diff->conn_latency), NULL, &diff->conn_latency_max, NULL); + } +#endif +} + +#ifdef USE_HISTOGRAMS +static void +print_histogram(hg64* histogram, const char* const desc) +{ + printf(" Latency bucket (s): %s\n", desc); + uint64_t pmin, pmax, pcount; + for (unsigned key = 0; + hg64_get(histogram, key, &pmin, &pmax, &pcount) == true; + key = hg64_next(histogram, key)) { + if (pcount == 0) + continue; + printf(" %" PRIu64 ".%06" PRIu64 " - %" PRIu64 ".%06" PRIu64 ": %" PRIu64 "\n", + pmin / MILLION, + pmin % MILLION, + pmax / MILLION, + pmax % MILLION, + pcount); + }; +} +#endif + +/* + * now != 0 is call to print stats in the middle of test run. + * min-max values are not available on per-interval basis, so skip them. + */ +static void +print_statistics(const config_t* config, const times_t* times, stats_t* stats, uint64_t now, uint64_t interval_time) { const char* units; uint64_t run_time; @@ -267,9 +362,12 @@ print_statistics(const config_t* config, const times_t* times, stats_t* stats) units = config->updates ? "Updates" : "Queries"; - run_time = times->end_time - times->start_time; + if (now) + run_time = now - times->start_time; + else + run_time = times->end_time - times->start_time; - printf("Statistics:\n\n"); + printf("%sStatistics:\n\n", now ? "Interval " : ""); printf(" %s sent: %" PRIu64 "\n", units, stats->num_sent); @@ -287,7 +385,7 @@ print_statistics(const config_t* config, const times_t* times, stats_t* stats) printf(" Response codes: "); first_rcode = true; - for (i = 0; i < 16; i++) { + for (i = 0; i < DNSPERF_STATS_RCODECOUNTS; i++) { if (stats->rcodecounts[i] == 0) continue; if (first_rcode) @@ -308,23 +406,33 @@ print_statistics(const config_t* config, const times_t* times, stats_t* stats) (unsigned int)(run_time / MILLION), (unsigned int)(run_time % MILLION)); printf(" %s per second: %.6lf\n", units, - PERF_SAFE_DIV(stats->num_completed, (((double)run_time) / MILLION))); + PERF_SAFE_DIV(stats->num_completed, (((double)(now ? interval_time : run_time) / MILLION)))); printf("\n"); latency_avg = PERF_SAFE_DIV(stats->latency_sum, stats->num_completed); - printf(" Average Latency (s): %u.%06u (min %u.%06u, max %u.%06u)\n", + printf(" Average Latency (s): %u.%06u", (unsigned int)(latency_avg / MILLION), - (unsigned int)(latency_avg % MILLION), - (unsigned int)(stats->latency_min / MILLION), - (unsigned int)(stats->latency_min % MILLION), - (unsigned int)(stats->latency_max / MILLION), - (unsigned int)(stats->latency_max % MILLION)); + (unsigned int)(latency_avg % MILLION)); + if (!now) { + printf(" (min %u.%06u, max %u.%06u)\n", + (unsigned int)(stats->latency_min / MILLION), + (unsigned int)(stats->latency_min % MILLION), + (unsigned int)(stats->latency_max / MILLION), + (unsigned int)(stats->latency_max % MILLION)); + } else { + printf("\n"); + } + if (stats->num_completed > 1) { printf(" Latency StdDev (s): %f\n", stddev(stats->latency_sum_squares, stats->latency_sum, stats->num_completed) / MILLION); +#ifdef USE_HISTOGRAMS + if (config->latency_histogram) + print_histogram(stats->latency, "answer count"); +#endif } printf("\n"); @@ -336,32 +444,56 @@ print_statistics(const config_t* config, const times_t* times, stats_t* stats) printf("Connection Statistics:\n\n"); printf(" Reconnections: %" PRIu64 "\n\n", stats->num_conn_reconnect); latency_avg = PERF_SAFE_DIV(stats->conn_latency_sum, stats->num_conn_completed); - printf(" Average Latency (s): %u.%06u (min %u.%06u, max %u.%06u)\n", + printf(" Average Latency (s): %u.%06u", (unsigned int)(latency_avg / MILLION), - (unsigned int)(latency_avg % MILLION), - (unsigned int)(stats->conn_latency_min / MILLION), - (unsigned int)(stats->conn_latency_min % MILLION), - (unsigned int)(stats->conn_latency_max / MILLION), - (unsigned int)(stats->conn_latency_max % MILLION)); + (unsigned int)(latency_avg % MILLION)); + if (!now) { + printf(" (min %u.%06u, max %u.%06u)\n", + (unsigned int)(stats->conn_latency_min / MILLION), + (unsigned int)(stats->conn_latency_min % MILLION), + (unsigned int)(stats->conn_latency_max / MILLION), + (unsigned int)(stats->conn_latency_max % MILLION)); + } else { + printf("\n"); + } if (stats->num_conn_completed > 1) { printf(" Latency StdDev (s): %f\n", stddev(stats->conn_latency_sum_squares, stats->conn_latency_sum, stats->num_conn_completed) / MILLION); +#ifdef USE_HISTOGRAMS + if (config->latency_histogram) + print_histogram(stats->latency, "connection count"); +#endif } printf("\n"); } +/* + * Caller must free() stats->latency and stats->conn_latency. + */ static void sum_stats(const config_t* config, stats_t* total) { unsigned int i, j; memset(total, 0, sizeof(*total)); +#ifdef USE_HISTOGRAMS + if (config->latency_histogram) { + total->latency = hg64_create(HISTOGRAM_SIGBITS); + total->conn_latency = hg64_create(HISTOGRAM_SIGBITS); + } +#endif for (i = 0; i < config->threads; i++) { stats_t* stats = &threads[i].stats; +#ifdef USE_HISTOGRAMS + if (config->latency_histogram) { + hg64_merge(total->latency, stats->latency); + hg64_merge(total->conn_latency, stats->conn_latency); + } +#endif - for (j = 0; j < 16; j++) + for (j = 0; j < DNSPERF_STATS_RCODECOUNTS; j++) total->rcodecounts[j] += stats->rcodecounts[j]; total->num_sent += stats->num_sent; @@ -499,6 +631,12 @@ setup(int argc, char** argv, config_t* config) "suppress messages/warnings, see man-page for list of message types", NULL, &local_suppress); perf_long_opt_add("num-queries-per-conn", perf_opt_uint, "queries", "Number of queries to send per connection", NULL, &config->num_queries_per_conn); + perf_long_opt_add("verbose-interval-stats", perf_opt_boolean, NULL, + "print detailed statistics for each stats_interval", NULL, &config->verbose_interval_stats); +#ifdef USE_HISTOGRAMS + perf_long_opt_add("latency-histogram", perf_opt_boolean, NULL, + "collect and print detailed latency histograms", NULL, &config->latency_histogram); +#endif bool log_stdout = false; perf_opt_add('W', perf_opt_boolean, NULL, "log warnings and errors to stdout instead of stderr", NULL, &log_stdout); @@ -574,14 +712,18 @@ setup(int argc, char** argv, config_t* config) * If we run more threads than max-qps, some threads will have * ->max_qps set to 0, and be unlimited. */ - if (config->max_qps > 0 && config->threads > config->max_qps) + if (config->max_qps > 0 && config->threads > config->max_qps) { + perf_log_warning("requested max QPS limit (-Q %u) is lower than number of threads (-T %u), lowering number of threads", config->max_qps, config->threads); config->threads = config->max_qps; + } /* * We also can't run more threads than clients. */ - if (config->threads > config->clients) + if (config->threads > config->clients) { + perf_log_warning("requested number of threads (-T %u) exceeds number of clients (-c %u), lowering number of threads\n", config->threads, config->clients); config->threads = config->clients; + } #ifndef HAVE_LDNS if (config->updates) { @@ -636,6 +778,10 @@ query_move(threadinfo_t* tinfo, query_info* q, query_move_op op) static inline uint64_t num_outstanding(const stats_t* stats) { + /* make sure negative values aren't returned */ + if (stats->num_completed + stats->num_timedout > stats->num_sent) { + return 0; + } return stats->num_sent - stats->num_completed - stats->num_timedout; } @@ -920,7 +1066,10 @@ recv_one(threadinfo_t* tinfo, int which_sock, } if (!n) { // Treat connection closed like try again until reconnection features are in - *saved_errnop = EAGAIN; + if (!*saved_errnop) { + // only set this if there was no error before to allow above error check to overwrite EAGAIN + *saved_errnop = EAGAIN; + } return false; } recvd->sock = tinfo->socks[which_sock]; @@ -1006,8 +1155,6 @@ do_recv(void* arg) break; } bit_set(socketbits, current_socket); - if (saved_errno != EAGAIN) - break; } if (j == tinfo->nsocks) break; @@ -1039,11 +1186,13 @@ do_recv(void* arg) perf_log_warning("received short response"); continue; } - if (recvd[i].unexpected && !tinfo->config->suppress.unexpected) { - perf_log_warning("received a response with an " - "unexpected (maybe timed out) " - "id: %u", - recvd[i].qid); + if (recvd[i].unexpected) { + if (!tinfo->config->suppress.unexpected) { + perf_log_warning("received a response with an " + "unexpected (maybe timed out) " + "id: %u", + recvd[i].qid); + } continue; } latency = recvd[i].when - recvd[i].sent; @@ -1061,6 +1210,11 @@ do_recv(void* arg) stats->total_response_size += recvd[i].size; stats->rcodecounts[recvd[i].rcode]++; stats->latency_sum += latency; +#ifdef USE_HISTOGRAMS + if (stats->latency) { + hg64_inc(stats->latency, latency); + } +#endif stats->latency_sum_squares += (latency * latency); if (latency < stats->latency_min || stats->num_completed == 1) stats->latency_min = latency; @@ -1097,18 +1251,17 @@ static void* do_interval_stats(void* arg) { threadinfo_t* tinfo; - stats_t total; + stats_t total = {}; + stats_t last = {}; + stats_t diff = {}; uint64_t now; uint64_t last_interval_time; - uint64_t last_completed; uint64_t interval_time; - uint64_t num_completed; double qps; struct perf_net_socket sock = { .mode = sock_pipe, .fd = threadpipe[0] }; tinfo = arg; last_interval_time = tinfo->times->start_time; - last_completed = 0; wait_for_start(); while (perf_os_waituntilreadable(&sock, threadpipe[0], @@ -1117,13 +1270,23 @@ do_interval_stats(void* arg) now = perf_get_time(); sum_stats(tinfo->config, &total); interval_time = now - last_interval_time; - num_completed = total.num_completed - last_completed; - qps = num_completed / (((double)interval_time) / MILLION); - perf_log_printf("%u.%06u: %.6lf", - (unsigned int)(now / MILLION), - (unsigned int)(now % MILLION), qps); + + if (tinfo->config->verbose_interval_stats) { + diff_stats(tinfo->config, &last, &total, &diff); + print_statistics(tinfo->config, tinfo->times, &diff, now, interval_time); + } else { + qps = (total.num_completed - last.num_completed) / (((double)interval_time) / MILLION); + perf_log_printf("%u.%06u: %.6lf", + (unsigned int)(now / MILLION), + (unsigned int)(now % MILLION), qps); + } + last_interval_time = now; - last_completed = total.num_completed; +#ifdef USE_HISTOGRAMS + free(last.latency); + free(last.conn_latency); +#endif + last = total; } return NULL; @@ -1189,6 +1352,11 @@ static void perf__net_event(struct perf_net_socket* sock, perf_socket_event_t ev case perf_socket_event_connected: stats->num_conn_completed++; +#ifdef USE_HISTOGRAMS + if (stats->conn_latency) { + hg64_inc(stats->conn_latency, elapsed_time); + } +#endif stats->conn_latency_sum += elapsed_time; stats->conn_latency_sum_squares += (elapsed_time * elapsed_time); if (elapsed_time < stats->conn_latency_min || stats->num_conn_completed == 1) @@ -1218,6 +1386,12 @@ threadinfo_init(threadinfo_t* tinfo, const config_t* config, perf_list_init(tinfo->outstanding_queries); perf_list_init(tinfo->unused_queries); +#ifdef USE_HISTOGRAMS + if (config->latency_histogram) { + tinfo->stats.latency = hg64_create(HISTOGRAM_SIGBITS); + tinfo->stats.conn_latency = hg64_create(HISTOGRAM_SIGBITS); + } +#endif for (i = 0; i < NQIDS; i++) { perf_link_init(&tinfo->queries[i]); perf_list_append(tinfo->unused_queries, &tinfo->queries[i]); @@ -1240,11 +1414,15 @@ threadinfo_init(threadinfo_t* tinfo, const config_t* config, /* * We can't have more than 64k outstanding queries per thread. */ - if (tinfo->max_outstanding > NQIDS) + if (tinfo->max_outstanding > NQIDS) { + perf_log_warning("requested number of outstanding queries (-q %u) per single thread (-T) exceeds built-in maximum %u, adjusting\n", tinfo->max_outstanding, NQIDS); tinfo->max_outstanding = NQIDS; + } - if (tinfo->nsocks > MAX_SOCKETS) + if (tinfo->nsocks > MAX_SOCKETS) { + perf_log_warning("requested number of clients (-c %u) per thread (-T) exceeds built-in maximum %u, adjusting\n", tinfo->nsocks, MAX_SOCKETS); tinfo->nsocks = MAX_SOCKETS; + } if (!(tinfo->socks = calloc(tinfo->nsocks, sizeof(*tinfo->socks)))) { perf_log_fatal("out of memory"); @@ -1383,7 +1561,7 @@ int main(int argc, char** argv) print_final_status(&config); sum_stats(&config, &total_stats); - print_statistics(&config, ×, &total_stats); + print_statistics(&config, ×, &total_stats, 0, 0); perf_net_stats_print(config.mode); cleanup(&config); |