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: http://www.varnish-cache.org/svn/trunk/varnish-cache@1053 d4fa192b-c00b-0410-8231-f00ffab90ce4

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

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);
 }
 
 /*

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

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));
 }
 
 /*--------------------------------------------------------------------*/

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;

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

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