pipe: Add missing Start and Process timestamps

And expose bereq.time in vcl_pipe now that we have some.

Refs #3562

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;

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

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}

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.

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
 ~~~~~~~~~~~~~~~~~~~~~~~~