Added service-time histograms for client_http and icp

diff --git a/src/client_side.cc b/src/client_side.cc
index db15196135a72b782444d49983b5fd8dd81356b7..e9f6e9af38a79c69e4feaca2fecba43289bf1316 100644 (file)
--- a/src/client_side.cc
+++ b/src/client_side.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: client_side.cc,v 1.208 1998/02/17 18:15:22 wessels Exp $
+ * $Id: client_side.cc,v 1.209 1998/02/18 09:38:14 wessels Exp $
  *
  * DEBUG: section 33    Client-side Routines
  * AUTHOR: Duane Wessels
@@ -524,6 +524,8 @@ clientUpdateCounters(clientHttpRequest * http)
     }
     if (http->request->err_type != ERR_NONE)
        Counter.client_http.errors++;
+    statLogHistCount(&Counter.client_http.svc_time,
+       tvSubMsec(http->start, current_time));
 }
 
 static void

diff --git a/src/icp_v2.cc b/src/icp_v2.cc
index 2d0f9b114a31f332c60f9a704660ba4536cf7e0a..09a05565d9edf3296edfaf51fb5c0d8fe8b49149 100644 (file)
--- a/src/icp_v2.cc
+++ b/src/icp_v2.cc
@@ -50,8 +50,11 @@ icpUdpReply(int fd, void *data)
            kb_incr(&Counter.icp.kbytes_sent, (size_t) x);
        }
        UdpQueueHead = queue->next;
-       if (queue->logcode)
+       if (queue->logcode) {
            icpLogIcp(queue);
+           statLogHistCount(&Counter.icp.svc_time,
+               tvSubUsec(queue->start, current_time));
+       }
        safe_free(queue->msg);
        safe_free(queue);
     }

diff --git a/src/protos.h b/src/protos.h
index 0e07f57947ae98c8c11e816ce2d108b63053980a..f1d2bd8c10614e07614c62840ff3798badc12a90 100644 (file)
--- a/src/protos.h
+++ b/src/protos.h
@@ -372,6 +372,8 @@ extern void identStart(int, ConnStateData *, IDCB * callback);
 extern void statInit(void);
 extern void pconnHistCount(int, int);
 extern int statMemoryAccounted(void);
+extern void statLogHistCount(StatLogHist * H, double val);
+
 
 extern void memInit(void);
 extern void memFreeMemory(void);

diff --git a/src/stat.cc b/src/stat.cc
index 59089830292a4d124368930fceeca51c3130cf63..14e0330e97f265185951d1dd79d21af4a01405dd 100644 (file)
--- a/src/stat.cc
+++ b/src/stat.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: stat.cc,v 1.196 1998/02/12 23:52:16 wessels Exp $
+ * $Id: stat.cc,v 1.197 1998/02/18 09:38:16 wessels Exp $
  *
  * DEBUG: section 18    Cache Manager Statistics
  * AUTHOR: Harvest Derived
@@ -114,6 +114,13 @@ static const char *describeTimestamps(const StoreEntry *);
 static void statAvgTick(void *notused);
 static void statAvgDump(StoreEntry *, int minutes);
 static void statCountersDump(StoreEntry * sentry);
+static void statLogHistInit(StatLogHist * H, int n, DTOI *, DTOD);
+static DTOI statIcpSvcTimeBin;
+static DTOI statHttpSvcTimeBin;
+static DTOD statIcpSvcTimeVal;
+static DTOD statHttpSvcTimeVal;
+static void statCounterInit(StatCounters *);
+static double statLogHistDeltaMedian(StatLogHist * A, StatLogHist * B);
 
 #ifdef XMALLOC_STATISTICS
 static void info_get_mallstat(int, int, StoreEntry *);
@@ -674,6 +681,7 @@ statAvgDump(StoreEntry * sentry, int minutes)
     StatCounters *l;
     double dt;
     double ct;
+    double x;
     assert(N_COUNT_HIST > 1);
     assert(minutes > 0);
     f = &CountHist[0];
@@ -692,6 +700,9 @@ statAvgDump(StoreEntry * sentry, int minutes)
        XAVG(client_http.kbytes_in.kb));
     storeAppendPrintf(sentry, "client_http.kbytes_out = %f/sec\n",
        XAVG(client_http.kbytes_out.kb));
