Cleaned up ICP logging/counting and ICP/CD stats output

diff --git a/src/access_log.cc b/src/access_log.cc
index 82b1c36d89f61740e1656a081b3bb0511597a804..5d774d992568d44c02c86c972719ee675bbdcf6c 100644 (file)
--- a/src/access_log.cc
+++ b/src/access_log.cc
@@ -1,7 +1,7 @@
 
 
 /*
- * $Id: access_log.cc,v 1.27 1998/04/06 22:32:10 wessels Exp $
+ * $Id: access_log.cc,v 1.28 1998/04/09 21:32:08 wessels Exp $
  *
  * DEBUG: section 46    Access Log
  * AUTHOR: Duane Wessels
@@ -58,6 +58,7 @@ const char *log_tags[] =
     "UDP_DENIED",
     "UDP_INVALID",
     "UDP_MISS_NOFETCH",
+    "ICP_QUERY",
     "LOG_TYPE_MAX"
 };
 

diff --git a/src/client_side.cc b/src/client_side.cc
index 6dce052f58c32df141e59f84ce118c8611c0426b..f4921ef392ea4035e6aabefffe6f6ea8d1adea57 100644 (file)
--- a/src/client_side.cc
+++ b/src/client_side.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: client_side.cc,v 1.271 1998/04/09 21:15:01 rousskov Exp $
+ * $Id: client_side.cc,v 1.272 1998/04/09 21:32:09 wessels Exp $
  *
  * DEBUG: section 33    Client-side Routines
  * AUTHOR: Duane Wessels
@@ -558,7 +558,8 @@ clientUpdateCounters(clientHttpRequest * http)
     i = &http->request->hier.icp;
     if (0 != i->stop.tv_sec && 0 != i->start.tv_sec)
        statHistCount(&Counter.icp.query_svc_time, tvSubUsec(i->start, i->stop));
-
+    if (i->timeout)
+       Counter.icp.query_timeouts++;
 #if SQUID_PEER_DIGEST
     H = &http->request->hier;
     if (H->peer_select_start.tv_sec && H->store_complete_stop.tv_sec)

diff --git a/src/enums.h b/src/enums.h
index 71a7d1e65a4ae589641df2281668229b96166305..1b52d7be401814f77a6a6adffaea080e28f1c282 100644 (file)
--- a/src/enums.h
+++ b/src/enums.h
@@ -19,6 +19,7 @@ typedef enum {
     LOG_UDP_DENIED,
     LOG_UDP_INVALID,
     LOG_UDP_MISS_NOFETCH,
+    LOG_ICP_QUERY,
     LOG_TYPE_MAX
 } log_type;
 
@@ -611,3 +612,8 @@ enum {
     MEDIAN_NM,
     MEDIAN_ICP_REPLY
 };
+
+enum {
+    SENT,
+    RECV
+};

diff --git a/src/icp_v2.cc b/src/icp_v2.cc
index a842abd4b315c75e18cbc63b49bcfe8c3cd92283..02318950d4523b2e910378b54eb80c4b180fd27e 100644 (file)
--- a/src/icp_v2.cc
+++ b/src/icp_v2.cc
@@ -4,6 +4,7 @@
 static void icpLogIcp(struct in_addr, log_type, int, const char *, int);
 static void icpHandleIcpV2(int, struct sockaddr_in, char *, int);
 static PF icpUdpSendQueue;
+static void icpCount(void *, int, size_t, int);
 
 static icpUdpData *UdpQueueHead = NULL;
 static icpUdpData *UdpQueueTail = NULL;
@@ -14,12 +15,9 @@ icpLogIcp(struct in_addr caddr, log_type logcode, int len, const char *url, int
     AccessLogEntry al;
     if (LOG_TAG_NONE == logcode)
        return;
+    if (LOG_ICP_QUERY == logcode)
+       return;
     clientdbUpdate(caddr, logcode, PROTO_ICP, len);
-    Counter.icp.pkts_sent++;
-    if (logcode == LOG_UDP_HIT)
-       Counter.icp.hits_sent++;
-    kb_incr(&Counter.icp.kbytes_sent, (size_t) len);
-    statHistCount(&Counter.icp.reply_svc_time, delay);
     if (!Config.onoff.log_udp)
        return;
     memset(&al, '\0', sizeof(al));
@@ -101,6 +99,7 @@ icpUdpSend(int fd,
     if (x >= 0) {
        /* successfully written */
        icpLogIcp(to->sin_addr, logcode, len, (char *) (msg + 1), delay);
