Maintain and report outgoing transfer statistics

Transfer statistics are currently only reported for incoming transfers,
even though they are equally useful for outgoing transfers.  Define a
separate structure for keeping track of the number of messages, records,
and bytes sent during each outgoing transfer, along with the time each
outgoing transfer took.  Repurpose the 'nmsg' field of the xfrout_ctx_t
structure for tracking the number of messages actually sent, ensuring it
is only increased after isc_socket_send() indicates success.  Report the
statistics gathered when an outgoing transfer completes.

diff --git a/lib/ns/xfrout.c b/lib/ns/xfrout.c
index 0212887e915d6972e633d9f1532a3394f315c518..f98ab6b7f546558c5a47bccb50fca70a173bd413 100644 (file)
--- a/lib/ns/xfrout.c
+++ b/lib/ns/xfrout.c
@@ -645,11 +645,22 @@ static rrstream_methods_t compound_rrstream_methods = {
 };
 
 /**************************************************************************/
-/*
+
+/*%
+ * Structure holding outgoing transfer statistics
+ */
+struct xfr_stats {
+       uint64_t        nmsg;   /*%< Number of messages sent */
+       uint64_t        nrecs;  /*%< Number of records sent */
+       uint64_t        nbytes; /*%< Number of bytes sent */
+       isc_time_t      start;  /*%< Start time of the transfer */
+       isc_time_t      end;    /*%< End time of the transfer */
+};
+
+/*%
  * An 'xfrout_ctx_t' contains the state of an outgoing AXFR or IXFR
  * in progress.
  */
-
 typedef struct {
        isc_mem_t               *mctx;
        ns_client_t             *client;
@@ -670,7 +681,6 @@ typedef struct {
        isc_buffer_t            txbuf;          /* Transmit message buffer */
        void                    *txmem;
        unsigned int            txmemlen;
-       unsigned int            nmsg;           /* Number of messages sent */
        dns_tsigkey_t           *tsigkey;       /* Key used to create TSIG */
        isc_buffer_t            *lasttsig;      /* the last TSIG */
        bool                    verified_tsig;  /* verified request MAC */
@@ -678,6 +688,7 @@ typedef struct {
        int                     sends;          /* Send in progress */
        bool                    shuttingdown;
        const char              *mnemonic;      /* Style of transfer */
+       struct xfr_stats        stats;          /*%< Transfer statistics */
 } xfrout_ctx_t;
 
 static isc_result_t
@@ -1186,7 +1197,6 @@ xfrout_ctx_create(isc_mem_t *mctx, ns_client_t *client, unsigned int id,
        xfr->tsigkey = tsigkey;
        xfr->lasttsig = lasttsig;
        xfr->verified_tsig = verified_tsig;
-       xfr->nmsg = 0;
        xfr->many_answers = many_answers;
        xfr->sends = 0;
        xfr->shuttingdown = false;
@@ -1198,6 +1208,11 @@ xfrout_ctx_create(isc_mem_t *mctx, ns_client_t *client, unsigned int id,
        xfr->stream = NULL;
        xfr->quota = NULL;
 
+       xfr->stats.nmsg = 0;
+       xfr->stats.nrecs = 0;
+       xfr->stats.nbytes = 0;
+       isc_time_now(&xfr->stats.start);
+
        /*
         * Allocate a temporary buffer for the uncompressed response
         * message data.  The size should be no more than 65535 bytes
@@ -1483,6 +1498,8 @@ sendstream(xfrout_ctx_t *xfr) {
                dns_message_addname(msg, msgname, DNS_SECTION_ANSWER);
                msgname = NULL;
 
+               xfr->stats.nrecs++;
+
                result = xfr->stream->methods->next(xfr->stream);
                if (result == ISC_R_NOMORE) {
                        xfr->end_of_stream = true;
@@ -1537,8 +1554,6 @@ sendstream(xfrout_ctx_t *xfr) {
        /* Advance lasttsig to be the last TSIG generated */
        CHECK(dns_message_getquerytsig(msg, xfr->mctx, &xfr->lasttsig));
 
-       xfr->nmsg++;
-
  failure:
        if (msgname != NULL) {
                if (msgrds != NULL) {
@@ -1621,10 +1636,20 @@ xfrout_senddone(isc_task_t *task, isc_event_t *event) {
 
        INSIST(event->ev_type == ISC_SOCKEVENT_SENDDONE);
 
-       isc_event_free(&event);
        xfr->sends--;
        INSIST(xfr->sends == 0);
 
+       /*
+        * Update transfer statistics if sending succeeded, accounting for the
+        * two-byte TCP length prefix included in the number of bytes sent.
+        */
+       if (evresult == ISC_R_SUCCESS) {
+               xfr->stats.nmsg++;
+               xfr->stats.nbytes += sev->region.length - 2;
+       }
+
+       isc_event_free(&event);
+
        (void)isc_timer_touch(xfr->client->timer);
        if (xfr->shuttingdown == true) {
                xfrout_maybe_destroy(xfr);
@@ -1634,8 +1659,28 @@ xfrout_senddone(isc_task_t *task, isc_event_t *event) {
                sendstream(xfr);
        } else {
                /* End of zone transfer stream. */
+               uint64_t msecs, persec;
+
                inc_stats(xfr->client, xfr->zone, ns_statscounter_xfrdone);
-               xfrout_log(xfr, ISC_LOG_INFO, "%s ended", xfr->mnemonic);
+               isc_time_now(&xfr->stats.end);
+               msecs = isc_time_microdiff(&xfr->stats.end, &xfr->stats.start);
+               msecs /= 1000;
+               if (msecs == 0) {
+                       msecs = 1;
+               }
+               persec = (xfr->stats.nbytes * 1000) / msecs;
+               xfrout_log(xfr, ISC_LOG_INFO,
+                          "%s ended: "
+                          "%" PRIu64 " messages, %" PRIu64 " records, "
+                          "%" PRIu64 " bytes, "
+                          "%u.%03u secs (%u bytes/sec)",
+                          xfr->mnemonic,
+                          xfr->stats.nmsg, xfr->stats.nrecs,
+                          xfr->stats.nbytes,
+                          (unsigned int) (msecs / 1000),
+                          (unsigned int) (msecs % 1000),
+                          (unsigned int) persec);
+
                ns_client_next(xfr->client, ISC_R_SUCCESS);
                xfrout_ctx_destroy(&xfr);
        }