+    x =        statLogHistDeltaMedian(&l->client_http.svc_time, &f->client_http.svc_time);
+    storeAppendPrintf(sentry, "client_http.median_svc_time = %f seconds\n",
+       x / 1000.0);
     storeAppendPrintf(sentry, "icp.pkts_sent = %f/sec\n",
        XAVG(icp.pkts_sent));
     storeAppendPrintf(sentry, "icp.pkts_recv = %f/sec\n",
@@ -700,6 +711,9 @@ statAvgDump(StoreEntry * sentry, int minutes)
        XAVG(icp.kbytes_sent.kb));
     storeAppendPrintf(sentry, "icp.kbytes_recv = %f/sec\n",
        XAVG(icp.kbytes_recv.kb));
+    x = statLogHistDeltaMedian(&l->icp.svc_time, &f->icp.svc_time);
+    storeAppendPrintf(sentry, "icp.median_svc_time = %f seconds\n",
+       x / 1000000.0);
     storeAppendPrintf(sentry, "unlink.requests = %f/sec\n",
        XAVG(unlink.requests));
     storeAppendPrintf(sentry, "page_faults = %f/sec\n",
@@ -711,6 +725,26 @@ statAvgDump(StoreEntry * sentry, int minutes)
     storeAppendPrintf(sentry, "cpu_usage = %f%%\n", dpercent(ct, dt));
 }
 
+static void
+statCounterInit(StatCounters * C)
+{
+    C->timestamp = current_time;
+    /*
+     * HTTP svc_time hist is kept in milli-seconds
+     */
+    statLogHistInit(&C->client_http.svc_time,
+       statHttpSvcTimeBin(3600000.0 * 3.0),
+       statHttpSvcTimeBin,
+       statHttpSvcTimeVal);
+    /*
+     * ICP svc_time hist is kept in micro-seconds
+     */
+    statLogHistInit(&C->icp.svc_time,
+       statIcpSvcTimeBin(1000000.0 * 60.0),
+       statIcpSvcTimeBin,
+       statIcpSvcTimeVal);
+}
+
 void
 statInit(void)
 {
@@ -722,8 +756,8 @@ statInit(void)
     }
     memset(CountHist, '\0', N_COUNT_HIST * sizeof(StatCounters));
     for (i = 0; i < N_COUNT_HIST; i++)
-       CountHist[i].timestamp = current_time;
-    Counter.timestamp = current_time;
+       statCounterInit(&CountHist[i]);
+    statCounterInit(&Counter);
     eventAdd("statAvgTick", statAvgTick, NULL, 60);
 }
 
@@ -804,3 +838,104 @@ statAvg60min(StoreEntry * e)
 {
     statAvgDump(e, 60);
 }
+
+static void
+statLogHistInit(StatLogHist * H, int n, DTOI * val_to_bin, DTOD * bin_to_val)
+{
+    H->nbins = n;
+    H->bins = xcalloc(n, sizeof(int));
+    H->val_to_bin = val_to_bin;
+    H->bin_to_val = bin_to_val;
+}
+
+void
+statLogHistCount(StatLogHist * H, double val)
+{
+    int bin = H->val_to_bin(val);
+    if (bin >= H->nbins)
+       bin = H->nbins - 1;
+    assert(0 <= bin && bin < H->nbins);
+    H->bins[bin]++;
+}
+
+static double
+statLogHistDeltaMedian(StatLogHist * A, StatLogHist * B)
+{
+    StatLogHist D;
+    int i;
+    int s1 = 0;
+    int h = 0;
+    int a = 0;
+    int b = 0;
+    int I;
+    int J;
+    int K;
+    double f;
+    assert(A->nbins == B->nbins);
+    memset(&D, '\0', sizeof(StatLogHist));
+    D.nbins = A->nbins;
+    D.bins = xcalloc(D.nbins, sizeof(int));
+    for (i = 0; i < A->nbins; i++) {
+       assert(B->bins[i] >= A->bins[i]);
+       D.bins[i] = B->bins[i] - A->bins[i];
+    }
+    for (i = 0; i < A->nbins; i++)
+       s1 += D.bins[i];
+    h = s1 >> 1;
+    I = 0;
+    J = A->nbins;
+    for (i = 0; i < A->nbins; i++) {
+       J = i;
+       b += D.bins[J];
+       if (a <= h && h <= b)
+           break;
+       I = i;
+       a += D.bins[I];
+    }
+    safe_free(D.bins);
+    if (s1 == 0)
+       return 0.0;
+    if (a > h) {
+       debug(0,0)("statLogHistDeltaMedian: a=%d, h=%d\n", a, h);
+       return 0.0;
+    }
+    if(a >= b) {
+       debug(0,0)("statLogHistDeltaMedian: a=%d, b=%d\n", a, b);
+       return 0.0;
+    }
+    if(I >= J) {
+       debug(0,0)("statLogHistDeltaMedian: I=%d, J=%d\n", I, J);
+       return 0.0;
+    }
+    f = (h - a) / (b - a);
+    K = f * (double) (J - I) + I;
+    return A->bin_to_val(K);
+}
+
+static int
+statHttpSvcTimeBin(double v)
+{
+    if (v <= 1.0)
+       return 0;
+    return (int) (log(v) * 10.0 + 0.5);
+}
+
+static int
+statIcpSvcTimeBin(double v)
+{
+    if (v <= 1.0)
+       return 0;
+    return (int) (log(v) * 50.0 + 0.5);
+}
+
+static double
+statHttpSvcTimeVal(double bin)
+{
+    return exp(bin / 10.0);
+}
+
+static double
+statIcpSvcTimeVal(double bin)
+{
+    return exp(bin / 50.0);
+}

