Pass through the delay for forward lookups.
Keep track of the time for forwarded dns lookups, and print a breakdown
of times in the cache_dump.
Change-Id: I4525a7476626c8426bf416cd96caeedf141341d5
diff --git a/src/cache.c b/src/cache.c
index 09b6dbf..e53e2c9 100644
--- a/src/cache.c
+++ b/src/cache.c
@@ -1386,6 +1386,12 @@
daemon->cachesize, cache_live_freed, cache_inserted);
my_syslog(LOG_INFO, _("queries forwarded %u, queries answered locally %u"),
daemon->queries_forwarded, daemon->local_answer);
+ my_syslog(LOG_INFO, ("dns_timings: %d,%d,%d,%d,%d,%d,%d,%d,%d"),
+ daemon->forward_timings[0], daemon->forward_timings[1], daemon->forward_timings[2],
+ daemon->forward_timings[3], daemon->forward_timings[4], daemon->forward_timings[5],
+ daemon->forward_timings[6], daemon->forward_timings[7], daemon->forward_timings[8]);
+ // Clear the forward timings.
+ memset(daemon->forward_timings, 0, sizeof(daemon->forward_timings));
#ifdef HAVE_AUTH
my_syslog(LOG_INFO, _("queries for authoritative zones %u"), daemon->auth_answer);
#endif
diff --git a/src/dnsmasq.h b/src/dnsmasq.h
index 418f815..3370aec 100644
--- a/src/dnsmasq.h
+++ b/src/dnsmasq.h
@@ -48,6 +48,7 @@
/* Also needed before config.h. */
#include <getopt.h>
+#include <stdint.h>
#include "config.h"
#include "ip6addr.h"
@@ -607,6 +608,7 @@
unsigned short orig_id, new_id;
int log_id, fd, forwardall, flags;
time_t time;
+ int64_t time64;
unsigned char *hash[HASH_SIZE];
#ifdef HAVE_DNSSEC
int class, work_counter;
@@ -908,6 +910,18 @@
struct dhcp_relay *current, *next;
};
+
+#define TIMING_BUCKET_ZEROES 0
+#define TIMING_BUCKET_1_MILLIS 1
+#define TIMING_BUCKET_2_MILLIS 2
+#define TIMING_BUCKET_5_MILLIS 3
+#define TIMING_BUCKET_10_MILLIS 4
+#define TIMING_BUCKET_50_MILLIS 5
+#define TIMING_BUCKET_100_MILLIS 6
+#define TIMING_BUCKET_200_MILLIS 7
+#define TIMING_BUCKET_500_MILLIS 8
+#define TIMING_BUCKETS 9
+
extern struct daemon {
/* datastuctures representing the command-line and
config file arguments. All set (including defaults)
@@ -1044,6 +1058,9 @@
char *addrbuff;
char *addrbuff2; /* only allocated when OPT_EXTRALOG */
+ /* Keep track of forwarded requests timings. */
+ int forward_timings[TIMING_BUCKETS];
+
} *daemon;
/* cache.c */
@@ -1160,6 +1177,7 @@
int sockaddr_isequal(union mysockaddr *s1, union mysockaddr *s2);
int hostname_isequal(const char *a, const char *b);
time_t dnsmasq_time(void);
+int64_t dnsmasq_time64(void);
int netmask_length(struct in_addr mask);
int is_same_net(struct in_addr a, struct in_addr b, struct in_addr mask);
#ifdef HAVE_IPV6
diff --git a/src/forward.c b/src/forward.c
index b17bc34..8893870 100644
--- a/src/forward.c
+++ b/src/forward.c
@@ -527,7 +527,7 @@
}
static size_t process_reply(struct dns_header *header, time_t now, struct server *server, size_t n, int check_rebind,
- int no_cache, int cache_secure, int ad_reqd, int do_bit, int added_pheader, int check_subnet, union mysockaddr *query_source)
+ int no_cache, int cache_secure, int ad_reqd, int do_bit, int added_pheader, int check_subnet, union mysockaddr *query_source, int64_t time64)
{
unsigned char *pheader, *sizep;
char **sets = 0;
@@ -537,6 +537,20 @@
(void)ad_reqd;
(void) do_bit;
+ if (time64 >= 0)
+ {
+ int64_t milliseconds = time64/1000000;
+ int bucket = TIMING_BUCKET_ZEROES;
+ if (milliseconds < 2) bucket = TIMING_BUCKET_1_MILLIS;
+ else if (milliseconds < 5) bucket = TIMING_BUCKET_2_MILLIS;
+ else if (milliseconds < 10) bucket = TIMING_BUCKET_5_MILLIS;
+ else if (milliseconds < 50) bucket = TIMING_BUCKET_10_MILLIS;
+ else if (milliseconds < 100) bucket = TIMING_BUCKET_50_MILLIS;
+ else if (milliseconds < 500) bucket = TIMING_BUCKET_100_MILLIS;
+ else bucket = TIMING_BUCKET_500_MILLIS;
+ daemon->forward_timings[bucket]++;
+ }
+
#ifdef HAVE_IPSET
if (daemon->ipsets && extract_request(header, n, daemon->namebuff, NULL))
{
@@ -693,6 +707,7 @@
#ifndef HAVE_DNSSEC
unsigned int crc;
#endif
+ int64_t now64 = dnsmasq_time64();
/* packet buffer overwritten */
daemon->srv_save = NULL;
@@ -1019,7 +1034,8 @@
if ((nn = process_reply(header, now, server, (size_t)n, check_rebind, no_cache_dnssec, cache_secure,
forward->flags & FREC_AD_QUESTION, forward->flags & FREC_DO_QUESTION,
- forward->flags & FREC_ADDED_PHEADER, forward->flags & FREC_HAS_SUBNET, &forward->source)))
+ forward->flags & FREC_ADDED_PHEADER, forward->flags & FREC_HAS_SUBNET, &forward->source,
+ now64 - forward->time64)))
{
header->id = htons(forward->orig_id);
header->hb4 |= HB4_RA; /* recursion if available */
@@ -1985,7 +2001,7 @@
m = process_reply(header, now, last_server, (unsigned int)m,
option_bool(OPT_NO_REBIND) && !norebind, no_cache_dnssec,
- cache_secure, ad_question, do_bit, added_pheader, check_subnet, &peer_addr);
+ cache_secure, ad_question, do_bit, added_pheader, check_subnet, &peer_addr, -1);
break;
}
@@ -2014,6 +2030,7 @@
{
f->next = daemon->frec_list;
f->time = now;
+ f->time64 = dnsmasq_time64();
f->sentto = NULL;
f->rfd4 = NULL;
f->flags = 0;
@@ -2139,6 +2156,7 @@
if (target)
{
target->time = now;
+ target->time64 = dnsmasq_time64();
return target;
}
@@ -2157,6 +2175,7 @@
{
free_frec(oldest);
oldest->time = now;
+ oldest->time64 = dnsmasq_time64();
}
return oldest;
}
diff --git a/src/util.c b/src/util.c
index d532444..81cfeeb 100644
--- a/src/util.c
+++ b/src/util.c
@@ -28,6 +28,8 @@
#include <idna.h>
#endif
+#include <stdint.h>
+
/* SURF random number generator */
static u32 seed[32];
@@ -332,6 +334,13 @@
#endif
}
+int64_t dnsmasq_time64(void)
+{
+ struct timespec ts;
+ clock_gettime(CLOCK_MONOTONIC, &ts);
+ return (int64_t)ts.tv_sec * INT64_C(1000000000) + ts.tv_nsec;
+}
+
int netmask_length(struct in_addr mask)
{
int zero_count = 0;
