- eliminated refreshWhen() which was out-of-sync with refreshCheck()

  potentially causing under-utilized cache digests
- maintain refreshCheck statistics on per-protocol basis so we
  can tell why ICP or Digests return too many misses, etc.

diff --git a/ChangeLog b/ChangeLog
index 7cc370d2e839fecb509036973c40bd7c9656860a..2894cf7094e39027bbee5ac95421e5700dcb0cb1 100644 (file)
--- a/ChangeLog
+++ b/ChangeLog
@@ -14,6 +14,10 @@ Changes to Squid-2.1 ():
          bugs.
        - Configurable handling of whitespace in request URI's.
          See 'uri_whitespace' in squid.conf.
+       - Eliminated refreshWhen() which was out-of-sync with refreshCheck()
+         potentially causing under-utilized cache digests
+       - Maintain refreshCheck statistics on per-protocol basis so we
+         can tell why ICP or Digests return too many misses, etc.
 
 Changes to Squid-2.0 (October 2, 1998):
 

diff --git a/src/client_side.cc b/src/client_side.cc
index 9324e93e860020c5e870d1f670deb171ed3d553e..c4de90118baabcc0c684adafd59fc5a8a26c65c3 100644 (file)
--- a/src/client_side.cc
+++ b/src/client_side.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: client_side.cc,v 1.415 1998/10/16 19:19:29 wessels Exp $
+ * $Id: client_side.cc,v 1.416 1998/10/17 04:34:09 rousskov Exp $
  *
  * DEBUG: section 33    Client-side Routines
  * AUTHOR: Duane Wessels
@@ -1197,7 +1197,7 @@ clientCacheHit(void *data, char *buf, ssize_t size)
        if (e->mem_status == IN_MEMORY)
            http->log_type = LOG_TCP_MEM_HIT;
        clientSendMoreData(data, buf, size);
-    } else if (refreshCheck(e, r, 0) && !http->flags.internal) {
+    } else if (refreshCheckHTTP(e, r) && !http->flags.internal) {
        /*
         * We hold a stale copy; it needs to be validated
         */

diff --git a/src/icp_v2.cc b/src/icp_v2.cc
index df2fc986b07c60939f93bb58ddff6e4d9914756c..c2b39b99d73f0b2cd5c775661552af228ae91b47 100644 (file)
--- a/src/icp_v2.cc
+++ b/src/icp_v2.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: icp_v2.cc,v 1.54 1998/10/13 20:35:55 wessels Exp $
+ * $Id: icp_v2.cc,v 1.55 1998/10/17 04:34:10 rousskov Exp $
  *
  * DEBUG: section 12    Internet Cache Protocol
  * AUTHOR: Duane Wessels
@@ -173,7 +173,7 @@ icpCheckUdpHit(StoreEntry * e, request_t * request)
        return 0;
     if (Config.onoff.icp_hit_stale)
        return 1;
-    if (refreshCheck(e, request, 30))
+    if (refreshCheckICP(e, request))
        return 0;
     return 1;
 }

