From: wessels <>
Date: Fri, 10 Apr 1998 03:32:08 +0000 (+0000)
Subject: Cleaned up ICP logging/counting and ICP/CD stats output
X-Git-Tag: SQUID_3_0_PRE1~3524
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=071a3ae79623f644f3544044423946dd3a35710b;p=thirdparty%2Fsquid.git

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

diff --git a/src/access_log.cc b/src/access_log.cc
index 82b1c36d89..5d774d9925 100644
--- 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 6dce052f58..f4921ef392 100644
--- 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 71a7d1e65a..1b52d7be40 100644
--- 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 a842abd4b3..02318950d4 100644
--- 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 8b9e31119e..88eae243a2 100644
--- 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 54fd12d987..c6d82a44ed 100644
--- 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;