histogram support for stats.

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

diff --git a/contrib/unbound_munin_ b/contrib/unbound_munin_
index 206bd28bd8a68205b7eff27cc5ff9c9e61beed1a..330e63fa1023e0d7e36fa12b1c23e8c880134f46 100755 (executable)
--- 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 a84244c7659e783f7b23fcf99cf158e1d897b639..d6e4f0ef64071b48fa73d9027db45486499bcd12 100644 (file)
--- 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; 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;
        }

diff --git a/daemon/stats.c b/daemon/stats.c
index 2476212992b9c4da1472bf93e90a5caa1a15b52f..63dec6774ab49f1420febd8e36fedd33fd744569 100644 (file)
--- 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; 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;

diff --git a/daemon/stats.h b/daemon/stats.h
index f5611cd1e54a91625e9a20c9f82229af20a6ce3c..d894e029291c85d402b4f24ea4fccc0be2074f6f 100644 (file)
--- 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 517e8e4711c5ffe93c940f4b9b5f848c61c78487..8f64b7dc734672c72fa15f7064ae18192b27f7ca 100644 (file)
--- 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 3f25615f7f7b4fe7ce61fb20c0d8d245128f79a2..593dcdd132eaceafc44c78ce7aca7421f05ce22a 100644 (file)
--- 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.<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

diff --git a/util/timehist.c b/util/timehist.c
index 6cdaf05edc0fbe6e7edd2c102b1de84cd205bad5..578f594e7989c405ab03831d3f273ad012ce13be 100644 (file)
--- 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; 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];
+}

diff --git a/util/timehist.h b/util/timehist.h
index aabda19c6201bda153fb850db0b3bd100996f19e..ab23f0128f239b5dad2bacdfe8d384afe011215c 100644 (file)
--- 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 */