[master] f463c682d http2: Improve timestamps

[Nils Goroll]

commit f463c682d557ffb9faf5a0a5f4e6d4466df24ca1
Author: Nils Goroll <nils.goroll at uplex.de>
Date:   Mon Feb 24 22:18:26 2025 +0100

    http2: Improve timestamps
    
    A newly created request's t_first is now when the first (partial) read of the
    HEADERS frame is complete.
    
    t_req is now when all headers are complete.
    
    This should match http1 more closely
    
    Implements #4282

diff --git a/bin/varnishd/http2/cache_http2.h b/bin/varnishd/http2/cache_http2.h
index 8794db23d..ba036b84d 100644
--- a/bin/varnishd/http2/cache_http2.h
+++ b/bin/varnishd/http2/cache_http2.h
@@ -196,6 +196,7 @@ struct h2_sess {
 	struct h2_settings		local_settings;
 
 	struct req			*new_req;
+	vtim_real			t1;	// t_first for new_req
 	uint32_t			goaway_last_stream;
 
 	VTAILQ_HEAD(,h2_req)		txqueue;
diff --git a/bin/varnishd/http2/cache_http2_proto.c b/bin/varnishd/http2/cache_http2_proto.c
index 3ef036145..d7309913c 100644
--- a/bin/varnishd/http2/cache_http2_proto.c
+++ b/bin/varnishd/http2/cache_http2_proto.c
@@ -329,6 +329,7 @@ h2_rx_push_promise(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2)
 	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
 	ASSERT_RXTHR(h2);
 	CHECK_OBJ_ORNULL(r2, H2_REQ_MAGIC);
+
 	// rfc7540,l,2262,2267
 	H2S_Lock_VSLb(h2, SLT_SessError, "H2: rx push promise");
 	return (H2CE_PROTOCOL_ERROR);
@@ -654,6 +655,7 @@ h2_end_headers(struct worker *wrk, struct h2_sess *h2,
 		h2_del_req(wrk, r2);
 		return (h2e);
 	}
+	req->t_req = VTIM_real();
 	VSLb_ts_req(req, "Req", req->t_req);
 
 	// XXX: Smarter to do this already at HPACK time into tail end of
@@ -774,8 +776,7 @@ h2_rx_headers(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2)
 	req->sp = h2->sess;
 	req->transport = &HTTP2_transport;
 
-	req->t_first = VTIM_real();
-	req->t_req = VTIM_real();
+	req->t_first = h2->t1;
 	req->t_prev = req->t_first;
 	VSLb_ts_req(req, "Start", req->t_first);
 	req->acct.req_hdrbytes += h2->rxf_len;
@@ -1479,8 +1480,9 @@ h2_rxframe(struct worker *wrk, struct h2_sess *h2)
 	if (h2->goaway && h2->open_streams == 0)
 		return (0);
 
+	h2->t1 = NAN;
 	VTCP_blocking(*h2->htc->rfd);
-	hs = HTC_RxStuff(h2->htc, h2_frame_complete, NULL, NULL, NAN,
+	hs = HTC_RxStuff(h2->htc, h2_frame_complete, &h2->t1, NULL, NAN,
 	    VTIM_real() + 0.5, NAN, h2->local_settings.max_frame_size + 9);
 
 	h2e = NULL;
diff --git a/doc/changes.rst b/doc/changes.rst
index a132c45cf..0df080469 100644
--- a/doc/changes.rst
+++ b/doc/changes.rst
@@ -41,6 +41,26 @@ Varnish Cache NEXT (2025-03-15)
 .. PLEASE keep this roughly in commit order as shown by git-log / tig
    (new to old)
 
+* (Add a prominent note to announcement) Timestamps for http/2 requests have
+  been corrected and made similar to how they are taken for http/1.
+
+  For http/1, the start time, internally called "t_first", is taken as soon as
+  any part of the request (headers) is received. Previously, http/2 took it
+  later, possibly much later if long header lines were involved. http/2 now
+  takes it the same way as http/1 when the first bit of the first HEADERS frame
+  of the request arrives.
+
+  Timing behavior for http/1 and http/2 is different and can not be directly
+  compared. But with this change, the ``Timestamp`` VSL records for http/2 now
+  at least reflect reality better.
+
+  NOTE that after upgrading Varnish-Cache, processing and response times for
+  http/2 will now be reported as worse than before the upgrade, potentially
+  *much* worse. This is **NOT** a performance regression, but rather due to the
+  corrected timestamps, which arguably were wrong for http/2.
+
+.. MISSING commits
+
 * The ``hitmiss`` and ``hitpass`` handling indicators have been added to the
   ``Varnish:handling`` format of ``varnishncsa``.