Decontest the shared memory mutex:

Add a log buffer to the worker threads, log a lot of stuff to that
and flush it into the "real" shmbuffer every so often.

git-svn-id: svn+ssh://projects.linpro.no/svn/varnish/trunk@1053 d4fa192b-c00b-0410-8231-f00ffab90ce4

diff --git a/varnish-cache/bin/varnishd/cache.h b/varnish-cache/bin/varnishd/cache.h
index ee6c4dca6e3464cdf94bfffbf2bbbfe5b527a480..0c261458cb2335fc2ebcaa1c635196b756d1f371 100644 (file)
--- a/varnish-cache/bin/varnishd/cache.h
+++ b/varnish-cache/bin/varnishd/cache.h
@@ -30,6 +30,9 @@ enum {
 
 #define MAX_IOVS       (HTTP_HDR_MAX * 2)
 
+/* Amount of per-worker logspace */
+#define WLOGSPACE      8192
+
 struct cli;
 struct vsb;
 struct sess;
@@ -115,6 +118,8 @@ struct worker {
        struct VCL_conf         *vcl;
        struct srcaddr          *srcaddr;
        struct acct             acct;
+       unsigned char           wlog[WLOGSPACE];
+       unsigned char           *wlp, *wle;
 };
 
 struct workreq {
@@ -348,8 +353,8 @@ void http_RecvPrep(struct http *hp);
 int http_RecvPrepAgain(struct http *hp);
 int http_RecvSome(int fd, struct http *hp);
 int http_RecvHead(struct http *hp, int fd);
-int http_DissectRequest(struct http *sp, int fd);
-int http_DissectResponse(struct http *sp, int fd);
+int http_DissectRequest(struct worker *w, struct http *sp, int fd);
+int http_DissectResponse(struct worker *w, struct http *sp, int fd);
 void http_DoConnection(struct sess *sp);
 
 #define HTTPH(a, b, c, d, e, f, g) extern char b[];
@@ -387,6 +392,9 @@ void VSL_Init(void);
 #ifdef SHMLOGHEAD_MAGIC
 void VSLR(enum shmlogtag tag, unsigned id, const char *b, const char *e);
 void VSL(enum shmlogtag tag, unsigned id, const char *fmt, ...);
+void WSLR(struct worker *w, enum shmlogtag tag, unsigned id, const char *b, const char *e);
+void WSL(struct worker *w, enum shmlogtag tag, unsigned id, const char *fmt, ...);
+void WSL_Flush(struct worker *w);
 #define HERE() VSL(SLT_Debug, 0, "HERE: %s(%d)", __func__, __LINE__)
 #define INCOMPL() do {                                                 \
        VSL(SLT_Debug, 0, "INCOMPLETE AT: %s(%d)", __func__, __LINE__); \

diff --git a/varnish-cache/bin/varnishd/cache_center.c b/varnish-cache/bin/varnishd/cache_center.c
index 29ebba4014c49760885035974400ff9efcef4576..ee743523987b6aeac663edfed457ac4635040b85 100644 (file)
--- a/varnish-cache/bin/varnishd/cache_center.c
+++ b/varnish-cache/bin/varnishd/cache_center.c
@@ -144,7 +144,7 @@ cnt_done(struct sess *sp)
        dp = cnt_dt(&sp->t_req, &sp->t_resp);
        da = cnt_dt(&sp->t_resp, &sp->t_end);
        dh = cnt_dt(&sp->t_open, &sp->t_req);
-       VSL(SLT_ReqEnd, sp->id, "%u %ld.%09ld %ld.%09ld %.9f %.9f %.9f",
+       WSL(sp->wrk, SLT_ReqEnd, sp->id, "%u %ld.%09ld %ld.%09ld %.9f %.9f %.9f",
            sp->xid,
            (long)sp->t_req.tv_sec, (long)sp->t_req.tv_nsec,
            (long)sp->t_end.tv_sec, (long)sp->t_end.tv_nsec,
@@ -438,7 +438,7 @@ cnt_lookup2(struct sess *sp)
 
        /* If we encountered busy-object, disembark worker thread */
        if (o == NULL) {
-               VSL(SLT_Debug, sp->fd,
+               WSL(sp->wrk, SLT_Debug, sp->fd,
                    "on waiting list on obj %u", sp->obj->xid);
                SES_Charge(sp);
                return (1);
@@ -456,10 +456,10 @@ cnt_lookup2(struct sess *sp)
        /* Account separately for pass and cache objects */
        if (sp->obj->pass) {
                VSL_stats->cache_hitpass++;
-               VSL(SLT_HitPass, sp->fd, "%u", sp->obj->xid);
+               WSL(sp->wrk, SLT_HitPass, sp->fd, "%u", sp->obj->xid);
        } else {
                VSL_stats->cache_hit++;
-               VSL(SLT_Hit, sp->fd, "%u", sp->obj->xid);
+               WSL(sp->wrk, SLT_Hit, sp->fd, "%u", sp->obj->xid);
        }
        sp->step = STP_HIT;
        return (0);
@@ -652,7 +652,7 @@ cnt_recv(struct sess *sp)
        clock_gettime(CLOCK_REALTIME, &sp->t_req);
        sp->wrk->idle = sp->t_req.tv_sec;
        sp->xid = ++xids;
-       VSL(SLT_ReqStart, sp->fd, "%s %s %u", sp->addr, sp->port,  sp->xid);
+       WSL(sp->wrk, SLT_ReqStart, sp->fd, "%s %s %u", sp->addr, sp->port,  sp->xid);
 
        AZ(sp->vcl);
        VCL_Refresh(&sp->wrk->vcl);
@@ -663,7 +663,7 @@ cnt_recv(struct sess *sp)
        AZ(sp->vbc);
 
        sp->wrk->acct.req++;
-       done = http_DissectRequest(sp->http, sp->fd);
+       done = http_DissectRequest(sp->wrk, sp->http, sp->fd);
        if (done != 0) {
                RES_Error(sp, done, NULL);
                sp->step = STP_DONE;
@@ -743,6 +743,7 @@ CNT_Session(struct sess *sp)
                if (w->nobjhead != NULL)
                        CHECK_OBJ(w->nobjhead, OBJHEAD_MAGIC);
        }
+       WSL_Flush(w);
 }
 
 /*

diff --git a/varnish-cache/bin/varnishd/cache_fetch.c b/varnish-cache/bin/varnishd/cache_fetch.c
index 9d3597a6a279f9175afa0d67f41af4d7a0fc6182..9c2f8583dc32eefb0b60d986a162957b12f52107 100644 (file)
--- a/varnish-cache/bin/varnishd/cache_fetch.c
+++ b/varnish-cache/bin/varnishd/cache_fetch.c
@@ -317,7 +317,7 @@ FetchHeaders(struct sess *sp)
 
        i = http_RecvHead(vc->http, vc->fd);
        xxxassert(i == 0);
-       xxxassert(http_DissectResponse(vc->http, vc->fd) == 0);
+       xxxassert(http_DissectResponse(sp->wrk, vc->http, vc->fd) == 0);
        CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
        CHECK_OBJ_NOTNULL(sp->wrk, WORKER_MAGIC);
        CHECK_OBJ_NOTNULL(sp->obj, OBJECT_MAGIC);

diff --git a/varnish-cache/bin/varnishd/cache_http.c b/varnish-cache/bin/varnishd/cache_http.c
index d0c625d8b285b15805e07d96702e9f8cd9f814f6..5d671b268d3ac98b5a08f597bb2d162b061bb32d 100644 (file)
--- a/varnish-cache/bin/varnishd/cache_http.c
+++ b/varnish-cache/bin/varnishd/cache_http.c
@@ -61,6 +61,9 @@ T(struct http *hp, enum httptag t)
 #define VSLH(ax, bx, cx, dx) \
        VSLR(T((cx), (ax)), (bx), (cx)->hd[(dx)].b, (cx)->hd[(dx)].e);
 
+#define WSLH(wx, ax, bx, cx, dx) \
+       WSLR(wx, T((cx), (ax)), (bx), (cx)->hd[(dx)].b, (cx)->hd[(dx)].e);
+
 /*--------------------------------------------------------------------*/
 
 void
@@ -294,7 +297,7 @@ http_GetStatus(struct http *hp)
  */
 
 static int
-http_dissect_hdrs(struct http *hp, int fd, char *p)
+http_dissect_hdrs(struct worker *w, struct http *hp, int fd, char *p)
 {
        char *q, *r;
 
@@ -325,11 +328,11 @@ http_dissect_hdrs(struct http *hp, int fd, char *p)
                        hp->hdf[hp->nhd] = 0;
                        hp->hd[hp->nhd].b = p;
                        hp->hd[hp->nhd].e = q;
-                       VSLH(HTTP_T_Header, fd, hp, hp->nhd);
+                       WSLH(w, HTTP_T_Header, fd, hp, hp->nhd);
                        hp->nhd++;
                } else {
                        VSL_stats->losthdr++;
-                       VSLR(T(hp, HTTP_T_LostHeader), fd, p, q);
+                       WSLR(w, T(hp, HTTP_T_LostHeader), fd, p, q);
                }
        }
        assert(hp->t <= hp->v);
@@ -340,7 +343,7 @@ http_dissect_hdrs(struct http *hp, int fd, char *p)
 /*--------------------------------------------------------------------*/
 
 int
-http_DissectRequest(struct http *hp, int fd)
+http_DissectRequest(struct worker *w, struct http *hp, int fd)
 {
        char *p;
 
@@ -358,23 +361,23 @@ http_DissectRequest(struct http *hp, int fd)
        for (; isalpha(*p); p++)
                ;
        hp->hd[HTTP_HDR_REQ].e = p;
-       VSLH(HTTP_T_Request, fd, hp, HTTP_HDR_REQ);
+       WSLH(w, HTTP_T_Request, fd, hp, HTTP_HDR_REQ);
        *p++ = '\0';
 
        /* Next find the URI */
        while (isspace(*p) && *p != '\n')
                p++;
        if (*p == '\n') {
-               VSLR(SLT_HttpGarbage, fd, hp->s, hp->v);
+               WSLR(w, SLT_HttpGarbage, fd, hp->s, hp->v);
                return (400);
        }
        hp->hd[HTTP_HDR_URL].b = p;
        while (!isspace(*p))
                p++;
        hp->hd[HTTP_HDR_URL].e = p;
-       VSLH(HTTP_T_URL, fd, hp, HTTP_HDR_URL);
+       WSLH(w, HTTP_T_URL, fd, hp, HTTP_HDR_URL);
        if (*p == '\n') {
-               VSLR(SLT_HttpGarbage, fd, hp->s, hp->v);
+               WSLR(w, SLT_HttpGarbage, fd, hp->s, hp->v);
                return (400);
        }
        *p++ = '\0';
@@ -383,31 +386,31 @@ http_DissectRequest(struct http *hp, int fd)
        while (isspace(*p) && *p != '\n')
                p++;
        if (*p == '\n') {
-               VSLR(SLT_HttpGarbage, fd, hp->s, hp->v);
+               WSLR(w, SLT_HttpGarbage, fd, hp->s, hp->v);
                return (400);
        }
        hp->hd[HTTP_HDR_PROTO].b = p;
        while (!isspace(*p))
                p++;
        hp->hd[HTTP_HDR_PROTO].e = p;
-       VSLH(HTTP_T_Protocol, fd, hp, HTTP_HDR_PROTO);
+       WSLH(w, HTTP_T_Protocol, fd, hp, HTTP_HDR_PROTO);
        if (*p != '\n')
                *p++ = '\0';
        while (isspace(*p) && *p != '\n')
                p++;
        if (*p != '\n') {
-               VSLR(SLT_HttpGarbage, fd, hp->s, hp->v);
+               WSLR(w, SLT_HttpGarbage, fd, hp->s, hp->v);
                return (400);
        }
        *p++ = '\0';
 
-       return (http_dissect_hdrs(hp, fd, p));
+       return (http_dissect_hdrs(w, hp, fd, p));
 }
 
 /*--------------------------------------------------------------------*/
 
 int
-http_DissectResponse(struct http *hp, int fd)
+http_DissectResponse(struct worker *w, struct http *hp, int fd)
 {
        char *p, *q;
 
@@ -425,7 +428,7 @@ http_DissectResponse(struct http *hp, int fd)
        while (!isspace(*p))
                p++;
        hp->hd[HTTP_HDR_PROTO].e = p;
-       VSLH(HTTP_T_Protocol, fd, hp, HTTP_HDR_PROTO);
+       WSLH(w, HTTP_T_Protocol, fd, hp, HTTP_HDR_PROTO);
        *p++ = '\0';
 
        /* Next find the status */
@@ -435,7 +438,7 @@ http_DissectResponse(struct http *hp, int fd)
        while (!isspace(*p))
                p++;
        hp->hd[HTTP_HDR_STATUS].e = p;
-       VSLH(HTTP_T_Status, fd, hp, HTTP_HDR_STATUS);
+       WSLH(w, HTTP_T_Status, fd, hp, HTTP_HDR_STATUS);
        *p++ = '\0';
 
        /* Next find the response */
@@ -449,10 +452,10 @@ http_DissectResponse(struct http *hp, int fd)
                continue;
        *q = '\0';
        hp->hd[HTTP_HDR_RESPONSE].e = q;
-       VSLH(HTTP_T_Response, fd, hp, HTTP_HDR_RESPONSE);
+       WSLH(w, HTTP_T_Response, fd, hp, HTTP_HDR_RESPONSE);
        p++;
 
-       return (http_dissect_hdrs(hp, fd, p));
+       return (http_dissect_hdrs(w, hp, fd, p));
 }
 
 /*--------------------------------------------------------------------*/

diff --git a/varnish-cache/bin/varnishd/cache_pass.c b/varnish-cache/bin/varnishd/cache_pass.c
index c116cfb2edbd8470673ea3aea64f09ef9290786f..00e324e23632b73781aa8e78808d1b8c9c3c14b4 100644 (file)
--- a/varnish-cache/bin/varnishd/cache_pass.c
+++ b/varnish-cache/bin/varnishd/cache_pass.c
@@ -207,7 +207,7 @@ PassSession(struct sess *sp)
                RES_Error(sp, 503, "Backend did not respond.");
                return (1);
        }
-       VSL(SLT_Backend, sp->fd, "%d %s", vc->fd, sp->backend->vcl_name);
+       WSL(w, SLT_Backend, sp->fd, "%d %s", vc->fd, sp->backend->vcl_name);
 
        http_CopyReq(vc->fd, vc->http, sp->http);
        http_FilterHeader(vc->fd, vc->http, sp->http, HTTPH_R_PASS);
@@ -221,7 +221,7 @@ PassSession(struct sess *sp)
 
        i = http_RecvHead(vc->http, vc->fd);
        xxxassert(i == 0);
-       http_DissectResponse(vc->http, vc->fd);
+       http_DissectResponse(w, vc->http, vc->fd);
 
        assert(sp->vbc == NULL);
        sp->vbc = vc;

diff --git a/varnish-cache/bin/varnishd/cache_pool.c b/varnish-cache/bin/varnishd/cache_pool.c
index 421d7d8bb0410d5a43ee62696b23caccff1a1750..ef9849f6b49d1732a1505c172f2570265935a6e5 100644 (file)
--- a/varnish-cache/bin/varnishd/cache_pool.c
+++ b/varnish-cache/bin/varnishd/cache_pool.c
@@ -182,6 +182,8 @@ wrk_thread(void *priv)
        memset(w, 0, sizeof *w);
        w->magic = WORKER_MAGIC;
        w->idle = time(NULL);
+       w->wlp = w->wlog;
+       w->wle = w->wlog + sizeof w->wlog;
        AZ(pipe(w->pipe));
 
        VSL(SLT_WorkThread, 0, "%p start", w);

diff --git a/varnish-cache/bin/varnishd/shmlog.c b/varnish-cache/bin/varnishd/shmlog.c
index 70558d81b4094eb4a3771e1536c22442ff07c5e9..e54ffaf8232fbc3574885a0bc9f8860f34d45777 100644 (file)
--- a/varnish-cache/bin/varnishd/shmlog.c
+++ b/varnish-cache/bin/varnishd/shmlog.c
@@ -52,6 +52,8 @@ vsl_wrap(void)
        logstart[loghead->ptr] = SLT_WRAPMARKER;
        loghead->ptr = 0;
 }
+
+/*--------------------------------------------------------------------*/
  
 void
 VSLR(enum shmlogtag tag, unsigned id, const char *b, const char *e)
@@ -92,6 +94,7 @@ VSLR(enum shmlogtag tag, unsigned id, const char *b, const char *e)
        p[0] = tag;
 }
 
+/*--------------------------------------------------------------------*/
 
 void
 VSL(enum shmlogtag tag, unsigned id, const char *fmt, ...)
@@ -112,7 +115,7 @@ VSL(enum shmlogtag tag, unsigned id, const char *fmt, ...)
        assert(loghead->ptr < loghead->size);
 
        /* Wrap if we cannot fit a full size record */
-       if (loghead->ptr + 5 + 255 + 1 > loghead->size) 
+       if (loghead->ptr + 5 + 255 + 1 >= loghead->size) 
                vsl_wrap();
 
        p = logstart + loghead->ptr;
@@ -137,6 +140,112 @@ VSL(enum shmlogtag tag, unsigned id, const char *fmt, ...)
        va_end(ap);
 }
 
