trackrdrd: Added the data table, data are now collected for each XID.

Also added the signal handler to dump the table's contents on USR1.

src/Makefile.am

@@ -9,7 +9,8 @@ trackrdrd_SOURCES = \
 	trackrdrd.c \
 	parse.c \
 	log.c \
-	config.c
+	config.c \
+	data.c
 
 trackrdrd_LDADD = \
 	$(VARNISHSRC)/lib/libvarnishcompat/libvarnishcompat.la \

src/data.c

+/*-
+ * Copyright (c) 2012 UPLEX Nils Goroll Systemoptimierung
+ * Copyright (c) 2012 Otto Gmbh & Co KG
+ * All rights reserved
+ * Use only with permission
+ *
+ * Author: Geoffrey Simmons <geoffrey.simmons@uplex.de>
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions
+ * are met:
+ * 1. Redistributions of source code must retain the above copyright
+ *    notice, this list of conditions and the following disclaimer.
+ * 2. Redistributions in binary form must reproduce the above copyright
+ *    notice, this list of conditions and the following disclaimer in the
+ *    documentation and/or other materials provided with the distribution.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
+ * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
+ * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
+ * ARE DISCLAIMED.  IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
+ * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
+ * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
+ * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
+ * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
+ * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
+ * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
+ * SUCH DAMAGE.
+ *
+ */
+
+#include <stdlib.h>
+#include <syslog.h>
+#include <string.h>
+#include <stdint.h>
+#include <limits.h>
+
+#include "libvarnish.h"
+#include "miniobj.h"
+
+#include "trackrdrd.h"
+
+#define MIN_TABLE_SCALE 10
+#define MIN_DATA_SCALE 10
+
+#define INDEX(u) ((u) & (tbl.len - 1))
+
+static const char *statename[3] = { "EMPTY", "OPEN", "DONE" };
+
+/*
+ * N.B.: Hash functions defined for XIDs, which are declared in Varnish as
+ * unsigned int, assuming that they are 32 bit.
+ */
+#if UINT_MAX != UINT32_MAX
+#error "Unsigned ints are not 32 bit"
+#endif
+
+#define rotr(v,n) (((v) >> (n)) | ((v) << (32 - (n))))
+#define USE_JENKMULVEY1
+#define h1(k) jenkmulvey1(k)
+#define h2(k) wang(k)
+
+#ifdef USE_JENKMULVEY1
+/*
+ * http://home.comcast.net/~bretm/hash/3.html
+ * Bret Mulvey ascribes this to Bob Jenkins, but I can't find any
+ * reference to it by Jenkins himself.
+ */
+static uint32_t
+jenkmulvey1(uint32_t n)
+{
+    n += (n << 12);
+    n ^= (n >> 22);
+    n += (n << 4);
+    n ^= (n >> 9);
+    n += (n << 10);
+    n ^= (n >> 2);
+    n += (n << 7);
+    n ^= (n >> 12);
+    return(n);
+}
+#endif
+
+#ifdef USE_JENKMULVEY2
+/*
+ * http://home.comcast.net/~bretm/hash/4.html
+ * Mulvey's modification of the (alleged) Jenkins algorithm
+ */
+static uint32_t
+jenkmulvey2(uint32_t n)
+{
+    n += (n << 16);
+    n ^= (n >> 13);
+    n += (n << 4);
+    n ^= (n >> 7);
+    n += (n << 10);
+    n ^= (n >> 5);
+    n += (n << 8);
+    n ^= (n >> 16);
+    return(n);
+}
+#endif
+
+/*
+ * http://www.cris.com/~Ttwang/tech/inthash.htm
+ */
+static uint32_t
+wang(uint32_t n)
+{
+  n  = ~n + (n << 15); // n = (n << 15) - n - 1;
+  n ^= rotr(n,12);
+  n += (n << 2);
+  n ^= rotr(n,4);
+  n  = (n + (n << 3)) + (n << 11);
+  n ^= rotr(n,16);
+  return n;
+}
+
+static void
+data_Cleanup(void)
+{
+    free(tbl.entry);
+    free(tbl.buf);
+}
+
+static void
+data_logstats(void)
+{
+    LOG_Log(LOG_INFO,
+        "Data table: len=%d collisions=%d insert_probes=%d find_probes=%d "
+        "open=%d done=%d load=%.2f occ_hi=%d seen=%d submitted=%d data_hi=%d",
+        tbl.len, tbl.collisions, tbl.insert_probes, tbl.find_probes,
+        tbl.open, tbl.done, 100.0 * ((float) tbl.open + tbl.done) / tbl.len,
+        tbl.occ_hi, tbl.seen, tbl.submitted, tbl.data_hi);
+}
+
+int
+DATA_Init(void)
+{
+    dataentry *entryptr;
+    char *bufptr;
+    
+    int bufsize = 1 << (config.maxdata_scale + MIN_DATA_SCALE);
+    int entries = 1 << (config.maxopen_scale + MIN_TABLE_SCALE);
+
+    entryptr = (dataentry *) calloc(entries, sizeof(dataentry));
+    if (entryptr == NULL)
+        return(errno);
+
+    bufptr = (char *) calloc(entries, bufsize);
+    if (bufptr == NULL) {
+        free(entryptr);
+        return(errno);
+    }
+
+    datatable init_tbl =
+        { .magic = DATATABLE_MAGIC, .len = entries, .collisions = 0,
+          .insert_probes = 0, .find_probes = 0, .seen = 0, .open = 0, .done = 0,
+          .submitted = 0, .occ_hi = 0, .data_hi = 0, .entry = entryptr,
+          .buf = bufptr };
+    memcpy(&tbl, &init_tbl, sizeof(datatable));
+
+    for (int i = 0; i < entries; i++) {
+        tbl.entry[i].magic = DATA_MAGIC;
+        tbl.entry[i].state = DATA_EMPTY;
+        tbl.entry[i].data = &tbl.buf[i * bufsize];
+    }
+    atexit(data_Cleanup);
+    return(0);
+}
+
+dataentry 
+*DATA_Insert(unsigned xid)
+{
+    uint32_t h = h1(xid);
+    if (tbl.entry[INDEX(h)].state == DATA_EMPTY)
+        return(&tbl.entry[INDEX(h)]);
+    
+    unsigned probes = 0;
+    tbl.collisions++;
+    h += h2(xid);
+    while (++probes <= tbl.len && tbl.entry[INDEX(h)].state != DATA_EMPTY)
+        h++;
+    tbl.insert_probes += probes;
+    if (probes > tbl.len)
+        return(NULL);
+    return(&tbl.entry[INDEX(h)]);
+}
+
+dataentry
+*DATA_Find(unsigned xid)
+{
+    uint32_t h = h1(xid);
+    if (tbl.entry[INDEX(h)].xid == xid)
+        return &tbl.entry[INDEX(h)];
+    h += h2(xid);
+    unsigned probes = 0;
+    while (++probes <= tbl.len && tbl.entry[INDEX(h)].xid != xid)
+        h++;
+    tbl.find_probes += probes;
+    if (probes > tbl.len)
+        return NULL;
+    return &tbl.entry[INDEX(h)];
+}
+
+void
+DATA_Dump(void)
+{
+    for (int i = 0; i < tbl.len; i++) {
+        dataentry entry = tbl.entry[i];
+        if (entry.state == DATA_EMPTY)
+            continue;
+        LOG_Log(LOG_INFO, "Data entry %d: XID=%d tid=%d state=%s data=[%.*s]",
+            i, entry.xid, entry.tid, statename[entry.state], entry.end,
+            entry.data);
+    }
+    data_logstats();
+}