+       icpCount(msg, SENT, (size_t) len, delay);
        safe_free(msg);
     } else if (0 == delay) {
        /* send failed, but queue it */
@@ -236,7 +235,6 @@ icpHandleIcpV2(int fd, struct sockaddr_in from, char *buf, int len)
        break;
 
     case ICP_HIT:
-       Counter.icp.hits_recv++;
     case ICP_SECHO:
     case ICP_DECHO:
     case ICP_MISS:
@@ -325,8 +323,7 @@ icpHandleUdp(int sock, void *datanotused)
                sock, xstrerror());
        return;
     }
-    Counter.icp.pkts_recv++;
-    kb_incr(&Counter.icp.kbytes_recv, (size_t) len);
+    icpCount(buf, RECV, (size_t) len, 0);
     buf[len] = '\0';
     debug(12, 4) ("icpHandleUdp: FD %d: received %d bytes from %s.\n",
        sock,
@@ -455,3 +452,39 @@ icpConnectionClose(void)
        comm_close(theOutIcpConnection);
     }
 }
+
+static void
+icpCount(void *buf, int which, size_t len, int delay)
+{
+    icp_common_t *icp = buf;
+    if (len < sizeof(*icp))
+       return;
+    if (SENT == which) {
+       Counter.icp.pkts_sent++;
+       kb_incr(&Counter.icp.kbytes_sent, len);
+       if (ICP_QUERY == icp->opcode) {
+           Counter.icp.queries_sent++;
+           kb_incr(&Counter.icp.q_kbytes_sent, len);
+       } else {
+           Counter.icp.replies_sent++;
+           kb_incr(&Counter.icp.r_kbytes_sent, len);
+           /* this is the sent-reply service time */
+            statHistCount(&Counter.icp.reply_svc_time, delay);
+       }
+        if (ICP_HIT == icp->opcode)
+           Counter.icp.hits_sent++;
+    } else if (RECV == which) {
+       Counter.icp.pkts_recv++;
+       kb_incr(&Counter.icp.kbytes_recv, len);
+       if (ICP_QUERY == icp->opcode) {
+           Counter.icp.queries_recv++;
+           kb_incr(&Counter.icp.q_kbytes_recv, len);
+       } else {
+           Counter.icp.replies_recv++;
+           kb_incr(&Counter.icp.r_kbytes_recv, len);
+           /* Counter.icp.query_svc_time set in clientUpdateCounters */
+       }
+        if (ICP_HIT == icp->opcode)
+           Counter.icp.hits_recv++;
+    }
+}

diff --git a/src/stat.cc b/src/stat.cc
index 8b9e31119e068cd9e9926bddcb1e61e1053ed233..88eae243a29b05b16beda615ae9b3c7510e7ef4b 100644 (file)
--- a/src/stat.cc
+++ b/src/stat.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: stat.cc,v 1.230 1998/04/09 21:15:02 rousskov Exp $
+ * $Id: stat.cc,v 1.231 1998/04/09 21:32:11 wessels Exp $
  *
  * DEBUG: section 18    Cache Manager Statistics
  * AUTHOR: Harvest Derived
@@ -120,14 +120,13 @@ static void statCountersInit(StatCounters *);
 static void statCountersInitSpecial(StatCounters *);
 static void statCountersClean(StatCounters *);
 static void statCountersCopy(StatCounters * dest, const StatCounters * orig);
-static void statCountersDump(StoreEntry * sentry);
 static double statMedianSvc(int, int);
 static OBJH stat_io_get;
 static OBJH stat_objects_get;
 static OBJH stat_vmobjects_get;
 static OBJH info_get;
 static OBJH statFiledescriptors;
