From 918e93ad041370d493894169f792b9a99bf523f4 Mon Sep 17 00:00:00 2001 From: phk Date: Sun, 17 Sep 2006 19:57:51 +0000 Subject: [PATCH] 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 --- varnish-cache/bin/varnishd/cache.h | 12 ++- varnish-cache/bin/varnishd/cache_center.c | 13 +-- varnish-cache/bin/varnishd/cache_fetch.c | 2 +- varnish-cache/bin/varnishd/cache_http.c | 37 ++++---- varnish-cache/bin/varnishd/cache_pass.c | 4 +- varnish-cache/bin/varnishd/cache_pool.c | 2 + varnish-cache/bin/varnishd/shmlog.c | 111 +++++++++++++++++++++- 7 files changed, 152 insertions(+), 29 deletions(-) diff --git a/varnish-cache/bin/varnishd/cache.h b/varnish-cache/bin/varnishd/cache.h index ee6c4dca..0c261458 100644 --- 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 29ebba40..ee743523 100644 --- 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 9d3597a6..9c2f8583 100644 --- 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 d0c625d8..5d671b26 100644 --- 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 c116cfb2..00e324e2 100644 --- 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 421d7d8b..ef9849f6 100644 --- 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 70558d81..e54ffaf8 100644 --- 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) { -- 2.39.5