[master] 389d7ba28 pipe: Add missing Start and Process timestamps
Dridi Boukelmoune
dridi.boukelmoune at gmail.com
Tue Dec 21 13:35:06 UTC 2021
commit 389d7ba28e0d0e3a2d5c30a959aa517e5166b246
Author: Dridi Boukelmoune <dridi.boukelmoune at gmail.com>
Date: Thu Dec 16 08:19:28 2021 +0100
pipe: Add missing Start and Process timestamps
And expose bereq.time in vcl_pipe now that we have some.
Refs #3562
diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c
index 3538c3e6c..86a74b0cb 100644
--- a/bin/varnishd/cache/cache_req_fsm.c
+++ b/bin/varnishd/cache/cache_req_fsm.c
@@ -766,6 +766,7 @@ cnt_pipe(struct worker *wrk, struct req *req)
CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
VSLb(bo->vsl, SLT_Begin, "bereq %u pipe", VXID(req->vsl->wid));
VSLb(req->vsl, SLT_Link, "bereq %u pipe", VXID(bo->vsl->wid));
+ VSLb_ts_busyobj(bo, "Start", W_TIM_real(wrk));
THR_SetBusyobj(bo);
bo->sp = req->sp;
SES_Ref(bo->sp);
@@ -792,6 +793,8 @@ cnt_pipe(struct worker *wrk, struct req *req)
nxt = REQ_FSM_MORE;
break;
case VCL_RET_PIPE:
+ VSLb_ts_req(req, "Process", W_TIM_real(wrk));
+ VSLb_ts_busyobj(bo, "Process", wrk->lastused);
if (V1P_Enter() == 0) {
AZ(bo->req);
bo->req = req;
diff --git a/bin/varnishtest/tests/b00030.vtc b/bin/varnishtest/tests/b00030.vtc
index ba6b7c9cb..72abee7da 100644
--- a/bin/varnishtest/tests/b00030.vtc
+++ b/bin/varnishtest/tests/b00030.vtc
@@ -7,7 +7,14 @@ varnishtest "Test timestamps"
server s1 {
rxreq
txresp
+
+ rxreq
+ txresp
+
rxreq
+ expect req.method == PIPE
+ expect req.http.req-time != <undef>
+ expect req.http.bereq-time != <undef>
txresp
} -start
@@ -31,6 +38,10 @@ varnish v1 -vcl+backend {
return (fail);
}
}
+ sub vcl_pipe {
+ set bereq.http.req-time = req.time;
+ set bereq.http.bereq-time = bereq.time;
+ }
sub vcl_synth {
set resp.http.now-synth = now;
if (req.http.req-time != "" + req.time) {
@@ -110,4 +121,7 @@ client c1 {
rxresp
expect resp.status == 200
expect resp.http.now-synth ~ "^..., .. ... .... ..:..:.. GMT"
+
+ txreq -method PIPE
+ rxresp
} -run
diff --git a/bin/varnishtest/tests/v00051.vtc b/bin/varnishtest/tests/v00051.vtc
index 8f5ffd606..e13dae04b 100644
--- a/bin/varnishtest/tests/v00051.vtc
+++ b/bin/varnishtest/tests/v00051.vtc
@@ -182,6 +182,7 @@ varnish v1 -expect sc_vcl_failure == 4
logexpect l1012 -v v1 -g vxid -q "vxid == 1012" {
expect 0 1012 Begin {^bereq 1011 pipe}
+ expect 0 = Timestamp {^Start:}
expect 0 = BereqMethod {^GET}
expect 0 = BereqURL {^/}
expect 0 = BereqProtocol {^HTTP/1.1}
diff --git a/doc/sphinx/reference/vcl_var.rst b/doc/sphinx/reference/vcl_var.rst
index 153d52d33..be15b6448 100644
--- a/doc/sphinx/reference/vcl_var.rst
+++ b/doc/sphinx/reference/vcl_var.rst
@@ -690,7 +690,7 @@ bereq.time
Type: TIME
- Readable from: backend
+ Readable from: vcl_pipe, backend
The time when we started preparing the first backend request,
remains constant across retries.
diff --git a/doc/sphinx/reference/vsl.rst b/doc/sphinx/reference/vsl.rst
index 3e174a979..e8ea7a36d 100644
--- a/doc/sphinx/reference/vsl.rst
+++ b/doc/sphinx/reference/vsl.rst
@@ -79,12 +79,19 @@ Restart
Pipe handling timestamps
~~~~~~~~~~~~~~~~~~~~~~~~
+The following timestamps are client timestamps specific to pipe transactions:
+
Pipe
Opened a pipe to the backend and forwarded the request.
PipeSess
The pipe session has finished.
+The following timestamps change meaning in a pipe transaction:
+
+Process
+ Processing finished, ready to begin the pipe delivery.
+
Backend fetch timestamps
~~~~~~~~~~~~~~~~~~~~~~~~
More information about the varnish-commit
mailing list