trackrdrd: consolidated VSL wrap logging (suitable for monitoring)

trackrdrd/src/child.c

@@ -519,7 +519,7 @@ static hashentry
         h += n * n;
     } while (probes <= htbl.max_probes);
 
-    /* none eligable for evacuation */
+    /* none eligible for evacuation */
     if ((oldest->insert_time + htbl.mlt) > t) {
         htbl.fail++;
         htbl.insert_probes += probes;
@@ -676,7 +676,7 @@ OSL_Track(void *priv, enum VSL_tag_e tag, unsigned fd, unsigned len,
     float tim, tim_exp_check = 0.0;
 
     /* wrap detection statistics */
-    static const char *pptr = (const char *)UINTPTR_MAX;
+    static const char *pptr = (const char *) UINTPTR_MAX;
 
     static unsigned wrap_start_xid = 0;
     static unsigned wrap_end_xid = 0;
@@ -715,7 +715,7 @@ OSL_Track(void *priv, enum VSL_tag_e tag, unsigned fd, unsigned len,
         LOG_Log(LOG_DEBUG, "%s: XID=%u", VSL_tags[tag], xid);
 
 	if (xid > last_start_xid)
-		last_start_xid = xid;
+            last_start_xid = xid;
 
 	tim = TIM_mono();
         if (! insert(xid, fd, tim)) {
@@ -762,7 +762,7 @@ OSL_Track(void *priv, enum VSL_tag_e tag, unsigned fd, unsigned len,
             (unsigned) reqend_t.tv_sec, reqend_t.tv_nsec);
 
 	if (xid > last_end_xid)
-		last_end_xid = xid;
+            last_end_xid = xid;
 
 	xid_spread_sum += (last_end_xid - last_start_xid);
 	xid_spread_count++;
@@ -792,25 +792,19 @@ OSL_Track(void *priv, enum VSL_tag_e tag, unsigned fd, unsigned len,
     }
 
     /* 
-     * log when the vsl ptr wraps, so we can relate lost records, if
-     * applicable 
+     * log when the vsl ptr wraps, to try to monitor lost records
+     * XXX: this doesn't work when XIDs wrap at UINT_MAX
      */
     if (ptr < pptr) {
-	    LOG_Log(LOG_INFO, "VSL wrap at %u", xid);
-	    if (wrap_start_xid) {
-		    LOG_Log(LOG_INFO, "VSL wrap start xid %10u current %10u delta %10d",
-			wrap_start_xid, last_start_xid, (last_start_xid - wrap_start_xid));
-		    LOG_Log(LOG_INFO, "VSL wrap end   xid %10u current %10u delta %10d",
-			wrap_end_xid, last_end_xid, (last_end_xid - wrap_end_xid));
-		    /* AAARRRGLLL, I confess: yes, I am calculating an average here */
-		    LOG_Log(LOG_INFO, "VSL wrap xid spread is %u - avg xid spread is %f",
-			(last_start_xid - last_end_xid),
-			(1.0 * xid_spread_sum / xid_spread_count));
-		    xid_spread_count = xid_spread_sum = 0;
-	    }
-
-	    wrap_start_xid = last_start_xid;
-	    wrap_end_xid = last_end_xid;
+        if (wrap_start_xid) {
+            LOG_Log(LOG_INFO,
+                "VSL wrap: delta_start=%u delta_end=%u delta_avg=%f",
+                last_start_xid - wrap_start_xid, last_end_xid - wrap_end_xid,
+                1.0 * xid_spread_sum / xid_spread_count);
+            xid_spread_count = xid_spread_sum = 0;
+        }
+        wrap_start_xid = last_start_xid;
+        wrap_end_xid = last_end_xid;
     }
     pptr = ptr;
 

trackrdrd/src/config.c

@@ -114,7 +114,6 @@ CONF_Add(const char *lval, const char *rval)
     confString("varnish.name", varnish_name);
     confString("log.file", log_file);
     confString("varnish.bindump", varnish_bindump);
-    confString("processor.log", processor_log);
     confString("mq.qname", mq_qname);
 
     confUnsigned("maxopen.scale", maxopen_scale);
@@ -231,7 +230,6 @@ CONF_Init(void)
     config.syslog_facility = LOG_LOCAL0;
     config.monitor_interval = 30;
     config.monitor_workers = false;
-    config.processor_log[0] = '\0';
     config.maxopen_scale = DEF_MAXOPEN_SCALE;
     config.maxdone = DEF_MAXDONE;
     config.maxdata = DEF_MAXDATA;
@@ -335,7 +333,6 @@ CONF_Dump(void)
     confdump("syslog.facility = %s", config.syslog_facility_name);
     confdump("monitor.interval = %u", config.monitor_interval);
     confdump("monitor.workers = %s", config.monitor_workers ? "true" : "false");
-    confdump("processor.log = %s", config.processor_log);
     confdump("maxopen.scale = %u", config.maxopen_scale);
     confdump("maxdone = %u", config.maxdone);
     confdump("maxdata = %u", config.maxdata);

trackrdrd/src/test/regress.sh

@@ -22,7 +22,7 @@ CMD="../trackrdrd -D -f varnish.binlog -l - -d -c test.conf"
 # the user running it
 CKSUM=$( $CMD | sed -e 's/\(initializing\) \(.*\)/\1/' | sed -e 's/\(Running as\) \([a-zA-Z0-9]*\)$/\1/' | grep -v 'Not running as root' | cksum)
 
-if [ "$CKSUM" != '1848318102 234119' ]; then
+if [ "$CKSUM" != '358541331 234058' ]; then
     echo "ERROR: Regression test incorrect cksum: $CKSUM"
     exit 1
 fi

trackrdrd/src/trackrdrd.h

@@ -255,7 +255,6 @@ struct config {
     char	syslog_facility_name[BUFSIZ];
     unsigned	monitor_interval;
     bool	monitor_workers;
-    char	processor_log[BUFSIZ];
 
     /* scale: unit is log(2,n), iow scale is taken to the power of 2 */
     unsigned	maxopen_scale;	/* max number of records in *_OPEN state */