[master] improvements to queryperf

3530.	[contrib]	Better RTT tracking in queryperf. [RT #30128]

diff --git a/CHANGES b/CHANGES
index 34e8325f3b3b9ac26ddc1a84a20d96e9d79d37b3..443693864dda770f4322553233de7f951c3ae98f 100644 (file)
--- a/CHANGES
+++ b/CHANGES
@@ -1,3 +1,5 @@
+3530.  [contrib]       Better RTT tracking in queryperf. [RT #30128]
+
 3529.  [func]          Named now listens on both IPv4 and IPv6 interfaces
                        by default.  Named previously only listened on IPv4
                        interfaces by default unless named was running in

diff --git a/contrib/queryperf/queryperf.c b/contrib/queryperf/queryperf.c
index 9bed11b65683e43f6668854247beb33c06446da6..6b153271ae8e99fee48a4e4393416e1f145c1e93 100644 (file)
--- a/contrib/queryperf/queryperf.c
+++ b/contrib/queryperf/queryperf.c
@@ -74,6 +74,7 @@
 #define HARD_TIMEOUT_EXTRA             5               /* in seconds */
 #define RESPONSE_BLOCKING_WAIT_TIME    0.1             /* in seconds */
 #define EDNSLEN                                11
+#define DNS_HEADERLEN                  12
 
 #define FALSE                          0
 #define TRUE                           1
@@ -128,6 +129,14 @@ struct query_status {
        unsigned short int id;
        struct timeval sent_timestamp;
        char *desc;
+       int qtype;
+       char qname[MAX_DOMAIN_LEN + 1];
+};
+
+struct query_mininfo {         /* minimum info for timeout queries */
+       int qtype;              /* use -1 if N/A */
+       struct timeval sent_timestamp;
+       char qname[MAX_DOMAIN_LEN + 1];
 };
 
 /*
@@ -208,6 +217,8 @@ unsigned int *rttarray = NULL;
 unsigned int *rttarray_interval = NULL;
 unsigned int rtt_overflows;
 unsigned int rtt_overflows_interval;
+unsigned int rtt_counted;
+unsigned int rtt_counted_interval;
 char *rtt_histogram_file = NULL;
 
 struct query_status *status;                           /* init NULL */
@@ -218,6 +229,8 @@ int socket4 = -1, socket6 = -1;
 
 static char *rcode_strings[] = RCODE_STRINGS;
 
+static struct query_mininfo *timeout_queries;
+
 /*
  * get_uint16:
  *   Get an unsigned short integer from a buffer (in network order)
@@ -1330,10 +1343,10 @@ update_config(char *config_change_desc) {
  *   Return a non-negative integer otherwise
  */
 int
-parse_query(char *input, char *qname, int qnlen, int *qtype) {
+parse_query(char *input, char *qname, unsigned int qnlen, int *qtype) {
        static char *qtype_strings[] = QTYPE_STRINGS;
        static int qtype_codes[] = QTYPE_CODES;
-       int num_types, index;
+       unsigned int num_types, index;
        int found = FALSE;
        char incopy[MAX_INPUT_LEN + 1];
        char *domain_str, *type_str;
@@ -1382,7 +1395,9 @@ parse_query(char *input, char *qname, int qnlen, int *qtype) {
  *   Return a non-negative integer otherwise
  */
 int
-dispatch_query(unsigned short int id, char *dom, int qt) {
+dispatch_query(unsigned short int id, char *dom, int qt, u_char **pktp,
+              int *pktlenp)
+{
        static u_char packet_buffer[PACKETSZ + 1];
        int buffer_len = PACKETSZ;
        int bytes_sent;
@@ -1438,6 +1453,9 @@ dispatch_query(unsigned short int id, char *dom, int qt) {
                fprintf(stderr, "Warning: incomplete packet sent: %s %d\n",
                        dom, qt);
 
+       *pktp = packet_buffer;
+       *pktlenp = buffer_len;
+
        return (0);
 }
 
@@ -1450,8 +1468,9 @@ send_query(char *query_desc) {
        static unsigned short int use_query_id = 0;
        static int qname_len = MAX_DOMAIN_LEN;
        static char domain[MAX_DOMAIN_LEN + 1];
+       u_char *qpkt;
        char serveraddr[NI_MAXHOST];
-       int query_type;
+       int query_type, qpkt_len;
        unsigned int count;
 
        use_query_id++;
@@ -1461,7 +1480,8 @@ send_query(char *query_desc) {
                return;
        }
 
-       if (dispatch_query(use_query_id, domain, query_type) == -1) {
+       if (dispatch_query(use_query_id, domain, query_type,
+                          &qpkt, &qpkt_len) == -1) {
                char *addrstr;
 
                if (getnameinfo(server_ai->ai_addr, server_ai->ai_addrlen,
@@ -1501,11 +1521,18 @@ send_query(char *query_desc) {
        }
 
        /* Register the query in status[] */
-       status[count].in_use = TRUE;
        status[count].id = use_query_id;
        if (verbose)
                status[count].desc = strdup(query_desc);
        set_timenow(&status[count].sent_timestamp);
+       status[count].qtype = query_type;
+       if (dn_expand(qpkt, qpkt + qpkt_len, qpkt + DNS_HEADERLEN,
+                     status[count].qname, MAX_DOMAIN_LEN) == -1) {
+               fprintf(stderr, "Unexpected error: "
+                       "query message doesn't have qname?\n");
+               return;
+       }
+       status[count].in_use = TRUE;
 
        if (num_queries_sent_interval == 0)
                set_timenow(&time_of_first_query_interval);
@@ -1516,7 +1543,9 @@ send_query(char *query_desc) {
 }
 
 void
-register_rtt(struct timeval *timestamp) {
+register_rtt(struct timeval *timestamp, char *qname, int qtype,
+            unsigned int rcode)
+{
        int i;
        int oldquery = FALSE;
        struct timeval now;
@@ -1535,6 +1564,7 @@ register_rtt(struct timeval *timestamp) {
                rtt_min = rtt;
 
        rtt_total += rtt;
+       rtt_counted++;
 
        if (!oldquery) {
                if (rtt_max_interval < 0 || rtt_max_interval < rtt)
@@ -1544,6 +1574,7 @@ register_rtt(struct timeval *timestamp) {
                        rtt_min_interval = rtt;
 
                rtt_total_interval += rtt;
+               rtt_counted_interval++;
        }
 
        if (rttarray == NULL)
@@ -1555,8 +1586,8 @@ register_rtt(struct timeval *timestamp) {
                if (!oldquery)
                        rttarray_interval[i]++;
        } else {
-               fprintf(stderr, "Warning: RTT is out of range: %.6lf\n",
-                       rtt);
+               fprintf(stderr, "Warning: RTT is out of range: %.6lf "
+                       "[query=%s/%d, rcode=%u]\n", rtt, qname, qtype, rcode);
                rtt_overflows++;
                if (!oldquery)
                        rtt_overflows_interval++;
@@ -1571,36 +1602,53 @@ register_rtt(struct timeval *timestamp) {
  *   status[] if any exists.
  */
 void
-register_response(unsigned short int id, unsigned int rcode) {
+register_response(unsigned short int id, unsigned int rcode, char *qname,
+       int qtype)
+{
        unsigned int ct = 0;
        int found = FALSE;
        struct timeval now;
        double rtt;
 
+       if (timeout_queries != NULL) {
+               struct query_mininfo *qi = &timeout_queries[id];
+
+               if (qi->qtype == qtype && strcasecmp(qi->qname, qname) == 0) {
+                       register_rtt(&qi->sent_timestamp, qname, qtype, rcode);
+                       qi->qtype = -1;
+                       found = TRUE;
+               }
+       }
+
        for (; (ct < query_status_allocated) && (found == FALSE); ct++) {
-               if ((status[ct].in_use == TRUE) && (status[ct].id == id)) {
+               if (status[ct].in_use == TRUE && status[ct].id == id &&
+                   status[ct].qtype == qtype &&
+                   strcasecmp(status[ct].qname, qname) == 0) {
                        status[ct].in_use = FALSE;
                        num_queries_outstanding--;
                        found = TRUE;
 
-                       register_rtt(&status[ct].sent_timestamp);
+                       register_rtt(&status[ct].sent_timestamp, qname, qtype,
+                                    rcode);
 
                        if (status[ct].desc) {
                                printf("> %s %s\n", rcode_strings[rcode],
                                       status[ct].desc);
                                free(status[ct].desc);
                        }
-                       if (countrcodes)
-                               rcodecounts[rcode]++;
                }
        }
 
+       if (countrcodes && (found == TRUE || target_qps > 0))
+               rcodecounts[rcode]++;
+
        if (found == FALSE) {
                if (target_qps > 0) {
                        num_queries_possiblydelayed++;
                        num_queries_possiblydelayed_interval++;
                } else {
-                       fprintf(stderr, "Warning: Received a response with an "
+                       fprintf(stderr,
+                               "Warning: Received a response with an "
                                "unexpected (maybe timed out) id: %u\n", id);
                }
        }
@@ -1617,9 +1665,9 @@ process_single_response(int sockfd) {
        struct sockaddr_storage from_addr_ss;
        struct sockaddr *from_addr;
        static unsigned char in_buf[MAX_BUFFER_LEN];
-       int numbytes, resp_id;
-       socklen_t addr_len;
-       int flags;
+       char qname[MAX_DOMAIN_LEN + 1];
+       int numbytes, addr_len, resp_id, qnamelen;
+       int qtype, flags;
 
        memset(&from_addr_ss, 0, sizeof(from_addr_ss));
        from_addr = (struct sockaddr *)&from_addr_ss;
@@ -1631,10 +1679,29 @@ process_single_response(int sockfd) {
                return;
        }
 
+       if (numbytes < DNS_HEADERLEN) {
+               if (verbose)
+                       fprintf(stderr, "Malformed response\n");
+               return;
+       }
        resp_id = get_uint16(in_buf);
        flags = get_uint16(in_buf + 2);
+       qnamelen = dn_expand(in_buf, in_buf + numbytes, in_buf + DNS_HEADERLEN,
+                            qname, MAX_DOMAIN_LEN);
+       if (qnamelen == -1) {
+               if (verbose)
+                       fprintf(stderr,
+                               "Failed to retrieve qname from response\n");
+               return;
+       }
+       if (numbytes < DNS_HEADERLEN + qnamelen + 2) {
+               if (verbose)
+                       fprintf(stderr, "Malformed response\n");
+               return;
+       }
+       qtype = get_uint16(in_buf + DNS_HEADERLEN + qnamelen);
 
-       register_response(resp_id, flags & 0xF);
+       register_response(resp_id, flags & 0xF, qname, qtype);
 }
 
 /*
@@ -1785,15 +1852,30 @@ retire_old_queries(int sending) {
        set_timenow(&curr_time);
 
        for (; count < query_status_allocated; count++) {
-
-               if ((status[count].in_use == TRUE)
-                   && (difftv(curr_time, status[count].sent_timestamp)
-                   >= (double)timeout)) {
-
+               if ((status[count].in_use == TRUE) &&
+                   (difftv(curr_time,
+                           status[count].sent_timestamp) >= (double)timeout))
+               {
                        status[count].in_use = FALSE;
                        num_queries_outstanding--;
-                       num_queries_timed_out++;
-                       num_queries_timed_out_interval++;
+
+                       if (timeout_queries != NULL) {
+                               struct query_mininfo *qi;
+
+                               qi = &timeout_queries[status[count].id];
+                               if (qi->qtype != -1) {
+                                       /* now really retire this query */
+                                       num_queries_timed_out++;
+                                       num_queries_timed_out_interval++;
+                               }
+                               qi->qtype = status[count].qtype;
+                               qi->sent_timestamp =
+                                       status[count].sent_timestamp;
+                               strcpy(qi->qname, status[count].qname);
+                       } else {
+                               num_queries_timed_out++;
+                               num_queries_timed_out_interval++;
+                       }
 
                        if (timeout_reduced == FALSE) {
                                if (status[count].desc) {
@@ -1850,7 +1932,7 @@ print_statistics(int intermediate, unsigned int sent, unsigned int timed_out,
                 struct timeval *first_query,
                 struct timeval *program_start,
                 struct timeval *end_perf, struct timeval *end_query,
-                double rmax, double rmin, double rtotal,
+                unsigned int rcounted, double rmax, double rmin, double rtotal,
                 unsigned int roverflows, unsigned int *rarray)
 {
        unsigned int num_queries_completed;
@@ -1896,11 +1978,11 @@ print_statistics(int intermediate, unsigned int sent, unsigned int timed_out,
                        difftv(*end_query, *first_query);
        }
 
-       if (num_queries_completed > 0) {
+       if (rcounted > 0) {
                int i;
                double sum = 0;
 
-               rtt_average = rtt_total / (double)num_queries_completed;
+               rtt_average = rtotal / (double)rcounted;
                for (i = 0; i < rttarray_size; i++) {
                        if (rarray[i] != 0) {
                                double mean, diff;
@@ -1911,7 +1993,7 @@ print_statistics(int intermediate, unsigned int sent, unsigned int timed_out,
                                sum += (diff * diff) * rarray[i];
                        }
                }
-               rtt_stddev = sqrt(sum / (double)num_queries_completed);
+               rtt_stddev = sqrt(sum / (double)rcounted);
        } else {
                rtt_average = 0.0;
                rtt_stddev = 0.0;
@@ -2028,9 +2110,9 @@ print_interval_statistics() {
                         num_queries_possiblydelayed_interval,
                         &time_of_first_query_interval,
                         &time_of_first_query_interval, &time_now, &time_now,
-                        rtt_max_interval, rtt_min_interval,
-                        rtt_total_interval, rtt_overflows_interval,
-                        rttarray_interval);
+                        rtt_counted_interval, rtt_max_interval,
+                        rtt_min_interval, rtt_total_interval,
+                        rtt_overflows_interval, rttarray_interval);
 
        /* Reset intermediate counters */
        num_queries_sent_interval = 0;
@@ -2039,6 +2121,7 @@ print_interval_statistics() {
        rtt_max_interval = -1;
        rtt_min_interval = -1;
        rtt_total_interval = 0.0;
+       rtt_counted_interval = 0.0;
        rtt_overflows_interval = 0;
        if (rttarray_interval != NULL) {
                memset(rttarray_interval, 0,
@@ -2072,6 +2155,18 @@ main(int argc, char **argv) {
        if (setup(argc, argv) == -1)
                return (-1);
 
+       /* XXX: move this to setup: */
+       timeout_queries = malloc(sizeof(struct query_mininfo) * 65536);
+       if (timeout_queries == NULL) {
+               fprintf(stderr,
+                       "failed to allocate memory for timeout queries\n");
+               return (-1);
+       } else {
+               int i;
+               for (i = 0; i < 65536; i++)
+                       timeout_queries[i].qtype = -1;
+       }
+
        printf("[Status] Processing input data\n");
 
        while ((sending = keep_sending(&got_eof)) == TRUE ||
@@ -2126,7 +2221,8 @@ main(int argc, char **argv) {
                         num_queries_possiblydelayed,
                         &time_of_first_query, &time_of_program_start,
                         &time_of_end_of_run, &time_of_stop_sending,
-                        rtt_max, rtt_min, rtt_total, rtt_overflows, rttarray);
+                        rtt_counted, rtt_max, rtt_min, rtt_total,
+                        rtt_overflows, rttarray);
 
        return (0);
 }