diff --git a/src/dnsperf.1.in b/src/dnsperf.1.in index 9ae24bd..15a392b 100644 --- a/src/dnsperf.1.in +++ b/src/dnsperf.1.in @@ -341,8 +341,9 @@ The default is the loopback address, 127.0.0.1. \fB-S \fIstats_interval\fR .br .RS -If this parameter is specified, a count of the number of queries per second -during the interval will be printed out every stats_interval seconds. +If this parameter is specified, a count of the number of answers received +per second during the interval will be printed out every \fIstats_interval\fR +seconds. .RE \fB-t \fItimeout\fR @@ -474,6 +475,18 @@ Waiting for responses may timeout and the timeout used for this is the same as specified by \fB-t\fR. Note that this option is only useful for connection oriented protocols. .RE + +\fBverbose-interval-stats\fR +.br +.RS +Change the statistics format of \fB-S\fR to that shown at end of run. + +\fIPlease note\fR: Min/max values for latency and connections are not +available in interval statistics. +Number of answers received within \fIstats_interval\fR can legitimately +exceed number of queries sent, depending on answer latency, configured +\fItimeout\fR, and \fIstats_interval\fR. +.RE .SH "SEE ALSO" \fBresperf\fR(1) .SH AUTHOR diff --git a/src/dnsperf.c b/src/dnsperf.c index 5190ff6..5be8932 100644 --- a/src/dnsperf.c +++ b/src/dnsperf.c @@ -85,6 +85,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; @@ -101,8 +102,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; @@ -257,7 +259,41 @@ 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(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; +} + +/* + * 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 +303,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 +326,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,18 +347,24 @@ 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, @@ -336,13 +381,18 @@ 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); @@ -361,7 +411,7 @@ sum_stats(const config_t* config, stats_t* total) for (i = 0; i < config->threads; i++) { stats_t* stats = &threads[i].stats; - 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 +549,8 @@ 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); bool log_stdout = false; perf_opt_add('W', perf_opt_boolean, NULL, "log warnings and errors to stdout instead of stderr", NULL, &log_stdout); @@ -1107,17 +1159,17 @@ do_interval_stats(void* arg) { threadinfo_t* tinfo; 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; + memset(&last, 0, sizeof(last)); wait_for_start(); while (perf_os_waituntilreadable(&sock, threadpipe[0], @@ -1126,13 +1178,19 @@ 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(&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; + last = total; } return NULL; @@ -1396,7 +1454,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); diff --git a/src/opt.c b/src/opt.c index d65a0f8..53931f6 100644 --- a/src/opt.c +++ b/src/opt.c @@ -238,13 +238,13 @@ static int perf_opt_long_parse(char* optarg) ssize_t optlen; char* arg; - // TODO: Allow boolean not to have =/value - if (!(arg = strchr(optarg, '='))) { - return -1; - } - optlen = arg - optarg; - if (optlen < 1) { - return -1; + if ((arg = strchr(optarg, '='))) { + optlen = arg - optarg; + if (optlen < 1) { + return -1; + } + } else { + optlen = strlen(optarg); } arg++; @@ -253,24 +253,42 @@ static int perf_opt_long_parse(char* optarg) if (!strncmp(optarg, opt->name, optlen)) { switch (opt->type) { case perf_opt_string: + if (!arg) { + return -1; + } *opt->u.stringp = arg; break; case perf_opt_boolean: *opt->u.boolp = true; break; case perf_opt_uint: + if (!arg) { + return -1; + } *opt->u.uintp = parse_uint(opt->desc, arg, 1, 0xFFFFFFFF); break; case perf_opt_zpint: + if (!arg) { + return -1; + } *opt->u.uintp = parse_uint(opt->desc, arg, 0, 0xFFFFFFFF); break; case perf_opt_timeval: + if (!arg) { + return -1; + } *opt->u.uint64p = parse_timeval(opt->desc, arg); break; case perf_opt_double: + if (!arg) { + return -1; + } *opt->u.doublep = parse_double(opt->desc, arg); break; case perf_opt_port: + if (!arg) { + return -1; + } *opt->u.portp = parse_uint(opt->desc, arg, 0, 0xFFFF); break; } @@ -284,10 +302,10 @@ static int perf_opt_long_parse(char* optarg) void perf_long_opt_usage(void) { - fprintf(stderr, "Usage: %s ... -O = ...\n\nAvailable long options:\n", progname); + fprintf(stderr, "Usage: %s ... -O [=] ...\n\nAvailable long options:\n", progname); long_opt_t* opt = longopts; while (opt) { - fprintf(stderr, " %s: %s", opt->name, opt->help); + fprintf(stderr, " %s%s: %s", opt->name, opt->type != perf_opt_boolean ? "=" : "", opt->help); if (opt->defval) { fprintf(stderr, " (default: %s)", opt->defval); }