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