src/log.c

@@ -42,9 +42,6 @@
 #include "libvarnish.h"
 
 static const char *level2name[LOG_DEBUG];
-static const int facilitynum[8] =
-    { LOG_LOCAL0, LOG_LOCAL1, LOG_LOCAL2, LOG_LOCAL3, LOG_LOCAL4, LOG_LOCAL5,
-      LOG_LOCAL6, LOG_LOCAL7 };
 
 static void
 syslog_setlevel(int level)
@@ -78,6 +75,7 @@ stdio_log(int level, const char *msg, ...)
     (void) vfprintf(logconf.out, msg, ap);
     va_end(ap);
     fprintf(logconf.out, "\n");
+    fflush(logconf.out);
 }
 
 static void

src/test/regress.sh

@@ -12,7 +12,7 @@
 # stdout. The cksum must match an expected value.
 
 CKSUM=$(./trackrdrd -f test/varnish.binlog -l - -d -c test/test.conf | cksum)
-if [ "$CKSUM" != '3004877510 166790' ]; then
+if [ "$CKSUM" != '209068317 228977' ]; then
     echo "ERROR: Regression test incorrect cksum: $CKSUM"
     exit 1
 fi

src/test/test.conf

@@ -2,3 +2,5 @@
 log.file = /tmp/trackrdrd.log
 pid.file = /tmp/trackrdrd.pid
 processor.log = /tmp/rdrproc.log
