BUG/MINOR: mux-h2: update the session's idle delay before creating the stream
The idle connection delay calculation before a request is a bit tricky,
especially for multiplexed protocols. It changed between 2.3 and 2.4 by
the integration of the idle delay inside the session itself with these
commits:
dd78921c6 ("MINOR: logs: Use session idle duration when no stream is provided")
7a6c51324 ("MINOR: stream: Always get idle duration from the session")
and by then it was only set by the H1 mux. But over multiple changes, what
used to be a zero idle delay + a request delay for H2 became a bit odd, with
the idle time slipping into the request time measurement. The effect is that,
as reported in GH issue #1395, some H2 request times look huge.
This patch introduces the calculation of the session's idle time on the
H2 mux before creating the stream. This is made possible because the
stream_new() code immediately copies this value into the stream for use
at log time. Thus we don't care about changing something that will be
touched by every single request. The idle time is calculated as documented,
i.e. the delay from the previous request to the current one. This also
means that when a single stream is present on a connection, a part of
the server's response time may appear in the %Ti measurement, but this
reflects the reality since nothing would prevent the client from using
the connection to fetch more objects. In addition this shows how long
it takes a client to find references to objects in an HTML page and
start to fetch them.
A different approach could have consisted in counting from the last time
the connection was left without any request (i.e. really idle), but this
would at least require a documentation change and it's not certain this
would provide a more useful information.
Thanks to Bart Butler and Luke Seelenbinder for reporting enough elements
to diagnose this issue.
This should be backported to 2.4.
diff --git a/src/mux_h2.c b/src/mux_h2.c
index 7e50aa5..767ffe9 100644
--- a/src/mux_h2.c
+++ b/src/mux_h2.c
@@ -1543,6 +1543,12 @@
if (flags & H2_SF_EXT_CONNECT_RCVD)
cs->flags |= CS_FL_WEBSOCKET;
+ /* The stream will record the request's accept date (which is either the
+ * end of the connection's or the date immediately after the previous
+ * request) and the idle time, which is the delay since the previous
+ * request. We can set the value now, it will be copied by stream_new().
+ */
+ sess->t_idle = tv_ms_elapsed(&sess->tv_accept, &now) - sess->t_handshake;
if (stream_create_from_cs(cs, input) < 0)
goto out_free_cs;
@@ -1554,6 +1560,7 @@
sess->accept_date = date;
sess->tv_accept = now;
sess->t_handshake = 0;
+ sess->t_idle = 0;
/* OK done, the stream lives its own life now */
if (h2_frt_has_too_many_cs(h2c))