r583 - in trunk/varnish-cache: bin/varnishd include
phk at projects.linpro.no
phk at projects.linpro.no
Tue Aug 1 11:39:53 CEST 2006
Author: phk
Date: 2006-08-01 11:39:52 +0200 (Tue, 01 Aug 2006)
New Revision: 583
Modified:
trunk/varnish-cache/bin/varnishd/cache.h
trunk/varnish-cache/bin/varnishd/cache_acceptor.c
trunk/varnish-cache/bin/varnishd/cache_fetch.c
trunk/varnish-cache/bin/varnishd/cache_hash.c
trunk/varnish-cache/bin/varnishd/cache_pool.c
trunk/varnish-cache/bin/varnishd/cache_response.c
trunk/varnish-cache/bin/varnishd/cache_vrt.c
trunk/varnish-cache/bin/varnishd/rfc2616.c
trunk/varnish-cache/include/shmlog_tags.h
Log:
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.
Modified: trunk/varnish-cache/bin/varnishd/cache.h
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache.h 2006-07-31 22:21:02 UTC (rev 582)
+++ trunk/varnish-cache/bin/varnishd/cache.h 2006-08-01 09:39:52 UTC (rev 583)
@@ -243,8 +243,8 @@
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;
Modified: trunk/varnish-cache/bin/varnishd/cache_acceptor.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache_acceptor.c 2006-07-31 22:21:02 UTC (rev 582)
+++ trunk/varnish-cache/bin/varnishd/cache_acceptor.c 2006-08-01 09:39:52 UTC (rev 583)
@@ -41,15 +41,15 @@
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 @@
(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 @@
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);
}
Modified: trunk/varnish-cache/bin/varnishd/cache_fetch.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache_fetch.c 2006-07-31 22:21:02 UTC (rev 582)
+++ trunk/varnish-cache/bin/varnishd/cache_fetch.c 2006-08-01 09:39:52 UTC (rev 583)
@@ -291,7 +291,6 @@
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 @@
*/
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);
}
Modified: trunk/varnish-cache/bin/varnishd/cache_hash.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache_hash.c 2006-07-31 22:21:02 UTC (rev 582)
+++ trunk/varnish-cache/bin/varnishd/cache_hash.c 2006-08-01 09:39:52 UTC (rev 583)
@@ -108,7 +108,7 @@
/* 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;
Modified: trunk/varnish-cache/bin/varnishd/cache_pool.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache_pool.c 2006-07-31 22:21:02 UTC (rev 582)
+++ trunk/varnish-cache/bin/varnishd/cache_pool.c 2006-08-01 09:39:52 UTC (rev 583)
@@ -189,7 +189,7 @@
struct worker *w;
pthread_t tp;
- sp->t_req = time(NULL);
+ clock_gettime(CLOCK_REALTIME, &sp->t_req);
sp->workreq.sess = sp;
Modified: trunk/varnish-cache/bin/varnishd/cache_response.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache_response.c 2006-07-31 22:21:02 UTC (rev 582)
+++ trunk/varnish-cache/bin/varnishd/cache_response.c 2006-08-01 09:39:52 UTC (rev 583)
@@ -33,7 +33,7 @@
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 @@
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 @@
{
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 @@
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");
Modified: trunk/varnish-cache/bin/varnishd/cache_vrt.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/cache_vrt.c 2006-07-31 22:21:02 UTC (rev 582)
+++ trunk/varnish-cache/bin/varnishd/cache_vrt.c 2006-08-01 09:39:52 UTC (rev 583)
@@ -119,7 +119,16 @@
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 @@
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 @@
{
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);
}
/*--------------------------------------------------------------------*/
Modified: trunk/varnish-cache/bin/varnishd/rfc2616.c
===================================================================
--- trunk/varnish-cache/bin/varnishd/rfc2616.c 2006-07-31 22:21:02 UTC (rev 582)
+++ trunk/varnish-cache/bin/varnishd/rfc2616.c 2006-08-01 09:39:52 UTC (rev 583)
@@ -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 @@
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 @@
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 @@
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;
}
Modified: trunk/varnish-cache/include/shmlog_tags.h
===================================================================
--- trunk/varnish-cache/include/shmlog_tags.h 2006-07-31 22:21:02 UTC (rev 582)
+++ trunk/varnish-cache/include/shmlog_tags.h 2006-08-01 09:39:52 UTC (rev 583)
@@ -13,6 +13,7 @@
SLTM(CLI)
SLTM(StatAddr)
SLTM(StatSess)
+SLTM(ReqServTime)
SLTM(SessionOpen)
SLTM(SessionReuse)
SLTM(SessionClose)
More information about the varnish-commit
mailing list