It can be sometimes useful to measure total time of a request, 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 negotiation time. To improve that, introduce a "TT" timer, without idle time but everything else. --- doc/configuration.txt | 8 ++++++++ include/types/log.h | 1 + src/log.c | 12 ++++++++++++ 3 files changed, 21 insertions(+)
diff --git a/doc/configuration.txt b/doc/configuration.txt index cf521483a..837090bb9 100644 --- a/doc/configuration.txt +++ b/doc/configuration.txt @@ -17733,6 +17733,7 @@ Please refer to the table below for currently defined variables : | H | %Tr | Tr (response time) | numeric | | | %Ts | timestamp | numeric | | | %Tt | Tt | numeric | + | | %TT | TT | numeric | | | %Tw | Tw | numeric | | | %U | bytes_uploaded (from client to server) | numeric | | | %ac | actconn | numeric | @@ -17900,6 +17901,7 @@ Timings events in HTTP mode: : Th Ti TR Tw Tc Tr Td : Ti ... :<---- Tq ---->: : :<-------------- Tt -------------->: + :<--> <--------- TT --------->: :<--------- Ta --------->: Timings events in TCP mode: @@ -17996,6 +17998,12 @@ 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). + - TT: total session duration time, between the moment the proxy accepted it + and the moment both ends were closed, without idle time. This is useful to + measure end-to-end time, without idle time pollution from keep-alive + requests. 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 diff --git a/include/types/log.h b/include/types/log.h index 3720fe73f..021e28d3d 100644 --- a/include/types/log.h +++ b/include/types/log.h @@ -104,6 +104,7 @@ enum { LOG_FMT_TR, LOG_FMT_TD, LOG_FMT_Tt, + LOG_FMT_TT, LOG_FMT_STATUS, LOG_FMT_CCLIENT, LOG_FMT_CSERVER, diff --git a/src/log.c b/src/log.c index 17e4a985f..e00b71ac6 100644 --- a/src/log.c +++ b/src/log.c @@ -151,6 +151,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 */ + { "TT", LOG_FMT_TT, PR_MODE_TCP, LW_BYTES, NULL }, /* TT = 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 */ @@ -2450,6 +2451,17 @@ int sess_build_logline(struct session *sess, struct stream *s, char *dst, size_t last_isspace = 0; break; + case LOG_FMT_TT: // %TT = total time without idle time = 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) -- 2.20.1