diff --git a/src/store_rebuild.cc b/src/store_rebuild.cc
index 256c2a67a842a48dbb143183084c4462cf53c936..d6ff4cbc7862b519c19176a5506ef4d65b4e4c9f 100644 (file)
--- a/src/store_rebuild.cc
+++ b/src/store_rebuild.cc
@@ -356,7 +356,10 @@ storeRebuildADirectory(void *unused)
     if (count < 0) {
        xfree(d);
     } else {
-       for (D = &RebuildState.rebuild_dir; *D; D = &(*D)->next);
+       for (D = &RebuildState.rebuild_dir; *D; D = &(*D)->next) {
+               debug(0,0)("D=%p\n", D);
+               debug(0,0)("*D=%p\n", *D);
+       }
        *D = d;
        d->next = NULL;
     }

diff --git a/src/structs.h b/src/structs.h
index 156ac76f8f47826b504471ff99043da23e6c0b45..2353f0d54ccdfa1843d68be2e9445309dbc10374 100644 (file)
--- a/src/structs.h
+++ b/src/structs.h
@@ -924,6 +924,13 @@ struct _ErrorState {
     char *request_hdrs;
 };
 
+struct _StatLogHist {
+    int nbins;
+    int *bins;
+    DTOI *val_to_bin;
+    DTOD *bin_to_val;
+};
+
 struct _StatCounters {
     struct {
        int requests;
@@ -932,7 +939,14 @@ struct _StatCounters {
        kb_t kbytes_in;
        kb_t kbytes_out;
        kb_t hit_kbytes_out;
+       StatLogHist svc_time;
     } client_http;
+    struct {
+       int requests;
+       int errors;
+       kb_t kbytes_in;
+       kb_t kbytes_out;
+    } server;
     struct {
        int pkts_sent;
        int pkts_recv;
@@ -940,6 +954,7 @@ struct _StatCounters {
        int hits_recv;
        kb_t kbytes_sent;
        kb_t kbytes_recv;
+       StatLogHist svc_time;
     } icp;
     struct {
        int requests;

diff --git a/src/typedefs.h b/src/typedefs.h
index dc5e04672a06837db1d7bc08b719fb860d7a3299..f4ee5a823f52eb2af47034b7e5fcd790f4a10b14 100644 (file)
--- a/src/typedefs.h
+++ b/src/typedefs.h
@@ -79,6 +79,7 @@ typedef struct _StatCounters StatCounters;
 typedef struct _tlv tlv;
 typedef struct _storeSwapLogData storeSwapLogData;
 typedef struct _cacheSwap cacheSwap;
+typedef struct _StatLogHist StatLogHist;
 
 /* define AIOCB even without USE_ASYNC_IO */
 typedef void AIOCB(void *, int aio_return, int aio_errno);
@@ -100,6 +101,8 @@ typedef void PSC(peer *, void *);
 typedef void RH(void *data, char *);
 typedef void UH(void *data, wordlist *);
 typedef int DEFER(int fd, void *data);
+typedef int DTOI(double);
+typedef double DTOD(double);
 
 typedef void SIH(int fd, void *);      /* swap in */
 typedef int QS(const void *, const void *);    /* qsort */