-static OBJH statCounters;
+static OBJH statCountersDump;
 static OBJH statPeerSelect;
 static OBJH statDigestBlob;
 static OBJH statAvg5min;
@@ -650,6 +649,7 @@ statAvgDump(StoreEntry * sentry, int minutes, int hours)
        &f->client_http.hit_svc_time);
     storeAppendPrintf(sentry, "client_http.hit_median_svc_time = %f seconds\n",
        x / 1000.0);
+
 #if SQUID_PEER_DIGEST
     storeAppendPrintf(sentry, "cd.msgs_sent = %f/sec\n",
        XAVG(cd.msgs_sent));
@@ -717,12 +717,30 @@ statAvgDump(StoreEntry * sentry, int minutes, int hours)
        XAVG(icp.pkts_sent));
     storeAppendPrintf(sentry, "icp.pkts_recv = %f/sec\n",
        XAVG(icp.pkts_recv));
+    storeAppendPrintf(sentry, "icp.queries_sent = %f/sec\n",
+       XAVG(icp.queries_sent));
+    storeAppendPrintf(sentry, "icp.replies_sent = %f/sec\n",
+       XAVG(icp.replies_sent));
+    storeAppendPrintf(sentry, "icp.queries_recv = %f/sec\n",
+       XAVG(icp.queries_recv));
+    storeAppendPrintf(sentry, "icp.replies_recv = %f/sec\n",
+       XAVG(icp.replies_recv));
     storeAppendPrintf(sentry, "icp.replies_queued = %f/sec\n",
        XAVG(icp.replies_queued));
+    storeAppendPrintf(sentry, "icp.query_timeouts = %f/sec\n",
+       XAVG(icp.query_timeouts));
     storeAppendPrintf(sentry, "icp.kbytes_sent = %f/sec\n",
        XAVG(icp.kbytes_sent.kb));
     storeAppendPrintf(sentry, "icp.kbytes_recv = %f/sec\n",
        XAVG(icp.kbytes_recv.kb));
+    storeAppendPrintf(sentry, "icp.q_kbytes_sent = %f/sec\n",
+       XAVG(icp.q_kbytes_sent.kb));
+    storeAppendPrintf(sentry, "icp.r_kbytes_sent = %f/sec\n",
+       XAVG(icp.r_kbytes_sent.kb));
+    storeAppendPrintf(sentry, "icp.q_kbytes_recv = %f/sec\n",
+       XAVG(icp.q_kbytes_recv.kb));
+    storeAppendPrintf(sentry, "icp.r_kbytes_recv = %f/sec\n",
+       XAVG(icp.r_kbytes_recv.kb));
     x = statHistDeltaMedian(&l->icp.query_svc_time, &f->icp.query_svc_time);
     storeAppendPrintf(sentry, "icp.query_median_svc_time = %f seconds\n",
        x / 1000000.0);
@@ -771,7 +789,7 @@ statInit(void)
        stat_io_get, 0);
     cachemgrRegister("counters",
        "Traffic and Resource Counters",
-       statCounters, 0);
+       statCountersDump, 0);
     cachemgrRegister("peer_select",
        "Peer Selection Algorithms",
        statPeerSelect, 0);
@@ -909,6 +927,40 @@ statCountersCopy(StatCounters * dest, const StatCounters * orig)
 #endif
 }
 