diff --git a/src/protos.h b/src/protos.h
index 1a6a33198cd79af51553b8fd4ce88d71cc3249a4..1265d1cabae1f622d3188b15d0af5228787d643c 100644 (file)
--- a/src/protos.h
+++ b/src/protos.h
@@ -1,6 +1,6 @@
 
 /*
- * $Id: protos.h,v 1.280 1998/10/16 20:02:47 wessels Exp $
+ * $Id: protos.h,v 1.281 1998/10/17 04:34:11 rousskov Exp $
  *
  *
  * SQUID Internet Object Cache  http://squid.nlanr.net/Squid/
@@ -643,8 +643,9 @@ extern void authenticateInit(void);
 extern void authenticateShutdown(void);
 
 extern void refreshAddToList(const char *, int, time_t, int, time_t);
-extern int refreshCheck(const StoreEntry *, request_t *, time_t delta);
-extern time_t refreshWhen(const StoreEntry * entry);
+extern int refreshCheckHTTP(const StoreEntry *, request_t *);
+extern int refreshCheckICP(const StoreEntry *, request_t *);
+extern int refreshCheckDigest(const StoreEntry *, time_t delta);
 extern time_t getMaxAge(const char *url);
 extern void refreshInit(void);
 

diff --git a/src/refresh.cc b/src/refresh.cc
index b931ae7caf885bf0bc7e9f1265a95d49eebcfdf5..d0bf14ef0e2515cecb9b8e9acea1935551d67301 100644 (file)
--- a/src/refresh.cc
+++ b/src/refresh.cc
@@ -1,7 +1,7 @@
 
 
 /*
- * $Id: refresh.cc,v 1.36 1998/09/19 17:06:09 wessels Exp $
+ * $Id: refresh.cc,v 1.37 1998/10/17 04:34:12 rousskov Exp $
  *
  * DEBUG: section 22    Refresh Calculation
  * AUTHOR: Harvest Derived
@@ -40,7 +40,10 @@
 
 #include "squid.h"
 
-struct {
+typedef enum { rcHTTP, rcICP, rcCDigest, rcCount } refreshCountsEnum;
+
+static struct RefreshCounts {
+    const char *proto;
     int total;
     int revalidate_stale;
     int request_max_age_stale;
@@ -51,7 +54,7 @@ struct {
     int last_modified_factor_stale;
     int conf_min_age_fresh;
     int default_stale;
-} refreshCounts;
+} refreshCounts[rcCount];
 
 /*
  * Defaults:
@@ -89,15 +92,16 @@ refreshUncompiledPattern(const char *pat)
     return NULL;
 }
 
-/*
- * refreshCheck():
- *     return 1 if its time to revalidate this entry, 0 otherwise
+/*  return 1 if the entry must be revalidated within delta seconds
+ *         0 otherwise
+ *
+ *  note: request maybe null (e.g. for cache digests build)
  */