+maxdata.scale = 2
+maxopen.scale = 1

src/trackrdrd.c

@@ -54,6 +54,7 @@
 #include "libvarnish.h"
 #include "vsl.h"
 #include "varnishapi.h"
+#include "miniobj.h"
 
 #include "trackrdrd.h"
 #include "revision.h"
@@ -67,54 +68,71 @@
 
 /*--------------------------------------------------------------------*/
 
+/* XXX: Temporary, for testing */
+static void
+submit(unsigned xid)
+{
+    dataentry *entry;
+    
+    entry = DATA_Find(xid);
+    CHECK_OBJ_NOTNULL(entry, DATA_MAGIC);
+    assert(entry->state == DATA_DONE);
+    LOG_Log(LOG_DEBUG, "submit: data=[%.*s]", entry->end, entry->data);
+    tbl.done--;
+    tbl.submitted++;
+    entry->state = DATA_EMPTY;
+}
+
+static void
+sigusr1(int sig)
+{
+    DATA_Dump();
+    signal(sig, sigusr1);
+}
+
 static int
 OSL_Track(void *priv, enum VSL_tag_e tag, unsigned fd, unsigned len,
           unsigned spec, const char *ptr, uint64_t bitmap)
 {
     unsigned xid;
-#if 0    
-    hashentry *entry;
-#endif    
-    int err;
-    int datalen;
+    dataentry *entry;
+    int err, datalen;
     char *data;
 
     (void) priv;
     (void) bitmap;
-#if 1
-    (void) spec;
-    (void) fd;
-#endif
-#if 0
-    /* if spec != 'c', we may have errors reading from SHM */
-    if (spec & VSL_S_CLIENT == 0)
-        WARN();
-#endif
+
+    /* spec != 'c' */
+    if ((spec & VSL_S_CLIENT) == 0)
+        LOG_Log(LOG_WARNING, "%s: Client bit ('c') not set", VSL_tags[tag]);
     
     switch (tag) {
     case SLT_ReqStart:
 
-        /* May not be able to have the assert()s, if we can't guarantee
-           that data arrive correctly and in the right order.
-           In which case we'll have to have lots of error checking,
-           and ERROR & WARN messages. */
-
         err = Parse_ReqStart(ptr, len, &xid);
         AZ(err);
         LOG_Log(LOG_DEBUG, "%s: XID=%d", VSL_tags[tag], xid);
-#if 0
-        /* assert(!(hash(XID) exists)); */
-        /* init hash(XID); */
-        /* HSH_Insert() should return err if hash(XID) exists */
-        err = HSH_Insert(hashtable, xid, &entry);
-        CHECK_OBJ_NOTNULL(entry, HASHENTRY_MAGIC);
-        /* Rather than assert, arrange for an error message.
-           We may have hashtable at MAX, etc. */
-        AZ(err);
 
-        /* hash(XID).tid = fd; */
+        tbl.seen++;
+        entry = DATA_Insert(xid);
+        if (entry == NULL) {
+            LOG_Log(LOG_ALERT,
+                "%s: Cannot insert data, XID=%d tid=%d DISCARDED",
+                VSL_tags[tag], xid, fd);
+            break;
+        }
+        CHECK_OBJ(entry, DATA_MAGIC);
+        
+        entry->state = DATA_OPEN;
+        entry->xid = xid;
         entry->tid = fd;
-#endif        
+        sprintf(entry->data, "XID=%d", xid);
+        entry->end = strlen(entry->data);
+        if (entry->end > tbl.data_hi)
+            tbl.data_hi = entry->end;
+        tbl.open++;
+        if (tbl.open + tbl.done > tbl.occ_hi)
+            tbl.occ_hi = tbl.open + tbl.done;
         break;
 
     case SLT_VCL_Log:
@@ -128,26 +146,31 @@ OSL_Track(void *priv, enum VSL_tag_e tag, unsigned fd, unsigned len,
         AZ(err);
         LOG_Log(LOG_DEBUG, "%s: XID=%d, data=[%.*s]", VSL_tags[tag],
             xid, datalen, data);
-#if 0
         
         /* assert((hash(XID) exists) && hash(XID).tid == fd
                   && !hash(XID).done); */
-        entry = HSH_Find(hashtable, xid);
-        CHECK_OBJ_NOTNULL(entry, HASHENTRY_MAGIC);
+        entry = DATA_Find(xid);
+        CHECK_OBJ_NOTNULL(entry, DATA_MAGIC);
         assert(entry->xid == xid);
         assert(entry->tid == fd);
-        assert(!entry->done);
-        /* Data overflow should be an error message, not assert. */
-        assert(entry->s + datalen + 1 <= MAX_DATA);
-        
-        /* append data to hash(XID).data; */
-        if (entry->s != 0) {
-            entry->data[entry->s] = '&';
-            entry->s++;
+        assert(entry->state == DATA_OPEN);
+
+        /* Data overflow */
+        /* XXX: Encapsulate (1 << (config.maxdata_scale+10)) */
+        if (entry->end + datalen + 1 > (1 << (config.maxdata_scale+10))) {
+            LOG_Log(LOG_ALERT,
+                "%s: Data too long, XID=%d, current length=%d, "
+                "DISCARDING data=[%.*s]", VSL_tags[tag], xid, entry->end,
+                datalen, data);
+            break;
         }
-        memcpy(&entry->data[entry->s], data, datalen);
-        entry->s += datalen;
-#endif        
+        
+        entry->data[entry->end] = '&';
+        entry->end++;
+        memcpy(&entry->data[entry->end], data, datalen);
+        entry->end += datalen;
+        if (entry->end > tbl.data_hi)
+            tbl.data_hi = entry->end;
         break;
 
     case SLT_ReqEnd:
@@ -157,24 +180,22 @@ OSL_Track(void *priv, enum VSL_tag_e tag, unsigned fd, unsigned len,
         AZ(err);
         LOG_Log(LOG_DEBUG, "%s: XID=%d", VSL_tags[tag], xid);
         
-#if 0        
-        entry = HSH_Find(hashtable, xid);
-        CHECK_OBJ_NOTNULL(entry, HASHENTRY_MAGIC);
+        entry = DATA_Find(xid);
+        CHECK_OBJ_NOTNULL(entry, DATA_MAGIC);
         assert(entry->xid == xid);
         assert(entry->tid == fd);
-        assert(!entry->done);
+        assert(entry->state == DATA_OPEN);
 
         /*hash(XID).done = TRUE;*/
-        entry->done = TRUE;
-        submit(XID);
-#endif        
+        entry->state = DATA_DONE;
+        tbl.done++;
+        tbl.open--;
+        submit(xid);
         break;
 
     default:
-#if 0        
-        /* Should never get here */
-        ERROR();
-#endif        
+        /* Unreachable */
+        AN(NULL);
         return(1);
     }
     return(0);
@@ -192,8 +213,7 @@ usage(int status)
 int
 main(int argc, char * const *argv)
 {
-	int c;
-	int d_flag = 0;
+        int c, d_flag = 0;
 	const char *P_arg = NULL, *l_arg = NULL, *n_arg = NULL, *f_arg = NULL,
             *y_arg = NULL, *c_arg = NULL;
 	struct vpf_fh *pfh = NULL;
@@ -278,6 +298,7 @@ main(int argc, char * const *argv)
         if (LOG_Open(PACKAGE_NAME) != 0) {
             exit(EXIT_FAILURE);
         }
+        
         if (d_flag)
             LOG_SetLevel(LOG_DEBUG);
         LOG_Log0(LOG_INFO, "starting");
@@ -304,9 +325,20 @@ main(int argc, char * const *argv)
 	}
         */
 
-        /* XXX: child opens and reads VSL */
+        /* XXX: child inits data table, opens and reads VSL */
+        if (DATA_Init() != 0) {
+            LOG_Log(LOG_ALERT, "Cannot init data table: %s", strerror(errno));
+            exit(EXIT_FAILURE);
+        }
+
+        /* XXX: Install this signal handler in the child */
+        if (signal(SIGUSR1, sigusr1) == SIG_ERR) {
+            perror("Signal handler USR1:");
+            exit(EXIT_FAILURE);
+        }
+        
 	if (VSL_Open(vd, 1))
-		exit(EXIT_FAILURE);
+            exit(EXIT_FAILURE);
 
         /* Only read the VSL tags relevant to tracking */
         assert(VSL_Arg(vd, 'i', TRACK_TAGS) > 0);

src/trackrdrd.h

@@ -31,9 +31,53 @@
 
 #include <stdio.h>
 
-#define EMPTY(s) (s[0] == '\0')
+/* data.c */
+typedef enum {
+    DATA_EMPTY = 0,
+    /* OPEN when the main thread is filling data, ReqEnd not yet seen. */
+    DATA_OPEN,
+    /* DONE when ReqEnd has been seen, data have not yet been submitted. */
+    DATA_DONE
+} data_state_e;
+
+typedef struct {
+    unsigned 		magic;
+#define DATA_MAGIC 0xb41cb1e1
+    data_state_e	state;
+    unsigned 		xid;
+    unsigned 		tid;	/* 'Thread ID', fd in the callback */
+    unsigned		end;	/* End of string index in data */
+    char		*data;
+} dataentry;
+
+typedef struct {
+    unsigned		magic;
+#define DATATABLE_MAGIC 0xd3ef3bd4
+    const unsigned	len;
+    unsigned		collisions;
+    unsigned		insert_probes;
+    unsigned		find_probes;
+    unsigned		seen;		/* Records (ReqStarts) seen */
+    unsigned		open;
+    unsigned		done;
+    unsigned		submitted;	/* Records submitted */
+    unsigned		occ_hi;		/* Occupancy high water mark */ 
+    unsigned		data_hi;	/* Data high water mark */
+    dataentry		*entry;
+    char		*buf;
+} datatable;
+
+datatable tbl;
+
+/* XXX: inline DATA_Insert and DATA_Find */
+int DATA_Init(void);
+dataentry *DATA_Insert(unsigned xid);
+dataentry *DATA_Find(unsigned xid);
+void DATA_Dump(void);
 
 /* config.c */
+#define EMPTY(s) (s[0] == '\0')
+
 struct config {
     char	pid_file[BUFSIZ];
     char	varnish_name[BUFSIZ];