+static void
+statCountersHistograms(StoreEntry *sentry)
+{
+    StatCounters *f = &Counter;
+#if TOO_MUCH_OUTPUT
+    storeAppendPrintf(sentry, "client_http.all_svc_time histogram:\n");
+    statHistDump(&f->client_http.all_svc_time, sentry, NULL);
+    storeAppendPrintf(sentry, "client_http.miss_svc_time histogram:\n");
+    statHistDump(&f->client_http.miss_svc_time, sentry, NULL);
+    storeAppendPrintf(sentry, "client_http.nm_svc_time histogram:\n");
+    statHistDump(&f->client_http.nm_svc_time, sentry, NULL);
+    storeAppendPrintf(sentry, "client_http.hit_svc_time histogram:\n");
+    statHistDump(&f->client_http.hit_svc_time, sentry, NULL);
+#endif
+#if SQUID_PEER_DIGEST
+    storeAppendPrintf(sentry, "\nicp.query_svc_time histogram:\n");
+    statHistDump(&f->icp.query_svc_time, sentry, NULL);
+    storeAppendPrintf(sentry, "\nicp.reply_svc_time histogram:\n");
+    statHistDump(&f->icp.reply_svc_time, sentry, NULL);
+    storeAppendPrintf(sentry, "\nicp.client_svc_time histogram:\n");
+    statHistDump(&f->icp.client_svc_time, sentry, NULL);
+    storeAppendPrintf(sentry, "\ncd.client_svc_time histogram:\n");
+    statHistDump(&f->cd.client_svc_time, sentry, NULL);
+#endif
+#if TOO_MUCH_OUTPUT
+    storeAppendPrintf(sentry, "icp.query_svc_time histogram:\n");
+    statHistDump(&f->icp.query_svc_time, sentry, NULL);
+    storeAppendPrintf(sentry, "icp.reply_svc_time histogram:\n");
+    statHistDump(&f->icp.reply_svc_time, sentry, NULL);
+    storeAppendPrintf(sentry, "dns.svc_time histogram:\n");
+    statHistDump(&f->dns.svc_time, sentry, NULL);
+#endif
+}
+
 static void
 statCountersDump(StoreEntry * sentry)
 {
@@ -933,17 +985,6 @@ statCountersDump(StoreEntry * sentry)
     storeAppendPrintf(sentry, "client_http.kbytes_out = %d\n",
        (int) f->client_http.kbytes_out.kb);
 
-#if TOO_MUCH_OUTPUT
-    storeAppendPrintf(sentry, "client_http.all_svc_time histogram:\n");
-    statHistDump(&f->client_http.all_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "client_http.miss_svc_time histogram:\n");
-    statHistDump(&f->client_http.miss_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "client_http.nm_svc_time histogram:\n");
-    statHistDump(&f->client_http.nm_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "client_http.hit_svc_time histogram:\n");
-    statHistDump(&f->client_http.hit_svc_time, sentry, NULL);
-#endif
-
     storeAppendPrintf(sentry, "server.all.requests = %d\n",
        (int) f->server.all.requests);
     storeAppendPrintf(sentry, "server.all.errors = %d\n",
@@ -984,35 +1025,48 @@ statCountersDump(StoreEntry * sentry)
        f->icp.pkts_sent);
     storeAppendPrintf(sentry, "icp.pkts_recv = %d\n",
        f->icp.pkts_recv);
+    storeAppendPrintf(sentry, "icp.queries_sent = %d\n",
+       f->icp.queries_sent);
+    storeAppendPrintf(sentry, "icp.replies_sent = %d\n",
+       f->icp.replies_sent);
+    storeAppendPrintf(sentry, "icp.queries_recv = %d\n",
+       f->icp.queries_recv);
+    storeAppendPrintf(sentry, "icp.replies_recv = %d\n",
+       f->icp.replies_recv);
+    storeAppendPrintf(sentry, "icp.query_timeouts = %d\n",
+       f->icp.query_timeouts);
     storeAppendPrintf(sentry, "icp.replies_queued = %d\n",
        f->icp.replies_queued);
     storeAppendPrintf(sentry, "icp.kbytes_sent = %d\n",
        (int) f->icp.kbytes_sent.kb);
     storeAppendPrintf(sentry, "icp.kbytes_recv = %d\n",
        (int) f->icp.kbytes_recv.kb);
+    storeAppendPrintf(sentry, "icp.q_kbytes_sent = %d\n",
+       (int) f->icp.q_kbytes_sent.kb);
+    storeAppendPrintf(sentry, "icp.r_kbytes_sent = %d\n",
+       (int) f->icp.r_kbytes_sent.kb);
+    storeAppendPrintf(sentry, "icp.q_kbytes_recv = %d\n",
+       (int) f->icp.q_kbytes_recv.kb);
+    storeAppendPrintf(sentry, "icp.r_kbytes_recv = %d\n",
+       (int) f->icp.r_kbytes_recv.kb);
 
 #if SQUID_PEER_DIGEST
+    storeAppendPrintf(sentry, "icp.times_used = %d\n",
+        f->icp.times_used);
+    storeAppendPrintf(sentry, "cd.times_used = %d\n",
+        f->cd.times_used);
     storeAppendPrintf(sentry, "cd.msgs_sent = %d\n",
        f->cd.msgs_sent);
     storeAppendPrintf(sentry, "cd.msgs_recv = %d\n",
        f->cd.msgs_recv);
+    storeAppendPrintf(sentry, "cd.memory = %d\n",
+       (int)f->cd.memory.kb);
+    storeAppendPrintf(sentry, "cd.store_memory = %d\n",
+        (int) (store_digest ? store_digest->mask_size/1024 : 0));
     storeAppendPrintf(sentry, "cd.kbytes_sent = %d\n",
        (int) f->cd.kbytes_sent.kb);
     storeAppendPrintf(sentry, "cd.kbytes_recv = %d\n",
        (int) f->cd.kbytes_recv.kb);
-    storeAppendPrintf(sentry, "cd.memory = %d\n",
-       (int)f->cd.memory.kb);
-    storeAppendPrintf(sentry, "cd.local_memory = %d\n",
-       store_digest ? store_digest->mask_size/1024 : 0);
-#endif
-
-#if TOO_MUCH_OUTPUT
-    storeAppendPrintf(sentry, "icp.query_svc_time histogram:\n");
-    statHistDump(&f->icp.query_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "icp.reply_svc_time histogram:\n");
-    statHistDump(&f->icp.reply_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "dns.svc_time histogram:\n");
-    statHistDump(&f->dns.svc_time, sentry, NULL);
 #endif
 
     storeAppendPrintf(sentry, "unlink.requests = %d\n",
@@ -1069,90 +1123,16 @@ statPeerSelect(StoreEntry * sentry)
 static void
 statDigestBlob(StoreEntry * sentry)
 {
-#if SQUID_PEER_DIGEST
-    StatCounters *f = &CountHist[0];
-    StatCounters *l = &CountHist[5];
-    double x;
-
-    storeAppendPrintf(sentry, "client_http.all_svc_time histogram:\n");
-    statHistDump(&f->client_http.all_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "client_http.miss_svc_time histogram:\n");
-    statHistDump(&f->client_http.miss_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "client_http.nm_svc_time histogram:\n");
-    statHistDump(&f->client_http.nm_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "client_http.hit_svc_time histogram:\n");
-    statHistDump(&f->client_http.hit_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "\nicp.query_svc_time histogram:\n");
-    statHistDump(&f->icp.query_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "\nicp.reply_svc_time histogram:\n");
-    statHistDump(&f->icp.reply_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "\nicp.client_svc_time histogram:\n");
-    statHistDump(&f->icp.client_svc_time, sentry, NULL);
-    storeAppendPrintf(sentry, "\ncd.client_svc_time histogram:\n");
-    statHistDump(&f->cd.client_svc_time, sentry, NULL);
-
-    storeAppendPrintf(sentry, "\nMedian service times:\n");
-    x = statHistDeltaMedian(&l->client_http.all_svc_time,
-       &f->client_http.all_svc_time);
-    storeAppendPrintf(sentry, "client_http.all_median_svc_time = %f seconds\n",
-       x / 1000.0);
-    x = statHistDeltaMedian(&l->client_http.miss_svc_time,
-       &f->client_http.miss_svc_time);
-    storeAppendPrintf(sentry, "client_http.miss_median_svc_time = %f seconds\n",
-       x / 1000.0);
-    x = statHistDeltaMedian(&l->client_http.hit_svc_time,
-       &f->client_http.hit_svc_time);
-    storeAppendPrintf(sentry, "client_http.hit_median_svc_time = %f seconds\n",
-       x / 1000.0);
-    x = statHistDeltaMedian(&l->cd.client_svc_time,
-       &f->cd.client_svc_time);
-    storeAppendPrintf(sentry, "cd.client_median_svc_time = %f seconds\n",
-       x / 1000.0);
-    x = statHistDeltaMedian(&l->icp.client_svc_time,
-       &f->icp.client_svc_time);
-    storeAppendPrintf(sentry, "icp.client_median_svc_time = %f seconds\n",
-       x / 1000.0);
-
-    storeAppendPrintf(sentry, "\nTraffic:\n");
-    storeAppendPrintf(sentry, "icp.times_used = %d\n",
-       f->icp.times_used);
-    storeAppendPrintf(sentry, "icp.pkts_sent = %d\n",
-       f->icp.pkts_sent);
-    storeAppendPrintf(sentry, "icp.pkts_recv = %d\n",
-       f->icp.pkts_recv);
-    storeAppendPrintf(sentry, "icp.replies_queued = %d\n",
-       f->icp.replies_queued);
-    storeAppendPrintf(sentry, "icp.kbytes_sent = %d\n",
-       (int) f->icp.kbytes_sent.kb);
-    storeAppendPrintf(sentry, "icp.kbytes_recv = %d\n",
-       (int) f->icp.kbytes_recv.kb);
-    storeAppendPrintf(sentry, "cd.times_used = %d\n",
-       f->cd.times_used);
-    storeAppendPrintf(sentry, "cd.msgs_sent = %d\n",
-       f->cd.msgs_sent);
-    storeAppendPrintf(sentry, "cd.msgs_recv = %d\n",
-       f->cd.msgs_recv);
-    storeAppendPrintf(sentry, "cd.kbytes_sent = %d\n",
-       (int) f->cd.kbytes_sent.kb);
-    storeAppendPrintf(sentry, "cd.kbytes_recv = %d\n",
-       (int) f->cd.kbytes_recv.kb);
-    storeAppendPrintf(sentry, "cd.peer_memory = %d\n",
-       (int) f->cd.memory.kb);
-    storeAppendPrintf(sentry, "cd.store_memory = %d\n",
-       (int) (store_digest ? store_digest->mask_size/1024 : 0));
-    storeAppendPrintf(sentry, "\n");
-#endif
+    storeAppendPrintf(sentry, "\nCounters:\n");
+    statCountersDump(sentry);
+    storeAppendPrintf(sentry, "\nHistograms:\n");
+    statCountersHistograms(sentry);
+    storeAppendPrintf(sentry, "\nPeer Digests:\n");
     statPeerSelect(sentry);
-    storeAppendPrintf(sentry, "\n");
+    storeAppendPrintf(sentry, "\nDigest Report:\n");
     storeDigestReport(sentry);
 }
 
-static void
-statCounters(StoreEntry * e)
-{
-    statCountersDump(e);
-}
-
 static void
 statAvg5min(StoreEntry * e)
 {

diff --git a/src/structs.h b/src/structs.h
index 54fd12d9874ab5a4fcfbe0e164c8c41dec05f5e1..c6d82a44ed7f356c8e953b7360aae8bca53773df 100644 (file)
--- a/src/structs.h
+++ b/src/structs.h
@@ -438,7 +438,6 @@ struct _fde {
     DEFER *defer_check;                /* check if we should defer read */
     void *defer_data;
     CommWriteStateData *rwstate;       /* State data for comm_write */
-    time_t connect_timeout;
 };
 
 struct _fileMap {
@@ -1182,15 +1181,24 @@ struct _StatCounters {
     } server;
     struct {
        int pkts_sent;
+       int queries_sent;
+       int replies_sent;
        int pkts_recv;
+       int queries_recv;
+       int replies_recv;
        int hits_sent;
        int hits_recv;
        int replies_queued;
        int replies_dropped;
        kb_t kbytes_sent;
+       kb_t q_kbytes_sent;
+       kb_t r_kbytes_sent;
        kb_t kbytes_recv;
+       kb_t q_kbytes_recv;
+       kb_t r_kbytes_recv;
        StatHist query_svc_time;
        StatHist reply_svc_time;
+        int query_timeouts;
 #if SQUID_PEER_DIGEST
        StatHist client_svc_time;
        StatHist server_svc_time;