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

diff --git a/varnish-cache/bin/varnishd/cache.h b/varnish-cache/bin/varnishd/cache.h
index 84d6a4ed78c31801e7019b29fb15c89f9106bba4..9ee3e61b3cd83cb179e32fe4d6ee02a07f04da4f 100644 (file)
--- 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 840f6abd47eb1cf6e03ce88cc3e13b9ee2d5e13a..2660d69509c29a1c9c10975a1406adb8b49dc5d5 100644 (file)
--- 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 27f05cac9a54c0e885d2c9e734fe988009a81f73..a7919db6361a6a733ca0961063484df313994971 100644 (file)
--- 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 f02ac182504370aecf9de435dbb67fe8b35d15b7..5b8f9116d7e0347fa51c4615a0d8c7ad6c8fa954 100644 (file)
--- 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 601ef47cd1898ae67d1ce382c8519ebcd81cfad7..bfe59dae15e3be5e416d3419ef83b98d9a583fa2 100644 (file)
--- 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 78f9c4c7a692ce3aed5ea205d9ce456cba857a1c..2aab60fe0325176fe76b0e98352b1b01cffcbdfc 100644 (file)
--- 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 254c32868ed5dc69ee744995749ba5f517e9b989..4e29b0cd54a24e242923f636e528fada79228373 100644 (file)
--- 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 ee6e1631bd5312a075994b4aa1e5577f76ea2477..7428e8ad20ec00e0307d5607efebeee5b6cd9ed4 100644 (file)
--- 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 e7437cda7c28f952dd203188cbb2d78c2b6ddaf3..d6181eea8b76871c3e77929fa79db1b76f4a59b7 100644 (file)
--- 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)