Add tracing probes to the dns_xfrin unit

Add tracing probes to incoming transfers, so we can accurately measure
the individual events when sending, receiving and parsing the incoming
transfers.

diff --git a/lib/dns/probes.d b/lib/dns/probes.d
index 056d9e68556126ae330608febe8a13d2b99778af..d2c87748c0c4ec903ceb404c7a03981e9827f5fb 100644 (file)
--- a/lib/dns/probes.d
+++ b/lib/dns/probes.d
@@ -12,4 +12,21 @@
  */
 
 provider libdns {
+       probe xfrin_axfr_finalize_begin(void *);
+       probe xfrin_axfr_finalize_end(void *, int);
+       probe xfrin_connected(void *, int);
+       probe xfrin_done_callback_begin(void *, int);
+       probe xfrin_done_callback_end(void *, int);
+       probe xfrin_journal_destroy_begin(void *, int);
+       probe xfrin_journal_destroy_end(void *, int);
+       probe xfrin_read(void *, int);
+       probe xfrin_recv_answer(void *, void *);
+       probe xfrin_recv_done(void *, int);
+       probe xfrin_recv_parsed(void *, int);
+       probe xfrin_recv_question(void *, void *);
+       probe xfrin_recv_send_request(void *);
+       probe xfrin_recv_start(void *, int);
+       probe xfrin_recv_try_axfr(void *, int);
+       probe xfrin_sent(void *, int);
+       probe xfrin_start(void *);
 };

diff --git a/lib/dns/xfrin.c b/lib/dns/xfrin.c
index 8e04d23e7762d372b47640ad8c06406024267843..e1459a09c2a74adc4063482ee40f5a1b2a9d888c 100644 (file)
--- a/lib/dns/xfrin.c
+++ b/lib/dns/xfrin.c
@@ -35,6 +35,7 @@
 #include <dns/rdataset.h>
 #include <dns/result.h>
 #include <dns/soa.h>
+#include <dns/trace.h>
 #include <dns/transport.h>
 #include <dns/tsig.h>
 #include <dns/view.h>
@@ -43,6 +44,8 @@
 
 #include <dst/dst.h>
 
+#include "probes.h"
+
 /*
  * Incoming AXFR and IXFR.
  */
@@ -360,10 +363,10 @@ static isc_result_t
 axfr_finalize(dns_xfrin_t *xfr) {
        isc_result_t result;
 
-       CHECK(dns_zone_replacedb(xfr->zone, xfr->db, true));
+       LIBDNS_XFRIN_AXFR_FINALIZE_BEGIN(xfr);
+       result = dns_zone_replacedb(xfr->zone, xfr->db, true);
+       LIBDNS_XFRIN_AXFR_FINALIZE_END(xfr, result);
 
-       result = ISC_R_SUCCESS;
-failure:
        return (result);
 }
 
@@ -956,6 +959,8 @@ xfrin_start(dns_xfrin_t *xfr) {
                CHECK(result);
        }
 
+       LIBDNS_XFRIN_START(xfr);
+
        /* Set the maximum timer */
        isc_interval_set(&interval, dns_zone_getmaxxfrin(xfr->zone), 0);
        isc_timer_start(xfr->max_time_timer, isc_timertype_once, &interval);
@@ -1027,6 +1032,8 @@ xfrin_connect_done(isc_result_t result, isc_region_t *region ISC_ATTR_UNUSED,
                result = ISC_R_SHUTTINGDOWN;
        }
 
