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.

diff --git a/doc/configuration.txt b/doc/configuration.txt
index 1348891bb9ee5e864c81788bb9d7d61b6196f7fa..3853d406f8484b60f1282396bccb50f6c5d09d2e 100644 (file)
--- a/doc/configuration.txt
+++ b/doc/configuration.txt
@@ -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

diff --git a/include/types/log.h b/include/types/log.h
index c348caa1eadfcf6ff711dc28c0ae20ea9d6f6e5a..868c08f01d294bcb0b82303ef9a1c024302ff43b 100644 (file)
--- 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_TU,
        LOG_FMT_STATUS,
        LOG_FMT_CCLIENT,
        LOG_FMT_CSERVER,

diff --git a/src/log.c b/src/log.c
index bacc04ed56c1255346f12e61f510272283456399..5d672942c8a6f0329d77a100530eea234f86adee 100644 (file)
--- a/src/log.c
+++ b/src/log.c
@@ -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)