BUG/MEDIUM: session: fix reporting of handshake processing time in the logs
The handshake processing time used to be stored per stream, which was
valid when there was exactly one stream per session. With H2 and
multiplexing it's not the case anymore and the reported handshake times
are wrong in the logs as it's computed between the TCP accept() and the
stream creation. Let's first move the handshake where it belongs, which
is the session.
However, this is not enough because we don't want to report an excessive
idle time either for H2 (since many requests use the connection).
So the solution used here is to have the stream retrieve sess->tv_accept
and the handshake duration when the stream is created, and let the mux
immediately reset them. This way, the handshake time becomes zero for the
second and subsequent requests in H2 (which was already the case in H1),
and the idle time exactly counts how long the connection remained unused
while it could be used, so in H1 it runs from the end of the previous
response and in H2 it runs from the end of the previous request since the
channel is already available.
This patch will need to be backported to 1.8.
diff --git a/doc/configuration.txt b/doc/configuration.txt
index 513ef0c..2332bb7 100644
--- a/doc/configuration.txt
+++ b/doc/configuration.txt
@@ -15958,7 +15958,10 @@
- "accept_date" is the exact date when the connection was received by haproxy
(which might be very slightly different from the date observed on the
network if there was some queuing in the system's backlog). This is usually
- the same date which may appear in any upstream firewall's log.
+ the same date which may appear in any upstream firewall's log. When used in
+ HTTP mode, the accept_date field will be reset to the first moment the
+ connection is ready to receive a new request (end of previous response for
+ HTTP/1, immediately after previous request for HTTP/2).
- "frontend_name" is the name of the frontend (or listener) which received
and processed the connection.
@@ -16158,24 +16161,25 @@
request could be received or the a bad request was received. It should
always be very small because a request generally fits in one single packet.
Large times here generally indicate network issues between the client and
- haproxy or requests being typed by hand. See "Timers" below for more details.
+ haproxy or requests being typed by hand. See section 8.4 "Timing Events"
+ for more details.
- "Tw" is the total time in milliseconds spent waiting in the various queues.
It can be "-1" if the connection was aborted before reaching the queue.
- See "Timers" below for more details.
+ See section 8.4 "Timing Events" for more details.
- "Tc" is the total time in milliseconds spent waiting for the connection to
establish to the final server, including retries. It can be "-1" if the
- request was aborted before a connection could be established. See "Timers"
- below for more details.
+ request was aborted before a connection could be established. See section
+ 8.4 "Timing Events" for more details.
- "Tr" is the total time in milliseconds spent waiting for the server to send
a full HTTP response, not counting data. It can be "-1" if the request was
aborted before a complete response could be received. It generally matches
the server's processing time for the request, though it may be altered by
the amount of data sent by the client to the server. Large times here on
- "GET" requests generally indicate an overloaded server. See "Timers" below
- for more details.
+ "GET" requests generally indicate an overloaded server. See section 8.4
+ "Timing Events" for more details.
- "Ta" is the time the request remained active in haproxy, which is the total
time in milliseconds elapsed between the first byte of the request was
@@ -16184,7 +16188,7 @@
one exception, if "option logasap" was specified, then the time counting
stops at the moment the log is emitted. In this case, a '+' sign is
prepended before the value, indicating that the final one will be larger.
- See "Timers" below for more details.
+ See section 8.4 "Timing Events" for more details.
- "status_code" is the HTTP status code returned to the client. This status
is generally set by the server, but it might also be set by haproxy when
@@ -16590,16 +16594,20 @@
may indicate that the client only pre-established the connection without
speaking, that it is experiencing network issues preventing it from
completing a handshake in a reasonable time (e.g. MTU issues), or that an
- SSL handshake was very expensive to compute.
+ SSL handshake was very expensive to compute. Please note that this time is
+ reported only before the first request, so it is safe to average it over
+ all request to calculate the amortized value. The second and subsequent
+ request will always report zero here.
- Ti: is the idle time before the HTTP request (HTTP mode only). This timer
counts between the end of the handshakes and the first byte of the HTTP
request. When dealing with a second request in keep-alive mode, it starts
- to count after the end of the transmission the previous response. Some
- browsers pre-establish connections to a server in order to reduce the
- latency of a future request, and keep them pending until they need it. This
- delay will be reported as the idle time. A value of -1 indicates that
- nothing was received on the connection.
+ to count after the end of the transmission the previous response. When a
+ multiplexed protocol such as HTTP/2 is used, it starts to count immediately
+ after the previous request. Some browsers pre-establish connections to a
+ server in order to reduce the latency of a future request, and keep them
+ pending until they need it. This delay will be reported as the idle time. A
+ value of -1 indicates that nothing was received on the connection.
- TR: total time to get the client request (HTTP mode only). It's the time
elapsed between the first bytes received and the moment the proxy received