Skip to content

Commit

Permalink
Merge pull request #213 from pspacek/verbose-interval-stats
Browse files Browse the repository at this point in the history 
verbose interval stats for dnsperf
  • Loading branch information
@jelu
jelu authored Jan 20, 2023
2 parents 432b47f + ad3fb03 commit fd34e07
Show file tree
Hide file tree
Showing 3 changed files with 129 additions and 40 deletions.
17 changes: 15 additions & 2 deletions src/dnsperf.1.in
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
116 changes: 87 additions & 29 deletions src/dnsperf.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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;
Expand Down Expand Up @@ -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;
Expand All @@ -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);
Expand All @@ -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)
Expand All @@ -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,
Expand All @@ -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);
Expand All @@ -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;
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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],
Expand All @@ -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;
Expand Down Expand Up @@ -1396,7 +1454,7 @@ int main(int argc, char** argv)
print_final_status(&config);

sum_stats(&config, &total_stats);
print_statistics(&config, &times, &total_stats);
print_statistics(&config, &times, &total_stats, 0, 0);
perf_net_stats_print(config.mode);

cleanup(&config);
Expand Down
36 changes: 27 additions & 9 deletions src/opt.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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++;

Expand All @@ -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;
}
Expand All @@ -284,10 +302,10 @@ static int perf_opt_long_parse(char* optarg)

void perf_long_opt_usage(void)
{
fprintf(stderr, "Usage: %s ... -O <name>=<value> ...\n\nAvailable long options:\n", progname);
fprintf(stderr, "Usage: %s ... -O <name>[=<value>] ...\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 ? "=<val>" : "", opt->help);
if (opt->defval) {
fprintf(stderr, " (default: %s)", opt->defval);
}
Expand Down

0 comments on commit fd34e07

Please sign in to comment.