-int
-refreshCheck(const StoreEntry * entry, request_t * request, time_t delta)
+static int
+refreshCheck(const StoreEntry * entry, request_t * request, time_t delta, struct RefreshCounts *rc)
 {
     const refresh_t *R;
-    const char *uri;
+    const char *uri = NULL;
     time_t min = REFRESH_DEFAULT_MIN;
     double pct = REFRESH_DEFAULT_PCT;
     time_t max = REFRESH_DEFAULT_MAX;
@@ -107,22 +111,24 @@ refreshCheck(const StoreEntry * entry, request_t * request, time_t delta)
     int reload_into_ims = 0;
     int ignore_reload = 0;
 #endif
-    const char *pattern = ".";
+    const char *pattern = "<none>";
     time_t age;
     double factor;
     time_t check_time = squid_curtime + delta;
     if (entry->mem_obj)
        uri = entry->mem_obj->url;
     else
+    if (request)
        uri = urlCanonical(request);
-    debug(22, 3) ("refreshCheck: '%s'\n", uri);
-    refreshCounts.total++;
+    
+    debug(22, 3) ("refreshCheck(%s): '%s'\n", rc->proto, uri ? uri : "<none>");
+    rc->total++;
     if (EBIT_TEST(entry->flags, ENTRY_REVALIDATE)) {
        debug(22, 3) ("refreshCheck: YES: Required Authorization\n");
-       refreshCounts.revalidate_stale++;
+       rc->revalidate_stale++;
        return 1;
     }
-    if ((R = refreshLimits(uri))) {
+    if ((R = uri ? refreshLimits(uri) : refreshUncompiledPattern("."))) {
        min = R->min;
        pct = R->pct;
        max = R->max;
@@ -144,28 +150,31 @@ refreshCheck(const StoreEntry * entry, request_t * request, time_t delta)
     debug(22, 3) ("refreshCheck: age = %d\n", (int) age);
     debug(22, 3) ("\tcheck_time:\t%s\n", mkrfc1123(check_time));
     debug(22, 3) ("\tentry->timestamp:\t%s\n", mkrfc1123(entry->timestamp));
+    /* request-specific checks */
+    if (request) {
 #if HTTP_VIOLATIONS
-    if (request->flags.nocache_hack) {
-       if (ignore_reload) {
-           /* The clients no-cache header is ignored */
-           debug(22, 3) ("refreshCheck: MAYBE: ignore-reload\n");
-       } else if (reload_into_ims) {
-           /* The clients no-cache header is changed into a IMS query */
-           debug(22, 3) ("refreshCheck: YES: reload-into-ims\n");
-           return 1;
-       } else {
-           /* The clients no-cache header is not overridden on this request */
-           debug(22, 3) ("refreshCheck: YES: client reload\n");
-           request->flags.nocache = 1;
-           return 1;
+       if (request->flags.nocache_hack) {
+           if (ignore_reload) {
+               /* The clients no-cache header is ignored */
+               debug(22, 3) ("refreshCheck: MAYBE: ignore-reload\n");
+           } else if (reload_into_ims) {
+               /* The clients no-cache header is changed into a IMS query */
+               debug(22, 3) ("refreshCheck: YES: reload-into-ims\n");
+               return 1;
+           } else {
+               /* The clients no-cache header is not overridden on this request */
+               debug(22, 3) ("refreshCheck: YES: client reload\n");
+               request->flags.nocache = 1;
+               return 1;
+           }
        }
-    }
 #endif
-    if (request->max_age > -1) {
-       if (age > request->max_age) {
-           debug(22, 3) ("refreshCheck: YES: age > client-max-age\n");
-           refreshCounts.request_max_age_stale++;
-           return 1;
+       if (request->max_age > -1) {
+           if (age > request->max_age) {
+               debug(22, 3) ("refreshCheck: YES: age > client-max-age\n");
+               rc->request_max_age_stale++;
+               return 1;
+           }
        }
     }
 #if HTTP_VIOLATIONS
@@ -177,17 +186,17 @@ refreshCheck(const StoreEntry * entry, request_t * request, time_t delta)
     if (entry->expires > -1) {
        if (entry->expires <= check_time) {
            debug(22, 3) ("refreshCheck: YES: expires <= curtime\n");
-           refreshCounts.response_expires_stale++;
+           rc->response_expires_stale++;
            return 1;
        } else {
            debug(22, 3) ("refreshCheck: NO: expires > curtime\n");
-           refreshCounts.response_expires_fresh++;
+           rc->response_expires_fresh++;
            return 0;
        }
     }
     if (age > max) {
        debug(22, 3) ("refreshCheck: YES: age > max\n");
-       refreshCounts.conf_max_age_stale++;
+       rc->conf_max_age_stale++;
        return 1;
     }
 #if HTTP_VIOLATIONS
@@ -201,77 +210,40 @@ refreshCheck(const StoreEntry * entry, request_t * request, time_t delta)
        debug(22, 3) ("refreshCheck: factor = %f\n", factor);
        if (factor < pct) {
            debug(22, 3) ("refreshCheck: NO: factor < pct\n");
-           refreshCounts.last_modified_factor_fresh++;
+           rc->last_modified_factor_fresh++;
            return 0;
        } else {
            debug(22, 3) ("refreshCheck: YES: factor >= pct\n");
-           refreshCounts.last_modified_factor_stale++;
+           rc->last_modified_factor_stale++;
            return 1;
        }
     }
     if (age <= min) {
        debug(22, 3) ("refreshCheck: NO: age < min\n");
-       refreshCounts.conf_min_age_fresh++;
+       rc->conf_min_age_fresh++;
        return 0;
     }
     debug(22, 3) ("refreshCheck: YES: default stale\n");
-    refreshCounts.default_stale++;
+    rc->default_stale++;
     return 1;
 }
 
-/* returns an approximate time when refreshCheck() may return true */
-time_t
-refreshWhen(const StoreEntry * entry)
-{
-    const refresh_t *R;
-    time_t refresh_time = squid_curtime;
-    time_t min = REFRESH_DEFAULT_MIN;
-    time_t max = REFRESH_DEFAULT_MAX;
-    double pct = REFRESH_DEFAULT_PCT;
-    const char *pattern = ".";
-    if (entry->mem_obj) {
-       assert(entry->mem_obj->url);
-       debug(22, 3) ("refreshWhen: key '%s'\n", storeKeyText(entry->key));
-       debug(22, 3) ("refreshWhen: url '%s'\n", entry->mem_obj->url);
-       if (EBIT_TEST(entry->flags, ENTRY_REVALIDATE)) {
-           debug(22, 3) ("refreshWhen: NOW: Required Authorization\n");
-           return refresh_time;
-       }
-       debug(22, 3) ("refreshWhen: entry: exp: %d, tstamp: %d, lmt: %d\n",
-           entry->expires, entry->timestamp, entry->lastmod);
-       R = refreshLimits(entry->mem_obj->url);
-    } else {
-       R = refreshUncompiledPattern(".");
-    }
-    if (R != NULL) {
-       min = R->min;
-       max = R->max;
-       pct = R->pct;
-       pattern = R->pattern;
-    }
-    debug(22, 3) ("refreshWhen: Matched '%s %d %d%% %d'\n",
-       pattern, (int) min, (int) (100.0 * pct), (int) max);
-    /* convert to absolute numbers */
-    min += entry->timestamp;
-    max += entry->timestamp;
-    if (-1 < entry->expires) {
-       debug(22, 3) ("refreshWhen: expires set\n");
-       refresh_time = entry->expires;
-    } else if (entry->timestamp <= entry->lastmod) {
-       debug(22, 3) ("refreshWhen: lastvalid <= lastmod\n");
-       refresh_time = squid_curtime;
-    } else {
-       refresh_time = (entry->timestamp - entry->lastmod) * pct + entry->timestamp;
-       debug(22, 3) ("refreshWhen: using refresh pct\n");
-    }
-    /* take min/max into account, max takes priority over min */
-    if (refresh_time < min)
-       refresh_time = min;
-    if (refresh_time > max)
-       refresh_time = max;
-    debug(22, 3) ("refreshWhen: answer: %d (in %d secs)\n",
-       refresh_time, (int) (refresh_time - squid_curtime));
-    return refresh_time;
+/* refreshCheck... functions below are protocol-specific wrappers around
+ * refreshCheck() function above */
+
+int
+refreshCheckHTTP(const StoreEntry * entry, request_t * request) {
+    return refreshCheck(entry, request, 0, refreshCounts + rcHTTP);
+}
+
+int
+refreshCheckICP(const StoreEntry * entry, request_t * request) {
+    return refreshCheck(entry, request, 30, refreshCounts + rcICP);
+}
+
+int
+refreshCheckDigest(const StoreEntry * entry, time_t delta) {
+    return refreshCheck(entry, NULL, delta, refreshCounts + rcCDigest);
 }
 
 time_t
@@ -285,34 +257,67 @@ getMaxAge(const char *url)
        return REFRESH_DEFAULT_MAX;
 }
 
+static void
+refreshCountsStats(StoreEntry * sentry, struct RefreshCounts *rc)
+{
+    storeAppendPrintf(sentry, "\n\n%s histogram:\n", rc->proto);
+    storeAppendPrintf(sentry, "Category\tCount\t%%Total\n");
+
+    storeAppendPrintf(sentry, "revalidate_stale\t%6d\t%6.2f\n",
+       rc->revalidate_stale, xpercent(rc->revalidate_stale, rc->total));
+    storeAppendPrintf(sentry, "request_max_age_stale\t%6d\t%6.2f\n",
+       rc->request_max_age_stale, xpercent(rc->revalidate_stale, rc->total));
+    storeAppendPrintf(sentry, "response_expires_stale\t%6d\t%6.2f\n",
+       rc->response_expires_stale, xpercent(rc->revalidate_stale, rc->total));
+    storeAppendPrintf(sentry, "response_expires_fresh\t%6d\t%6.2f\n",
+       rc->response_expires_fresh, xpercent(rc->response_expires_fresh, rc->total));
+    storeAppendPrintf(sentry, "conf_max_age_stale\t%6d\t%6.2f\n",
+       rc->conf_max_age_stale, xpercent(rc->conf_max_age_stale, rc->total));
+    storeAppendPrintf(sentry, "last_modified_factor_fresh\t%6d\t%6.2f\n",
+       rc->last_modified_factor_fresh, xpercent(rc->last_modified_factor_fresh, rc->total));
+    storeAppendPrintf(sentry, "last_modified_factor_stale\t%6d\t%6.2f\n",
+       rc->last_modified_factor_stale, xpercent(rc->last_modified_factor_stale, rc->total));
+    storeAppendPrintf(sentry, "conf_min_age_fresh\t%6d\t%6.2f\n",
+       rc->conf_min_age_fresh, xpercent(rc->conf_min_age_fresh, rc->total));
+    storeAppendPrintf(sentry, "default_stale\t%6d\t%6.2f\n",
+       rc->default_stale, xpercent(rc->default_stale, rc->total));
+    storeAppendPrintf(sentry, "total\t%6d\t%6.2f\n",
+       rc->total, xpercent(rc->total, rc->total));
+}
+
 static void
 refreshStats(StoreEntry * sentry)
 {
-    storeAppendPrintf(sentry, "refreshCounts.total\t%d\n",
-       refreshCounts.total);
-    storeAppendPrintf(sentry, "refreshCounts.revalidate_stale\t%d\n",
-       refreshCounts.revalidate_stale);
-    storeAppendPrintf(sentry, "refreshCounts.request_max_age_stale\t%d\n",
-       refreshCounts.request_max_age_stale);
-    storeAppendPrintf(sentry, "refreshCounts.response_expires_stale\t%d\n",
-       refreshCounts.response_expires_stale);
-    storeAppendPrintf(sentry, "refreshCounts.response_expires_fresh\t%d\n",
-       refreshCounts.response_expires_fresh);
-    storeAppendPrintf(sentry, "refreshCounts.conf_max_age_stale\t%d\n",
-       refreshCounts.conf_max_age_stale);
-    storeAppendPrintf(sentry, "refreshCounts.last_modified_factor_fresh\t%d\n",
-       refreshCounts.last_modified_factor_fresh);
-    storeAppendPrintf(sentry, "refreshCounts.last_modified_factor_stale\t%d\n",
-       refreshCounts.last_modified_factor_stale);
-    storeAppendPrintf(sentry, "refreshCounts.conf_min_age_fresh\t%d\n",
-       refreshCounts.conf_min_age_fresh);
-    storeAppendPrintf(sentry, "refreshCounts.default_stale\t%d\n",
-       refreshCounts.default_stale);
+    int i;
+    int total = 0;
+
+    /* get total usage count */
+    for (i = 0; i < rcCount; ++i)
+       total += refreshCounts[i].total;
+
+    /* protocol usage histogram */
+    storeAppendPrintf(sentry, "\nRefreshCheck calls per protocol\n\n");
+    storeAppendPrintf(sentry, "Protocol\t#Calls\t%%Calls\n");
+    for (i = 0; i < rcCount; ++i)
+       storeAppendPrintf(sentry, "%10s\t%6d\t%6.2f\n",
+           refreshCounts[i].proto,
+           refreshCounts[i].total, 
+           xpercent(refreshCounts[i].total, total));
+
+    /* per protocol histograms */
+    storeAppendPrintf(sentry, "\n\nRefreshCheck histograms for various protocols\n");
+    for (i = 0; i < rcCount; ++i)
+       refreshCountsStats(sentry, refreshCounts + i);
 }
 
 void
-refreshInit(void)
+refreshInit()
 {
+    memset(refreshCounts, 0, sizeof(refreshCounts));
+    refreshCounts[rcHTTP].proto = "HTTP";
+    refreshCounts[rcICP].proto = "ICP";
+    refreshCounts[rcCDigest].proto = "Cache Digests";
+
     cachemgrRegister("refresh",
        "Refresh Algorithm Statistics",
        refreshStats,

diff --git a/src/store_digest.cc b/src/store_digest.cc
index dcc09ef83aecff1d6b91bb9a14b93b2d08786413..6b6d820f9c80f1de110bedfda2d89bae580d2e12 100644 (file)
--- a/src/store_digest.cc
+++ b/src/store_digest.cc
@@ -1,5 +1,5 @@
 /*
- * $Id: store_digest.cc,v 1.28 1998/09/19 17:06:13 wessels Exp $
+ * $Id: store_digest.cc,v 1.29 1998/10/17 04:34:12 rousskov Exp $
  *
  * DEBUG: section 71    Store Digest Manager
  * AUTHOR: Alex Rousskov
@@ -189,13 +189,11 @@ storeDigestAdd(const StoreEntry * entry)
        storeKeyText(entry->key));
     /* only public entries are digested */
     if (!EBIT_TEST(entry->flags, KEY_PRIVATE)) {
-       const time_t refresh = refreshWhen(entry);
-       debug(71, 6) ("storeDigestAdd: entry expires in %d secs\n",
-           (int) (refresh - squid_curtime));
        /* if expires too soon, ignore */
-       /* Note: We should use the time of the next rebuild, not cur_time @?@ */
-       if (refresh <= squid_curtime + StoreDigestRebuildPeriod) {
-           debug(71, 6) ("storeDigestAdd: entry expires too early, ignoring\n");
+       /* Note: We should use the time of the next rebuild, not (cur_time+period) */
+       if (refreshCheckDigest(entry, StoreDigestRebuildPeriod)) {
+           debug(71, 6) ("storeDigestAdd: entry expires within %d secs, ignoring\n", 
+               StoreDigestRebuildPeriod);
        } else {
            good_entry = 1;
        }