Reported processing duration for http1 and http2 is not comparable

[nigoroll]

Expected Behavior

Provide statistics which reflect reality as realistically as possible

Current Behavior

On a production system, http2 was disabled. The ttfb and total processing time for cache hits as reported by post-processing of varnishncsa logs then went through the roof:

Context

Regarding ttfb (as deduced from Timestamp Processing:), the reporting point is independent of the protocol here and here.

The timestamp is relative to req->t_first, which is initialized in these places:

• http1

varnish-cache/bin/varnishd/http1/cache_http1_fsm.c

Lines 322 to 327 in 3cd6596

	hs = HTC_RxStuff(req->htc, HTTP1_Complete,
	&req->t_first, &req->t_req,
	sp->t_idle + SESS_TMO(sp, timeout_linger),
	sp->t_idle + SESS_TMO(sp, timeout_idle),
	NAN,
	cache_param->http_req_size);

• http2

varnish-cache/bin/varnishd/http2/cache_http2_proto.c

Lines 774 to 778 in 3cd6596

	req->t_first = VTIM_real();
	req->t_req = VTIM_real();
	req->t_prev = req->t_first;
	VSLb_ts_req(req, "Start", req->t_first);
	req->acct.req_hdrbytes += h2->rxf_len;

where the dispatched function h2_rx_headers() is called via h2_procframe() from h2_rxframe(), which has the actual receive:

varnish-cache/bin/varnishd/http2/cache_http2_proto.c

Lines 1480 to 1481 in 3cd6596

	hs = HTC_RxStuff(h2->htc, h2_frame_complete, NULL, NULL, NAN,
	VTIM_real() + 0.5, NAN, h2->local_settings.max_frame_size + 9);

One simple option to make the values comparable would be to start "Processing" after the receive also for http/1. Or we could at least take the t_first timestamp also at the beginning of the receive in h2_rxframe() for http2.

Opinions?

[nigoroll]

bugwash: make h2 reporting more like h1.