MINOR: log: Add "Tu" timer

It can be sometimes useful to measure total time of a request as seen
from an end user, including TCP/TLS negotiation, server response time
and transfer time. "Tt" currently provides something close to that, but
it also takes client idle time into account, which is problematic for
keep-alive requests as idle time can be very long. "Ta" is also not
sufficient as it hides TCP/TLS negotiationtime. To improve that, introduce
a "Tu" timer, without idle time and everything else. It roughly estimates
time spent time spent from user point of view (without DNS resolution
time), assuming network latency is the same in both directions.
This commit is contained in:
Damien Claisse 2020-04-28 12:09:19 +00:00 committed by Willy Tarreau
parent 528f4811d6
commit 57c8eb939d
3 changed files with 24 additions and 0 deletions

View File

@ -18243,6 +18243,7 @@ Please refer to the table below for currently defined variables :
| H | %Tr | Tr (response time) | numeric |
| | %Ts | timestamp | numeric |
| | %Tt | Tt | numeric |
| | %Tu | Tu | numeric |
| | %Tw | Tw | numeric |
| | %U | bytes_uploaded (from client to server) | numeric |
| | %ac | actconn | numeric |
@ -18410,6 +18411,7 @@ Timings events in HTTP mode:
: Th Ti TR Tw Tc Tr Td : Ti ...
:<---- Tq ---->: :
:<-------------- Tt -------------->:
:<-- -----Tu--------------->:
:<--------- Ta --------->:
Timings events in TCP mode:
@ -18506,6 +18508,15 @@ Timings events in TCP mode:
mode, "Ti", "Tq" and "Tr" have to be excluded too. Note that "Tt" can never
be negative and that for HTTP, Tt is simply equal to (Th+Ti+Ta).
- Tu: total estimated time as seen from client, between the moment the proxy
accepted it and the moment both ends were closed, without idle time.
This is useful to roughly measure end-to-end time as a user would see it,
without idle time pollution from keep-alive time between requests. This
timer in only an estimation of time seen by user as it assumes network
latency is the same in both directions. The exception is when the "logasap"
option is specified. In this case, it only equals (Th+TR+Tw+Tc+Tr), and is
prefixed with a '+' sign.
These timers provide precious indications on trouble causes. Since the TCP
protocol defines retransmit delays of 3, 6, 12... seconds, we know for sure
that timers close to multiples of 3s are nearly always related to lost packets

View File

@ -104,6 +104,7 @@ enum {
LOG_FMT_TR,
LOG_FMT_TD,
LOG_FMT_TT,
LOG_FMT_TU,
LOG_FMT_STATUS,
LOG_FMT_CCLIENT,
LOG_FMT_CSERVER,

View File

@ -152,6 +152,7 @@ static const struct logformat_type logformat_keywords[] = {
{ "Td", LOG_FMT_TD, PR_MODE_TCP, LW_BYTES, NULL }, /* Td = Tt - (Tq + Tw + Tc + Tr) */
{ "Ts", LOG_FMT_TS, PR_MODE_TCP, LW_INIT, NULL }, /* timestamp GMT */
{ "Tt", LOG_FMT_TT, PR_MODE_TCP, LW_BYTES, NULL }, /* Tt */
{ "Tu", LOG_FMT_TU, PR_MODE_TCP, LW_BYTES, NULL }, /* Tu = Tt -Ti */
{ "Tw", LOG_FMT_TW, PR_MODE_TCP, LW_BYTES, NULL }, /* Tw */
{ "U", LOG_FMT_BYTES_UP, PR_MODE_TCP, LW_BYTES, NULL }, /* bytes from client to server */
{ "ac", LOG_FMT_ACTCONN, PR_MODE_TCP, LW_BYTES, NULL }, /* actconn */
@ -2460,6 +2461,17 @@ int sess_build_logline(struct session *sess, struct stream *s, char *dst, size_t
last_isspace = 0;
break;
case LOG_FMT_TU: // %Tu = total time seen by user = Tt - Ti
if (!(fe->to_log & LW_BYTES))
LOGCHAR('+');
ret = ltoa_o(logs->t_close - (logs->t_idle >= 0 ? logs->t_idle : 0),
tmplog, dst + maxsize - tmplog);
if (ret == NULL)
goto out;
tmplog = ret;
last_isspace = 0;
break;
case LOG_FMT_STATUS: // %ST
ret = ltoa_o(txn ? txn->status : 0, tmplog, dst + maxsize - tmplog);
if (ret == NULL)