+       LIBDNS_XFRIN_CONNECTED(xfr, result);
+
        if (result != ISC_R_SUCCESS) {
                xfrin_fail(xfr, result, "failed to connect");
                goto failure;
@@ -1155,6 +1162,8 @@ xfrin_send_request(dns_xfrin_t *xfr) {
        dns_dbversion_t *ver = NULL;
        dns_name_t *msgsoaname = NULL;
 
+       LIBDNS_XFRIN_RECV_SEND_REQUEST(xfr);
+
        /* Create the request message */
        dns_message_create(xfr->mctx, DNS_MESSAGE_INTENTRENDER, &msg);
        CHECK(dns_message_settsigkey(msg, xfr->tsigkey));
@@ -1245,6 +1254,8 @@ xfrin_send_done(isc_result_t result, isc_region_t *region, void *arg) {
                result = ISC_R_SHUTTINGDOWN;
        }
 
+       LIBDNS_XFRIN_SENT(xfr, result);
+
        CHECK(result);
 
        xfrin_log(xfr, ISC_LOG_DEBUG(3), "sent request data");
@@ -1274,6 +1285,8 @@ xfrin_recv_done(isc_result_t result, isc_region_t *region, void *arg) {
        /* Stop the idle timer */
        isc_timer_stop(xfr->max_idle_timer);
 
+       LIBDNS_XFRIN_RECV_START(xfr, result);
+
        CHECK(result);
 
        xfrin_log(xfr, ISC_LOG_DEBUG(7), "received %u bytes", region->length);
@@ -1307,6 +1320,8 @@ xfrin_recv_done(isc_result_t result, isc_region_t *region, void *arg) {
                          isc_result_totext(result));
        }
 
+       LIBDNS_XFRIN_RECV_PARSED(xfr, result);
+
        if (result != ISC_R_SUCCESS || msg->rcode != dns_rcode_noerror ||
            msg->opcode != dns_opcode_query || msg->rdclass != xfr->rdclass)
        {
@@ -1334,6 +1349,7 @@ xfrin_recv_done(isc_result_t result, isc_region_t *region, void *arg) {
                xfrin_log(xfr, ISC_LOG_DEBUG(3), "got %s, retrying with AXFR",
                          isc_result_totext(result));
        try_axfr:
+               LIBDNS_XFRIN_RECV_TRY_AXFR(xfr, result);
                dns_message_detach(&msg);
                xfrin_reset(xfr);
                xfr->reqtype = dns_rdatatype_soa;
@@ -1374,6 +1390,8 @@ xfrin_recv_done(isc_result_t result, isc_region_t *region, void *arg) {
        {
                dns_rdataset_t *rds = NULL;
 
+               LIBDNS_XFRIN_RECV_QUESTION(xfr, msg);
+
                name = NULL;
                dns_message_currentname(msg, DNS_SECTION_QUESTION, &name);
                if (!dns_name_equal(name, &xfr->name)) {
@@ -1435,6 +1453,8 @@ xfrin_recv_done(isc_result_t result, isc_region_t *region, void *arg) {
        {
                dns_rdataset_t *rds = NULL;
 
+               LIBDNS_XFRIN_RECV_ANSWER(xfr, msg);
+
                name = NULL;
                dns_message_currentname(msg, DNS_SECTION_ANSWER, &name);
                for (rds = ISC_LIST_HEAD(name->list); rds != NULL;
@@ -1513,15 +1533,19 @@ xfrin_recv_done(isc_result_t result, isc_region_t *region, void *arg) {
                 * Close the journal.
                 */
                if (xfr->ixfr.journal != NULL) {
+                       LIBDNS_XFRIN_JOURNAL_DESTROY_BEGIN(xfr, result);
                        dns_journal_destroy(&xfr->ixfr.journal);
+                       LIBDNS_XFRIN_JOURNAL_DESTROY_END(xfr, result);
                }
 
                /*
                 * Inform the caller we succeeded.
                 */
                if (xfr->done != NULL) {
+                       LIBDNS_XFRIN_DONE_CALLBACK_BEGIN(xfr, result);
                        (xfr->done)(xfr->zone, ISC_R_SUCCESS);
                        xfr->done = NULL;
+                       LIBDNS_XFRIN_DONE_CALLBACK_END(xfr, result);
                }
 
                atomic_store(&xfr->shuttingdown, true);
@@ -1539,6 +1563,8 @@ xfrin_recv_done(isc_result_t result, isc_region_t *region, void *arg) {
                isc_interval_set(&interval, dns_zone_getidlein(xfr->zone), 0);
                isc_timer_start(xfr->max_idle_timer, isc_timertype_once,
                                &interval);
+
+               LIBDNS_XFRIN_READ(xfr, result);
                return;
        }
 
@@ -1551,6 +1577,7 @@ failure:
                dns_message_detach(&msg);
        }
        dns_xfrin_detach(&xfr);
+       LIBDNS_XFRIN_RECV_DONE(xfr, result);
 }
 
 static void