histogram support for stats.

git-svn-id: file:///svn/unbound/trunk@1258 be551aaa-1e26-0410-a405-d3ace91eadb9

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

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; i<hist->num; 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;
 	}

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; i<STATS_RCODE_NUM; i++)
 			total->svr.ans_rcode[i] += a->svr.ans_rcode[i];
+		for(i=0; i<NUM_BUCKETS_HIST; i++)
+			total->svr.hist[i] += a->svr.hist[i];
 	}
 
 	total->mesh_num_states += a->mesh_num_states;

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];
 };
 
 /** 

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.

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.<sec>.<usec>.to.<sec>.<usec>
+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

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; i<sz; i++)
+		array[i] = hist->buckets[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; i<sz; i++)
+		hist->buckets[i].count = array[i];
+}

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 */