+
+/*--------------------------------------------------------------------*/
+
+void
+WSL_Flush(struct worker *w)
+{
+       unsigned char *p;
+       unsigned l;
+
+       if (w->wlp == w->wlog)
+               return;
+       l = w->wlp - w->wlog;
+       LOCKSHM(&vsl_mtx);
+       if (loghead->ptr + l + 1 >= loghead->size)
+               vsl_wrap();
+       p = logstart + loghead->ptr;
+       memcpy(p + 1, w->wlog + 1, l - 1);
+       p[l] = SLT_ENDMARKER;
+       loghead->ptr += l;
+       assert(loghead->ptr < loghead->size);
+       p[0] = w->wlog[0];
+       UNLOCKSHM(&vsl_mtx);
+       w->wlp = w->wlog;
+}
+
+/*--------------------------------------------------------------------*/
+ 
+void
+WSLR(struct worker *w, enum shmlogtag tag, unsigned id, const char *b, const char *e)
+{
+       unsigned char *p;
+       unsigned l;
+
+       assert(b != NULL);
+       if (e == NULL)
+               e = strchr(b, '\0');
+
+       /* Truncate */
+       l = e - b;
+       if (l > 255) {
+               l = 255;
+               e = b + l;
+       }
+
+       assert(w->wlp < w->wle);
+
+       /* Wrap if necessary */
+       if (w->wlp + 5 + l + 1 >= w->wle)
+               WSL_Flush(w);
+       p = w->wlp;
+       w->wlp += 5 + l;
+       assert(w->wlp < w->wle);
+       p[5 + l] = SLT_ENDMARKER;
+
+       p[1] = l & 0xff;
+       p[2] = (id >> 8) & 0xff;
+       p[3] = id & 0xff;
+       memcpy(p + 4, b, l);
+       p[4 + l] = '\0';
+       p[0] = tag;
+}
+
+/*--------------------------------------------------------------------*/
+
+void
+WSL(struct worker *w, enum shmlogtag tag, unsigned id, const char *fmt, ...)
+{
+       va_list ap;
+       unsigned char *p;
+       unsigned n;
+
+       va_start(ap, fmt);
+
+       p = strchr(fmt, '%');
+       if (p == NULL) {
+               WSLR(w, tag, id, fmt, NULL);
+               return;
+       }
+
+       assert(w->wlp < w->wle);
+
+       /* Wrap if we cannot fit a full size record */
+       if (w->wlp + 5 + 255 + 1 >= w->wle)
+               WSL_Flush(w);
+
+       p = w->wlp;
+       n = 0;
+       if (fmt != NULL) {
+               n = vsnprintf((char *)(p + 4), 256, fmt, ap);
+               if (n > 255)
+                       n = 255;        /* we truncate long fields */
+       }
+       p[1] = n & 0xff;
+       p[2] = (id >> 8) & 0xff;
+       p[3] = id & 0xff;
+       p[4 + n] = '\0';;
+       p[5 + n] = SLT_ENDMARKER;
+       p[0] = tag;
+
+       w->wlp += 5 + n;
+       assert(w->wlp < w->wle);
+       va_end(ap);
+}
+
+/*--------------------------------------------------------------------*/
+
 void
 VSL_Init(void)
 {