[master] ae6512a47 Add {req,req_top,resp,bereq,beresp,obj}.time
Nils Goroll
nils.goroll at uplex.de
Mon Nov 29 14:47:06 UTC 2021
commit ae6512a47dbef775036d890a71cd9f87b18fa84d
Author: Nils Goroll <nils.goroll at uplex.de>
Date: Thu Mar 25 17:26:21 2021 +0100
Add {req,req_top,resp,bereq,beresp,obj}.time
{req,bereq}.time remain constant across restarts/retries
req_top.time remains constant across esi includes
The other values represent the time when the respective object
was created.
diff --git a/bin/varnishd/cache/cache.h b/bin/varnishd/cache/cache.h
index f35b0ab69..aeadda251 100644
--- a/bin/varnishd/cache/cache.h
+++ b/bin/varnishd/cache/cache.h
@@ -393,6 +393,7 @@ struct busyobj {
/* Timers */
vtim_real t_first; /* First timestamp logged */
+ vtim_real t_resp; /* response received */
vtim_real t_prev; /* Previous timestamp logged */
/* Acct */
@@ -484,6 +485,7 @@ struct req {
vtim_real t_first; /* First timestamp logged */
vtim_real t_prev; /* Previous timestamp logged */
vtim_real t_req; /* Headers complete */
+ vtim_real t_resp; /* Entry to last deliver/synth */
struct http_conn *htc;
struct vfp_ctx *vfc;
diff --git a/bin/varnishd/cache/cache_fetch.c b/bin/varnishd/cache/cache_fetch.c
index 76a3a2422..942a611f8 100644
--- a/bin/varnishd/cache/cache_fetch.c
+++ b/bin/varnishd/cache/cache_fetch.c
@@ -427,7 +427,7 @@ vbf_stp_startfetch(struct worker *wrk, struct busyobj *bo)
VSLb_ts_busyobj(bo, "Fetch", W_TIM_real(wrk));
i = VDI_GetHdr(bo);
- now = W_TIM_real(wrk);
+ bo->t_resp = now = W_TIM_real(wrk);
VSLb_ts_busyobj(bo, "Beresp", now);
if (i) {
diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c
index 0b383e594..3538c3e6c 100644
--- a/bin/varnishd/cache/cache_req_fsm.c
+++ b/bin/varnishd/cache/cache_req_fsm.c
@@ -231,7 +231,9 @@ cnt_deliver(struct worker *wrk, struct req *req)
!(req->objcore->flags & OC_F_PRIVATE))
http_ForceHeader(req->resp, H_Accept_Ranges, "bytes");
+ req->t_resp = W_TIM_real(wrk);
VCL_deliver_method(req->vcl, wrk, req, NULL, NULL);
+
VSLb_ts_req(req, "Process", W_TIM_real(wrk));
assert(req->restarts <= cache_param->max_restarts);
@@ -324,6 +326,7 @@ cnt_synth(struct worker *wrk, struct req *req)
synth_body = VSB_new_auto();
AN(synth_body);
+ req->t_resp = W_TIM_real(wrk);
VCL_synth_method(req->vcl, wrk, req, NULL, synth_body);
AZ(VSB_finish(synth_body));
diff --git a/bin/varnishd/cache/cache_vrt_var.c b/bin/varnishd/cache/cache_vrt_var.c
index 1f0edca4d..64b7257d4 100644
--- a/bin/varnishd/cache/cache_vrt_var.c
+++ b/bin/varnishd/cache/cache_vrt_var.c
@@ -707,6 +707,25 @@ VRT_DO_EXP_R(beresp, ctx->bo->fetch_objcore, keep, 0)
/*lint -restore */
+// XXX more assertions?
+#define VRT_DO_TIME_R(which, where, field) \
+ \
+VCL_TIME \
+VRT_r_##which##_time(VRT_CTX) \
+{ \
+ CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC); \
+ AN((ctx)->where); \
+ \
+ return ((ctx)->where->field); \
+}
+
+VRT_DO_TIME_R(req, req, t_req)
+VRT_DO_TIME_R(req_top, req->top->topreq, t_req)
+VRT_DO_TIME_R(resp, req, t_resp)
+VRT_DO_TIME_R(bereq, bo, t_first)
+VRT_DO_TIME_R(beresp, bo, t_resp)
+VRT_DO_TIME_R(obj, req->objcore, t_origin)
+
/*--------------------------------------------------------------------
*/
diff --git a/bin/varnishtest/tests/b00030.vtc b/bin/varnishtest/tests/b00030.vtc
index 626324755..ba6b7c9cb 100644
--- a/bin/varnishtest/tests/b00030.vtc
+++ b/bin/varnishtest/tests/b00030.vtc
@@ -7,68 +7,107 @@ varnishtest "Test timestamps"
server s1 {
rxreq
txresp
+ rxreq
+ txresp
} -start
varnish v1 -vcl+backend {
import vtc;
+ import std;
sub recv_sub {
- set req.http.recv_sub = now;
+ set req.http.now-recv_sub = now;
}
sub vcl_recv {
- set req.http.recv = now;
+ if (req.restarts == 0) {
+ set req.http.req-time = req.time;
+ } else if (req.http.req-time != "" + req.time) {
+ return (fail);
+ }
+ set req.http.now-recv = now;
vtc.sleep(1s);
call recv_sub;
- if (req.http.recv != req.http.recv_sub) {
+ if (req.http.now-recv != req.http.now-recv_sub) {
return (fail);
}
}
sub vcl_synth {
- set resp.http.synth = now;
+ set resp.http.now-synth = now;
+ if (req.http.req-time != "" + req.time) {
+ return (fail);
+ }
+ set req.http.req-time = req.time;
+ set resp.http.resp-time = resp.time;
}
sub vcl_deliver {
- set resp.http.deliver = now;
- if (req.http.recv == req.http.deliver) {
+ if (req.http.req-time != "" + req.time) {
+ return (fail);
+ }
+ set resp.http.resp-time = resp.time;
+ set resp.http.obj-time = obj.time;
+ set resp.http.now-deliver = now;
+ if (req.http.now-recv == req.http.now-deliver) {
return (fail);
}
vtc.sleep(1s);
+ if (req.restarts == 0) {
+ return (restart);
+ }
return (synth(200));
}
sub bf_sub {
- set bereq.http.bf_sub = now;
+ set bereq.http.now-bf_sub = now;
}
sub vcl_backend_fetch {
- set bereq.http.bf = now;
+ if (bereq.retries == 0) {
+ set bereq.http.bereq-time = bereq.time;
+ } else if (bereq.http.bereq-time != "" + bereq.time) {
+ # bereq.time is identical for all retries
+ return (fail);
+ }
+ if (bereq.time <= std.time(bereq.http.req-time)) {
+ return (fail);
+ }
+ set bereq.http.now-bf = now;
vtc.sleep(1s);
call bf_sub;
- if (bereq.http.bf != bereq.http.bf_sub) {
+ # now remains constant during built-in vcl sub
+ if (bereq.http.now-bf != bereq.http.now-bf_sub) {
return (fail);
}
}
sub br_sub {
- set beresp.http.br_sub = now;
+ set beresp.http.now-br_sub = now;
}
sub vcl_backend_response {
- set beresp.http.br = now;
+ if (bereq.http.bereq-time != "" + bereq.time) {
+ return (fail);
+ }
+ set beresp.http.beresp-time = beresp.time;
+ set beresp.http.now-br = now;
vtc.sleep(1s);
call br_sub;
- if (beresp.http.br != beresp.http.br_sub) {
+ if (beresp.http.now-br != beresp.http.now-br_sub) {
return (fail);
}
- if (bereq.http.bf == beresp.http.br) {
+ if (bereq.http.now-bf == beresp.http.now-br) {
return (fail);
}
+ if (bereq.retries == 0) {
+ return (retry);
+ }
+ }
+ sub vcl_backend_error {
+ call vcl_backend_response;
}
-
-
} -start
client c1 {
txreq
rxresp
expect resp.status == 200
- expect resp.http.synth ~ "^..., .. ... .... ..:..:.. GMT"
+ expect resp.http.now-synth ~ "^..., .. ... .... ..:..:.. GMT"
} -run
diff --git a/bin/varnishtest/tests/e00030.vtc b/bin/varnishtest/tests/e00030.vtc
index 0a529d1f9..ff2016fb9 100644
--- a/bin/varnishtest/tests/e00030.vtc
+++ b/bin/varnishtest/tests/e00030.vtc
@@ -56,7 +56,11 @@ varnish v1 -vcl+backend {
sub vcl_recv {
if (req.esi_level > 0) {
set req.url = req.url + req.esi_level;
+ if (req_top.http.top-time != "" + req_top.time) {
+ return (fail);
+ }
} else {
+ set req.http.top-time = req_top.time;
set req.http.foo = "bar";
}
diff --git a/doc/sphinx/reference/vcl_var.rst b/doc/sphinx/reference/vcl_var.rst
index 4271824ac..02f71001f 100644
--- a/doc/sphinx/reference/vcl_var.rst
+++ b/doc/sphinx/reference/vcl_var.rst
@@ -409,6 +409,15 @@ req.is_hitpass
If this request resulted in a hitpass
+req.time
+
+ Type: TIME
+
+ Readable from: client
+
+ The time when the request was fully received, remains constant
+ across restarts.
+
req_top.method
Type: STRING
@@ -453,6 +462,14 @@ req_top.proto
ESI requests.
Identical to req.proto in non-ESI requests.
+req_top.time
+
+ Type: TIME
+
+ Readable from: client
+
+ The time when the top-level request was fully received,
+ remains constant across restarts.
bereq
~~~~~
@@ -671,6 +688,15 @@ bereq.is_hitpass
If this backend request was caused by a hitpass.
+bereq.time
+
+ Type: TIME
+
+ Readable from: backend
+
+ The time when we started preparing the first backend request,
+ remains constant across retries.
+
beresp
~~~~~~
@@ -1025,6 +1051,17 @@ beresp.filters
After beresp.filters is set, using any of the beforementioned
``beresp.do_*`` switches is a VCL error.
+beresp.time
+
+ Type: TIME
+
+ Readable from: vcl_backend_response, vcl_backend_error
+
+ When the backend headers were fully received just before
+ ``vcl_backend_response {}`` was entered, or when
+ ``vcl_backend_error {}`` was entered.
+
+
obj
~~~
@@ -1149,6 +1186,15 @@ obj.can_esi
``vcl_deliver {}`` would cause the response body to be ESI
processed.
+obj.time
+
+ Type: TIME
+
+ Readable from: vcl_hit, vcl_deliver
+
+ The time the object was created from the perspective of the
+ server which generated it. This will roughly be equivalent to
+ ``now`` - ``obj.age``.
resp
~~~~
@@ -1292,6 +1338,15 @@ resp.filters
effiect. Using resp.do_esi is an error once resp.filters is
set.
+resp.time
+
+ Type: TIME
+
+ Readable from: vcl_deliver, vcl_synth
+
+ The time when we started preparing the response, just before
+ entering ``vcl_synth {}`` or ``vcl_deliver {}``.
+
Special variables
~~~~~~~~~~~~~~~~~
More information about the varnish-commit
mailing list