diff --git a/contrib/unbound_munin_ b/contrib/unbound_munin_ index 206bd28bd..330e63fa1 100755 --- a/contrib/unbound_munin_ +++ b/contrib/unbound_munin_ @@ -41,6 +41,7 @@ # unbound_munin_by_opcode - incoming queries by opcode # unbound_munin_by_rcode - answers by rcode, validation status # unbound_munin_by_flags - incoming queries by flags +# unbound_munin_histogram - histogram of query resolving times # # Magic markers - optional - used by installation scripts and # munin-config: @@ -82,6 +83,7 @@ unbound_munin_by_class - incoming queries by class unbound_munin_by_opcode - incoming queries by opcode unbound_munin_by_rcode - answers by rcode, validation status unbound_munin_by_flags - incoming queries by flags +unbound_munin_histogram - histogram of query resolving times =head1 AUTHOR @@ -178,6 +180,7 @@ if test "$1" = "suggest" ; then echo "by_opcode" echo "by_rcode" echo "by_flags" + echo "histogram" exit 0 fi @@ -319,6 +322,49 @@ if test "$1" = "config" ; then p_config "num.query.edns.DO" "DO (DNSSEC OK) flag" echo "graph_info This graphs plots the flags inside incoming queries. For example, if QR, AA, TC, RA, Z flags are set, the query can be rejected. RD, AD, CD and DO are legitimately set by some software." ;; + histogram) + echo "graph_title Unbound DNS histogram of reply time" + echo "graph_args --base 1000 -l 0" + echo "graph_vlabel queries / second" + echo "graph_category DNS" + echo h64ms.label "0 msec - 66 msec" + echo h64ms.min 0 + echo h64ms.draw AREA + echo h64ms.colour 0000FF + echo h128ms.label "66 msec - 131 msec" + echo h128ms.min 0 + echo h128ms.colour 1F00DF + echo h128ms.draw STACK + echo h256ms.label "131 msec - 262 msec" + echo h256ms.min 0 + echo h256ms.draw STACK + echo h256ms.colour 3F00BF + echo h512ms.label "262 msec - 524 msec" + echo h512ms.min 0 + echo h512ms.draw STACK + echo h512ms.colour 5F009F + echo h1s.label "524 msec - 1 sec" + echo h1s.min 0 + echo h1s.draw STACK + echo h1s.colour 7F007F + echo h2s.label "1 sec - 2 sec" + echo h2s.min 0 + echo h2s.draw STACK + echo h2s.colour 9F005F + echo h4s.label "2 sec - 4 sec" + echo h4s.min 0 + echo h4s.draw STACK + echo h4s.colour BF003F + echo h8s.label "4 sec - 8 sec" + echo h8s.min 0 + echo h8s.draw STACK + echo h8s.colour DF001F + echo h16s.label "8 sec - ..." + echo h16s.min 0 + echo h16s.draw STACK + echo h16s.colour FF0000 + echo "graph_info Histogram of the reply times for queries." + ;; esac exit 0 @@ -412,4 +458,63 @@ by_flags) print_qps $x done ;; +histogram) + r=0 + for x in histogram.000000.000000.to.000000.000001 \ + histogram.000000.000001.to.000000.000002 \ + histogram.000000.000002.to.000000.000004 \ + histogram.000000.000004.to.000000.000008 \ + histogram.000000.000008.to.000000.000016 \ + histogram.000000.000016.to.000000.000032 \ + histogram.000000.000032.to.000000.000064 \ + histogram.000000.000064.to.000000.000128 \ + histogram.000000.000128.to.000000.000256 \ + histogram.000000.000256.to.000000.000512 \ + histogram.000000.000512.to.000000.001024 \ + histogram.000000.001024.to.000000.002048 \ + histogram.000000.002048.to.000000.004096 \ + histogram.000000.004096.to.000000.008192 \ + histogram.000000.008192.to.000000.016384 \ + histogram.000000.016384.to.000000.032768 \ + histogram.000000.032768.to.000000.065536; do + get_value $x + r=`expr $r + $value` + done + echo h64ms.value $r + get_value histogram.000000.065536.to.000000.131072 + echo h128ms.value $value + get_value histogram.000000.131072.to.000000.262144 + echo h256ms.value $value + get_value histogram.000000.262144.to.000000.524288 + echo h512ms.value $value + get_value histogram.000000.524288.to.000001.000000 + echo h1s.value $value + get_value histogram.000001.000000.to.000002.000000 + echo h2s.value $value + get_value histogram.000002.000000.to.000004.000000 + echo h4s.value $value + get_value histogram.000004.000000.to.000008.000000 + echo h8s.value $value + r=0 + for x in histogram.000008.000000.to.000016.000000 \ + histogram.000016.000000.to.000032.000000 \ + histogram.000032.000000.to.000064.000000 \ + histogram.000064.000000.to.000128.000000 \ + histogram.000128.000000.to.000256.000000 \ + histogram.000256.000000.to.000512.000000 \ + histogram.000512.000000.to.001024.000000 \ + histogram.001024.000000.to.002048.000000 \ + histogram.002048.000000.to.004096.000000 \ + histogram.004096.000000.to.008192.000000 \ + histogram.008192.000000.to.016384.000000 \ + histogram.016384.000000.to.032768.000000 \ + histogram.032768.000000.to.065536.000000 \ + histogram.065536.000000.to.131072.000000 \ + histogram.131072.000000.to.262144.000000 \ + histogram.262144.000000.to.524288.000000; do + get_value $x + r=`expr $r + $value` + done + echo h16s.value $r + ;; esac diff --git a/daemon/remote.c b/daemon/remote.c index a84244c76..d6e4f0ef6 100644 --- a/daemon/remote.c +++ b/daemon/remote.c @@ -656,6 +656,34 @@ print_uptime(SSL* ssl, struct worker* worker) return 1; } +/** print extended histogram */ +static int +print_hist(SSL* ssl, struct stats_info* s) +{ + struct timehist* hist; + size_t i; + hist = timehist_setup(); + if(!hist) { + log_err("out of memory"); + return 0; + } + timehist_import(hist, s->svr.hist, NUM_BUCKETS_HIST); + for(i=0; inum; i++) { + if(!ssl_printf(ssl, + "histogram.%6.6d.%6.6d.to.%6.6d.%6.6d=%u\n", + (int)hist->buckets[i].lower.tv_sec, + (int)hist->buckets[i].lower.tv_usec, + (int)hist->buckets[i].upper.tv_sec, + (int)hist->buckets[i].upper.tv_usec, + (unsigned)hist->buckets[i].count)) { + timehist_delete(hist); + return 0; + } + } + timehist_delete(hist); + return 1; +} + /** print extended stats */ static int print_ext(SSL* ssl, struct stats_info* s) @@ -804,6 +832,8 @@ do_stats(SSL* ssl, struct daemon_remote* rc) if(daemon->cfg->stat_extended) { if(!print_mem(ssl, rc->worker, daemon)) return; + if(!print_hist(ssl, &total)) + return; if(!print_ext(ssl, &total)) return; } diff --git a/daemon/stats.c b/daemon/stats.c index 247621299..63dec6774 100644 --- a/daemon/stats.c +++ b/daemon/stats.c @@ -135,6 +135,8 @@ server_stats_compile(struct worker* worker, struct stats_info* s) s->svr.ans_rcode_nodata += worker->env.mesh->ans_nodata; for(i=0; i<16; i++) s->svr.ans_rcode[i] += worker->env.mesh->ans_rcode[i]; + timehist_export(worker->env.mesh->histogram, s->svr.hist, + NUM_BUCKETS_HIST); /* values from outside network */ s->svr.unwanted_replies = worker->back->unwanted_replies; @@ -219,6 +221,8 @@ void server_stats_add(struct stats_info* total, struct stats_info* a) total->svr.qopcode[i] += a->svr.qopcode[i]; for(i=0; isvr.ans_rcode[i] += a->svr.ans_rcode[i]; + for(i=0; isvr.hist[i] += a->svr.hist[i]; } total->mesh_num_states += a->mesh_num_states; diff --git a/daemon/stats.h b/daemon/stats.h index f5611cd1e..d894e0292 100644 --- a/daemon/stats.h +++ b/daemon/stats.h @@ -42,6 +42,7 @@ #ifndef DAEMON_STATS_H #define DAEMON_STATS_H +#include "util/timehist.h" struct worker; struct config_file; struct comm_point; @@ -120,6 +121,12 @@ struct server_stats { size_t unwanted_replies; /** unwanted traffic received on client-facing ports */ size_t unwanted_queries; + + /** histogram data exported to array + * if the array is the same size, no data is lost, and + * if all histograms are same size (is so by default) then + * adding up works well. */ + size_t hist[NUM_BUCKETS_HIST]; }; /** diff --git a/doc/Changelog b/doc/Changelog index 517e8e471..8f64b7dc7 100644 --- a/doc/Changelog +++ b/doc/Changelog @@ -3,6 +3,7 @@ - munin plugin improvements. - nicer abbreviations for high query types values (ixfr, axfr, any...) - documented the statistics output in unbound-control man page. + - extended statistics prints out histogram, over unbound-control. 17 September 2008: Wouter - locking for threadsafe bogus rrset counter. diff --git a/doc/unbound-control.8.in b/doc/unbound-control.8.in index 3f25615f7..593dcdd13 100644 --- a/doc/unbound-control.8.in +++ b/doc/unbound-control.8.in @@ -169,6 +169,12 @@ Memory in bytes in use by the iterator module. Memory in bytes in use by the validator module. Includes the key cache and negative cache. .TP +.I histogram...to.. +Shows a histogram, summed over all threads. Every element counts the +recursive queries whose reply time fit between the lower and upper bound. +Times larger or equal to the lowerbound, and smaller than the upper bound. +There are 40 buckets, with bucket sizes doubling. +.TP .I num.query.type.A The total number of queries over all threads with query type A. Printed for the other query types as well, but only for the types for which diff --git a/util/timehist.c b/util/timehist.c index 6cdaf05ed..578f594e7 100644 --- a/util/timehist.c +++ b/util/timehist.c @@ -82,7 +82,7 @@ struct timehist* timehist_setup() sizeof(struct timehist)); if(!hist) return NULL; - hist->num = 40; + hist->num = NUM_BUCKETS_HIST; hist->buckets = (struct th_buck*)calloc(hist->num, sizeof(struct th_buck)); if(!hist->buckets) { @@ -218,3 +218,25 @@ timehist_quartile(struct timehist* hist, double q) res = (lookfor - passed)*(up-low)/((double)hist->buckets[i].count); return res; } + +void +timehist_export(struct timehist* hist, size_t* array, size_t sz) +{ + size_t i; + if(!hist) return; + if(sz > hist->num) + sz = hist->num; + for(i=0; ibuckets[i].count; +} + +void +timehist_import(struct timehist* hist, size_t* array, size_t sz) +{ + size_t i; + if(!hist) return; + if(sz > hist->num) + sz = hist->num; + for(i=0; ibuckets[i].count = array[i]; +} diff --git a/util/timehist.h b/util/timehist.h index aabda19c6..ab23f0128 100644 --- a/util/timehist.h +++ b/util/timehist.h @@ -42,6 +42,9 @@ #ifndef UTIL_TIMEHIST_H #define UTIL_TIMEHIST_H +/** Number of buckets in a histogram */ +#define NUM_BUCKETS_HIST 40 + /** * Bucket of time history information */ @@ -112,4 +115,20 @@ void timehist_print(struct timehist* hist); */ void timehist_log(struct timehist* hist, const char* name); +/** + * Export histogram to an array. + * @param hist: histogram + * @param array: the array to export to. + * @param sz: number of items in array. + */ +void timehist_export(struct timehist* hist, size_t* array, size_t sz); + +/** + * Import histogram from an array. + * @param hist: histogram + * @param array: the array to import from. + * @param sz: number of items in array. + */ +void timehist_import(struct timehist* hist, size_t* array, size_t sz); + #endif /* UTIL_TIMEHIST_H */