From 171497c8676641aa64f8df0006ce4d346dbd4305 Mon Sep 17 00:00:00 2001 From: phk Date: Tue, 1 Aug 2006 09:39:52 +0000 Subject: [PATCH] Record timestamp when we have received completed HTTP request header, and define this as the "start of request timestamp". Define "end of request timestamp" as when we are ready to transmit HTTP header back. SHMlog the start and difference between start and stop with ReqServTime tag. Keep track of idle sessions using CLOCK_MONOTONIC to avoid trouble here should our clock get stepped. git-svn-id: svn+ssh://projects.linpro.no/svn/varnish/trunk@583 d4fa192b-c00b-0410-8231-f00ffab90ce4 --- varnish-cache/bin/varnishd/cache.h | 4 ++-- varnish-cache/bin/varnishd/cache_acceptor.c | 10 +++++----- varnish-cache/bin/varnishd/cache_fetch.c | 5 +++-- varnish-cache/bin/varnishd/cache_hash.c | 2 +- varnish-cache/bin/varnishd/cache_pool.c | 2 +- varnish-cache/bin/varnishd/cache_response.c | 14 +++++++++++--- varnish-cache/bin/varnishd/cache_vrt.c | 15 ++++++++++++--- varnish-cache/bin/varnishd/rfc2616.c | 20 +++++++++----------- varnish-cache/include/shmlog_tags.h | 1 + 9 files changed, 45 insertions(+), 28 deletions(-) diff --git a/varnish-cache/bin/varnishd/cache.h b/varnish-cache/bin/varnishd/cache.h index 84d6a4ed..9ee3e61b 100644 --- a/varnish-cache/bin/varnishd/cache.h +++ b/varnish-cache/bin/varnishd/cache.h @@ -243,8 +243,8 @@ struct sess { const char *doclose; struct http *http; - time_t t_req; - time_t t_resp; + struct timespec t_req; + struct timespec t_idle; enum step step; unsigned handling; diff --git a/varnish-cache/bin/varnishd/cache_acceptor.c b/varnish-cache/bin/varnishd/cache_acceptor.c index 840f6abd..2660d695 100644 --- a/varnish-cache/bin/varnishd/cache_acceptor.c +++ b/varnish-cache/bin/varnishd/cache_acceptor.c @@ -41,15 +41,15 @@ static void vca_tick(int a, short b, void *c) { struct sess *sp, *sp2; - time_t t; + struct timespec t; (void)a; (void)b; (void)c; AZ(evtimer_add(&tick_e, &tick_rate)); - (void)time(&t); + clock_gettime(CLOCK_MONOTONIC, &t); TAILQ_FOREACH_SAFE(sp, &sesshead, list, sp2) { - if (sp->t_resp + 30 < t) { + if (sp->t_idle.tv_sec + 30 < t.tv_sec) { TAILQ_REMOVE(&sesshead, sp, list); vca_close_session(sp, "timeout"); vca_return_session(sp); @@ -88,7 +88,7 @@ pipe_f(int fd, short event, void *arg) (void)arg; i = read(fd, &sp, sizeof sp); assert(i == sizeof sp); - sp->t_resp = time(NULL); + clock_gettime(CLOCK_MONOTONIC, &sp->t_idle); TAILQ_INSERT_TAIL(&sesshead, sp, list); http_RecvHead(sp->http, sp->fd, evb, vca_callback, sp); } @@ -132,7 +132,7 @@ accept_f(int fd, short event, void *arg) TCP_name(addr, l, sp->addr, sizeof sp->addr, sp->port, sizeof sp->port); VSL(SLT_SessionOpen, sp->fd, "%s %s", sp->addr, sp->port); - (void)time(&sp->t_resp); + clock_gettime(CLOCK_MONOTONIC, &sp->t_idle); TAILQ_INSERT_TAIL(&sesshead, sp, list); http_RecvHead(sp->http, sp->fd, evb, vca_callback, sp); } diff --git a/varnish-cache/bin/varnishd/cache_fetch.c b/varnish-cache/bin/varnishd/cache_fetch.c index 27f05cac..a7919db6 100644 --- a/varnish-cache/bin/varnishd/cache_fetch.c +++ b/varnish-cache/bin/varnishd/cache_fetch.c @@ -291,7 +291,6 @@ FetchHeaders(struct sess *sp) sp->backend->hostname); } - sp->t_req = time(NULL); WRK_Reset(w, &vc->fd); http_Write(w, vc->http, 0); i = WRK_Flush(w); @@ -303,8 +302,10 @@ FetchHeaders(struct sess *sp) */ http_RecvHead(vc->http, vc->fd, w->eb, NULL, NULL); (void)event_base_loop(w->eb, 0); - sp->t_resp = time(NULL); assert(http_DissectResponse(vc->http, vc->fd) == 0); sp->vbc = vc; + + sp->obj->entered = time(NULL); + return (0); } diff --git a/varnish-cache/bin/varnishd/cache_hash.c b/varnish-cache/bin/varnishd/cache_hash.c index f02ac182..5b8f9116 100644 --- a/varnish-cache/bin/varnishd/cache_hash.c +++ b/varnish-cache/bin/varnishd/cache_hash.c @@ -108,7 +108,7 @@ HSH_Lookup(struct sess *sp) /* ignore */ } else if (o->ttl == 0) { /* Object banned but not reaped yet */ - } else if (o->ttl < sp->t_req) { + } else if (o->ttl < sp->t_req.tv_sec) { /* Object expired */ } else if (BAN_CheckObject(o, url)) { o->ttl = 0; diff --git a/varnish-cache/bin/varnishd/cache_pool.c b/varnish-cache/bin/varnishd/cache_pool.c index 601ef47c..bfe59dae 100644 --- a/varnish-cache/bin/varnishd/cache_pool.c +++ b/varnish-cache/bin/varnishd/cache_pool.c @@ -189,7 +189,7 @@ WRK_QueueSession(struct sess *sp) struct worker *w; pthread_t tp; - sp->t_req = time(NULL); + clock_gettime(CLOCK_REALTIME, &sp->t_req); sp->workreq.sess = sp; diff --git a/varnish-cache/bin/varnishd/cache_response.c b/varnish-cache/bin/varnishd/cache_response.c index 78f9c4c7..2aab60fe 100644 --- a/varnish-cache/bin/varnishd/cache_response.c +++ b/varnish-cache/bin/varnishd/cache_response.c @@ -33,7 +33,7 @@ RES_Error(struct sess *sp, int error, const char *msg) sbuf_clear(sb); sbuf_printf(sb, "HTTP/1.1 %03d %s\r\n", error, msg); - TIM_format(sp->t_req, buf); + TIM_format(sp->t_req.tv_sec, buf); sbuf_printf(sb, "Date: %s\r\n", buf); sbuf_cat(sb, "Server: Varnish\r\n" @@ -106,7 +106,7 @@ res_do_conds(struct sess *sp) if (sp->obj->last_modified > 0 && http_GetHdr(sp->http, H_If_Modified_Since, &p)) { ims = TIM_parse(p); - if (ims > sp->t_req) /* [RFC2616 14.25] */ + if (ims > sp->t_req.tv_sec) /* [RFC2616 14.25] */ return (0); if (ims > sp->obj->last_modified) { VSL(SLT_Debug, sp->fd, @@ -128,7 +128,15 @@ RES_WriteObj(struct sess *sp) { struct storage *st; unsigned u = 0; + double dt; + struct timespec t_resp; + clock_gettime(CLOCK_REALTIME, &t_resp); + dt = (t_resp.tv_sec - sp->t_req.tv_sec); + dt += (t_resp.tv_nsec - sp->t_req.tv_nsec) * 1e-9; + VSL(SLT_ReqServTime, sp->fd, "%ld.%09ld %.9f", + (long)sp->t_req.tv_sec, (long)sp->t_req.tv_nsec, dt); + if (sp->obj->response == 200 && sp->http->conds && res_do_conds(sp)) return; @@ -144,7 +152,7 @@ RES_WriteObj(struct sess *sp) else http_PrintfHeader(sp->fd, sp->http, "X-Varnish: %u", sp->xid); http_PrintfHeader(sp->fd, sp->http, "Age: %u", - sp->obj->age + sp->t_req - sp->obj->entered); + sp->obj->age + sp->t_req.tv_sec - sp->obj->entered); http_SetHeader(sp->fd, sp->http, "Via: 1.1 varnish"); if (sp->doclose != NULL) http_SetHeader(sp->fd, sp->http, "Connection: close"); diff --git a/varnish-cache/bin/varnishd/cache_vrt.c b/varnish-cache/bin/varnishd/cache_vrt.c index 254c3286..4e29b0cd 100644 --- a/varnish-cache/bin/varnishd/cache_vrt.c +++ b/varnish-cache/bin/varnishd/cache_vrt.c @@ -119,7 +119,16 @@ VRT_r_backend_##onm(struct backend *be) \ VBACKEND(const char *, host, hostname) VBACKEND(const char *, port, portname) -/*--------------------------------------------------------------------*/ +/*-------------------------------------------------------------------- + * XXX: Working relative to t_req is maybe not the right thing, we could + * XXX: have spent a long time talking to the backend since then. + * XXX: It might make sense to cache a timestamp as "current time" + * XXX: before vcl_recv (== t_req) and vcl_fetch. + * XXX: On the other hand, that might lead to inconsistent behaviour + * XXX: where an object expires while we are running VCL code, and + * XXX: and that may not be a good idea either. + * XXX: See also related t_req use in cache_hash.c + */ void VRT_l_obj_ttl(struct sess *sp, double a) @@ -130,7 +139,7 @@ VRT_l_obj_ttl(struct sess *sp, double a) VSL(SLT_TTL, sp->fd, "%u VCL %.0f %u", sp->obj->xid, a, sp->t_req); if (a < 0) a = 0; - sp->obj->ttl = sp->t_req + (int)a; + sp->obj->ttl = sp->t_req.tv_sec + (int)a; if (sp->obj->heap_idx != 0) EXP_TTLchange(sp->obj); } @@ -140,7 +149,7 @@ VRT_r_obj_ttl(struct sess *sp) { CHECK_OBJ_NOTNULL(sp, SESS_MAGIC); CHECK_OBJ_NOTNULL(sp->obj, OBJECT_MAGIC); /* XXX */ - return (sp->obj->ttl - sp->t_req); + return (sp->obj->ttl - sp->t_req.tv_sec); } /*--------------------------------------------------------------------*/ diff --git a/varnish-cache/bin/varnishd/rfc2616.c b/varnish-cache/bin/varnishd/rfc2616.c index ee6e1631..7428e8ad 100644 --- a/varnish-cache/bin/varnishd/rfc2616.c +++ b/varnish-cache/bin/varnishd/rfc2616.c @@ -71,15 +71,13 @@ #endif static time_t -RFC2616_Ttl(struct sess *sp, struct http *hp, time_t t_req, time_t t_resp, struct object *obj) +RFC2616_Ttl(struct sess *sp, struct http *hp, struct object *obj) { int retirement_age; unsigned u1, u2; time_t h_date, h_expires, ttd; char *p; - (void)t_resp; /* XXX */ - retirement_age = INT_MAX; u1 = u2 = 0; @@ -102,10 +100,11 @@ RFC2616_Ttl(struct sess *sp, struct http *hp, time_t t_req, time_t t_resp, struc if (http_GetHdr(hp, H_Expires, &p)) h_expires = TIM_parse(p); - if (h_date < t_req && h_expires > t_req) { + if (h_date < obj->entered && h_expires > obj->entered) { ttd = h_expires; - if (retirement_age != INT_MAX && t_req + retirement_age < ttd) - ttd = t_req + retirement_age; + if (retirement_age != INT_MAX && + obj->entered + retirement_age < ttd) + ttd = obj->entered + retirement_age; } else { if (h_date != 0 && h_expires != 0) { if (h_date < h_expires && @@ -115,13 +114,13 @@ RFC2616_Ttl(struct sess *sp, struct http *hp, time_t t_req, time_t t_resp, struc if (retirement_age == INT_MAX) retirement_age = heritage.default_ttl; - ttd = t_req + retirement_age; + ttd = obj->entered + retirement_age; } /* calculated TTL, Our time, Date, Expires, max-age, age */ VSL(SLT_TTL, sp->fd, "%u RFC %d %d %d %d %d %d", sp->xid, - (int)(ttd - t_req), (int)t_req, (int)h_date, (int)h_expires, - (int)u1, (int)u2); + (int)(ttd - obj->entered), (int)obj->entered, (int)h_date, + (int)h_expires, (int)u1, (int)u2); return (ttd); } @@ -155,8 +154,7 @@ RFC2616_cache_policy(struct sess *sp, struct http *hp) break; } - sp->obj->ttl = RFC2616_Ttl(sp, hp, sp->t_req, sp->t_resp, sp->obj); - sp->obj->entered = sp->t_req; + sp->obj->ttl = RFC2616_Ttl(sp, hp, sp->obj); if (sp->obj->ttl == 0) { sp->obj->cacheable = 0; } diff --git a/varnish-cache/include/shmlog_tags.h b/varnish-cache/include/shmlog_tags.h index e7437cda..d6181eea 100644 --- a/varnish-cache/include/shmlog_tags.h +++ b/varnish-cache/include/shmlog_tags.h @@ -13,6 +13,7 @@ SLTM(Error) SLTM(CLI) SLTM(StatAddr) SLTM(StatSess) +SLTM(ReqServTime) SLTM(SessionOpen) SLTM(SessionReuse) SLTM(SessionClose) -- 2.39.5