Mailing List Archive

Author: phk
Date: 2006-09-17 21:57:51 +0200 (Sun, 17 Sep 2006)
New Revision: 1053

Modified:
trunk/varnish-cache/bin/varnishd/cache.h
trunk/varnish-cache/bin/varnishd/cache_center.c
trunk/varnish-cache/bin/varnishd/cache_fetch.c
trunk/varnish-cache/bin/varnishd/cache_http.c
trunk/varnish-cache/bin/varnishd/cache_pass.c
trunk/varnish-cache/bin/varnishd/cache_pool.c
trunk/varnish-cache/bin/varnishd/shmlog.c
Log:
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.


Modified: trunk/varnish-cache/bin/varnishd/cache.h
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache.h 2006-09-17 19:31:27 UTC (rev 1052)
+++ trunk/varnish-cache/bin/varnishd/cache.h 2006-09-17 19:57:51 UTC (rev 1053)
@@ -30,6 +30,9 @@

#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 VCL_conf *vcl;
struct srcaddr *srcaddr;
struct acct acct;
+ unsigned char wlog[WLOGSPACE];
+ unsigned char *wlp, *wle;
};

struct workreq {
@@ -348,8 +353,8 @@
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 @@
#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__); \

Modified: trunk/varnish-cache/bin/varnishd/cache_center.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache_center.c 2006-09-17 19:31:27 UTC (rev 1052)
+++ trunk/varnish-cache/bin/varnishd/cache_center.c 2006-09-17 19:57:51 UTC (rev 1053)
@@ -144,7 +144,7 @@
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 @@

/* 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 @@
/* 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 @@
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 @@
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 @@
if (w->nobjhead != NULL)
CHECK_OBJ(w->nobjhead, OBJHEAD_MAGIC);
}
+ WSL_Flush(w);
}

/*

Modified: trunk/varnish-cache/bin/varnishd/cache_fetch.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache_fetch.c 2006-09-17 19:31:27 UTC (rev 1052)
+++ trunk/varnish-cache/bin/varnishd/cache_fetch.c 2006-09-17 19:57:51 UTC (rev 1053)
@@ -317,7 +317,7 @@

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);

Modified: trunk/varnish-cache/bin/varnishd/cache_http.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache_http.c 2006-09-17 19:31:27 UTC (rev 1052)
+++ trunk/varnish-cache/bin/varnishd/cache_http.c 2006-09-17 19:57:51 UTC (rev 1053)
@@ -61,6 +61,9 @@
#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 @@
*/

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 @@
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 @@
/*--------------------------------------------------------------------*/

int
-http_DissectRequest(struct http *hp, int fd)
+http_DissectRequest(struct worker *w, struct http *hp, int fd)
{
char *p;

@@ -358,23 +361,23 @@
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 @@
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 @@
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 @@
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 @@
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));
}

/*--------------------------------------------------------------------*/

Modified: trunk/varnish-cache/bin/varnishd/cache_pass.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache_pass.c 2006-09-17 19:31:27 UTC (rev 1052)
+++ trunk/varnish-cache/bin/varnishd/cache_pass.c 2006-09-17 19:57:51 UTC (rev 1053)
@@ -207,7 +207,7 @@
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 @@

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;

Modified: trunk/varnish-cache/bin/varnishd/cache_pool.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache_pool.c 2006-09-17 19:31:27 UTC (rev 1052)
+++ trunk/varnish-cache/bin/varnishd/cache_pool.c 2006-09-17 19:57:51 UTC (rev 1053)
@@ -182,6 +182,8 @@
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);

Modified: trunk/varnish-cache/bin/varnishd/shmlog.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/shmlog.c 2006-09-17 19:31:27 UTC (rev 1052)
+++ trunk/varnish-cache/bin/varnishd/shmlog.c 2006-09-17 19:57:51 UTC (rev 1053)
@@ -52,6 +52,8 @@
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 @@
p[0] = tag;
}

+/*--------------------------------------------------------------------*/

void
VSL(enum shmlogtag tag, unsigned id, const char *fmt, ...)
@@ -112,7 +115,7 @@
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,7 +140,113 @@
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)
{