MEDIUM: tree-wide: replace timeval with nanoseconds in tv_accept and tv_request

Let's get rid of timeval in storage of internal timestamps so that they
are no longer mistaken for wall clock time. These were exclusively used
subtracted from each other or to/from "now" after being converted to ns,
so this patch removes the tv_to_ns() conversion to use them natively. Two
occurrences of tv_isge() were turned to a regular wrapping subtract.

diff --git a/include/haproxy/mux_quic.h b/include/haproxy/mux_quic.h
index ac87aee8cda7c03a937de11f9e16e34ceb4f3026..9c643e9ab30deac27cd34cb30aec11b754356a74 100644 (file)
--- a/include/haproxy/mux_quic.h
+++ b/include/haproxy/mux_quic.h
@@ -101,7 +101,7 @@ static inline struct stconn *qc_attach_sc(struct qcs *qcs, struct buffer *buf)
        se_expect_no_data(qcs->sd);
 
        /* TODO duplicated from mux_h2 */
-       sess->t_idle = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&sess->tv_accept)) - sess->t_handshake;
+       sess->t_idle = ns_to_ms(tv_to_ns(&now) - sess->accept_ts) - sess->t_handshake;
 
        if (!sc_new_from_endp(qcs->sd, sess, buf))
                return NULL;
@@ -116,7 +116,7 @@ static inline struct stconn *qc_attach_sc(struct qcs *qcs, struct buffer *buf)
 
        /* TODO duplicated from mux_h2 */
        sess->accept_date = date;
-       sess->tv_accept   = now;
+       sess->accept_ts   = tv_to_ns(&now);
        sess->t_handshake = 0;
        sess->t_idle = 0;
 

diff --git a/include/haproxy/session-t.h b/include/haproxy/session-t.h
index 46023f0239512ddf1999ec28411865548e38c9ba..dff167ecb552e0acaa883d5207f4cc50b619e0a2 100644 (file)
--- a/include/haproxy/session-t.h
+++ b/include/haproxy/session-t.h
@@ -49,7 +49,7 @@ struct session {
        struct listener *listener;      /* the listener by which the request arrived */
        enum obj_type *origin;          /* the connection / applet which initiated this session */
        struct timeval accept_date;     /* date of the session's accept() in user date */
-       struct timeval tv_accept;       /* date of the session's accept() in internal date (monotonic) */
+       ullong accept_ts;               /* date of the session's accept() in internal date (monotonic) */
        struct stkctr *stkctr;          /* stick counters for tcp-connection */
        struct vars vars;               /* list of variables for the session scope. */
        struct task *task;              /* handshake timeout processing */

diff --git a/include/haproxy/stream-t.h b/include/haproxy/stream-t.h
index fe85217c0a988e82417ea0aaf3183eb685fb1dad..14293d5b825d2a8e700832bd126913b2dc73f8ec 100644 (file)
--- a/include/haproxy/stream-t.h
+++ b/include/haproxy/stream-t.h
@@ -185,10 +185,10 @@ struct strm_logs {
        int logwait;                    /* log fields waiting to be collected : LW_* */
        int level;                      /* log level to force + 1 if > 0, -1 = no log */
        struct timeval accept_date;     /* date of the stream's accept() in user date */
-       struct timeval tv_accept;       /* date of the stream's accept() in internal date (monotonic) */
+       ullong accept_ts;               /* date of the session's accept() in internal date (monotonic) */
        long t_handshake;               /* handshake duration, -1 if never occurs */
        long t_idle;                    /* idle duration, -1 if never occurs */
-       struct timeval tv_request;      /* date the request arrives, {0,0} if never occurs */
+       ullong request_ts;              /* date when the request arrives in internal date */
        long  t_queue;                  /* delay before the stream gets out of the connect queue, -1 if never occurs */
        long  t_connect;                /* delay before the connect() to the server succeeds, -1 if never occurs */
        long  t_data;                   /* delay before the first data byte from the server ... */

diff --git a/src/backend.c b/src/backend.c
index 085bb1bf759eef506beb94c21fe089a2e07eadec..7b8e12d3f3d4691c340476fa7acfb11b5490f9d4 100644 (file)
--- a/src/backend.c
+++ b/src/backend.c
@@ -2024,7 +2024,7 @@ void back_try_conn_req(struct stream *s)
                        sc_shutdown(sc);
                        sc->flags |= SC_FL_ERROR;
 
-                       s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept));
+                       s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts);
 
                        /* we may need to know the position in the queue for logging */
                        pendconn_cond_unlink(s->pend_pos);
@@ -2060,7 +2060,7 @@ void back_try_conn_req(struct stream *s)
                        if (unlikely(!(s->flags & SF_ASSIGNED)))
                                sc->state = SC_ST_REQ;
                        else {
-                               s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept));
+                               s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts);
                                sc->state = SC_ST_ASS;
                        }
                        DBG_TRACE_STATE("dequeue connection request", STRM_EV_STRM_PROC|STRM_EV_CS_ST, s);
@@ -2072,7 +2072,7 @@ void back_try_conn_req(struct stream *s)
                        /* ... and timeout expired */
                        s->conn_exp = TICK_ETERNITY;
                        s->flags &= ~SF_CONN_EXP;
-                       s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept));
+                       s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts);
 
                        /* we may need to know the position in the queue for logging */
                        pendconn_cond_unlink(s->pend_pos);
@@ -2094,7 +2094,7 @@ void back_try_conn_req(struct stream *s)
 
                /* Connection remains in queue, check if we have to abort it */
                if (back_may_abort_req(req, s)) {
-                       s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept));
+                       s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts);
 
                        /* we may need to know the position in the queue for logging */
                        pendconn_cond_unlink(s->pend_pos);
@@ -2219,7 +2219,7 @@ void back_handle_st_req(struct stream *s)
        }
 
        /* The server is assigned */
-       s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept));
+       s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts);
        sc->state = SC_ST_ASS;
        be_set_sess_last(s->be);
        DBG_TRACE_STATE("connection request assigned to a server", STRM_EV_STRM_PROC|STRM_EV_CS_ST, s);
@@ -2440,9 +2440,9 @@ void back_handle_st_rdy(struct stream *s)
                 */
                BUG_ON(!sc_appctx(s->scb));
 
-               if (tv_iszero(&s->logs.tv_request))
-                       s->logs.tv_request = now;
-               s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept));
+               if (!s->logs.request_ts)
+                       s->logs.request_ts = tv_to_ns(&now);
+               s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts);
                be_set_sess_last(s->be);
        }
 

diff --git a/src/cli.c b/src/cli.c
index 412cbfb292268b7afa9683b670ecea3b09c1c444..5af4804fd3231629486da3292e2c95fab0dca078 100644 (file)
--- a/src/cli.c
+++ b/src/cli.c
@@ -2626,7 +2626,7 @@ read_again:
 
        /* If there is data available for analysis, log the end of the idle time. */
        if (c_data(req) && s->logs.t_idle == -1)
-               s->logs.t_idle = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept)) - s->logs.t_handshake;
+               s->logs.t_idle = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts) - s->logs.t_handshake;
 
        to_forward = pcli_parse_request(s, req, &errmsg, &next_pid);
        if (to_forward > 0) {
@@ -2762,7 +2762,7 @@ int pcli_wait_for_response(struct stream *s, struct channel *rep, int an_bit)
                                sess_change_server(s, NULL);
                }
 
-               s->logs.t_close = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept));
+               s->logs.t_close = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts);
                stream_process_counters(s);
 
                /* don't count other requests' data */
@@ -2784,10 +2784,10 @@ int pcli_wait_for_response(struct stream *s, struct channel *rep, int an_bit)
                stream_update_time_stats(s);
 
                s->logs.accept_date = date; /* user-visible date for logging */
-               s->logs.tv_accept = now;  /* corrected date for internal use */
+               s->logs.accept_ts = tv_to_ns(&now);  /* corrected date for internal use */
                s->logs.t_handshake = 0; /* There are no handshake in keep alive connection. */
                s->logs.t_idle = -1;
-               tv_zero(&s->logs.tv_request);
+               s->logs.request_ts = 0;
                s->logs.t_queue = -1;
                s->logs.t_connect = -1;
                s->logs.t_data = -1;

diff --git a/src/hlua.c b/src/hlua.c
index b14ac838f84e3f27aa896a252c8958037899ac17..7c49f5e0b5fd351f3cd3a4176562edb696465b7e 100644 (file)
--- a/src/hlua.c
+++ b/src/hlua.c
@@ -8295,7 +8295,7 @@ __LJMP static int hlua_txn_done(lua_State *L)
        finst = ((htxn->dir == SMP_OPT_DIR_REQ) ? SF_FINST_R : SF_FINST_H);
        if (htxn->dir == SMP_OPT_DIR_REQ) {
                /* let's log the request time */
-               s->logs.tv_request = now;
+               s->logs.request_ts = tv_to_ns(&now);
                if (s->sess->fe == s->be) /* report it if the request was intercepted by the frontend */
                        _HA_ATOMIC_INC(&s->sess->fe->fe_counters.intercepted_req);
        }

diff --git a/src/http_act.c b/src/http_act.c
index 596e68c5461b7ebd7a5f9e99fa963702bd0686fc..07997fa1887a66d79483eb4b372b08ecc3df4f14 100644 (file)
--- a/src/http_act.c
+++ b/src/http_act.c
@@ -1284,7 +1284,7 @@ static enum act_return http_action_auth(struct act_rule *rule, struct proxy *px,
                goto fail;
 
        /* Note: Only eval on the request */
-       s->logs.tv_request = now;
+       s->logs.request_ts = tv_to_ns(&now);
        req->analysers &= AN_REQ_FLT_END;
 
        if (s->sess->fe == s->be) /* report it if the request was intercepted by the frontend */
@@ -2279,7 +2279,7 @@ static enum act_return http_action_return(struct act_rule *rule, struct proxy *p
 
        if (rule->from == ACT_F_HTTP_REQ) {
                /* let's log the request time */
-               s->logs.tv_request = now;
+               s->logs.request_ts = tv_to_ns(&now);
                req->analysers &= AN_REQ_FLT_END;
 
                if (s->sess->fe == s->be) /* report it if the request was intercepted by the frontend */

diff --git a/src/http_ana.c b/src/http_ana.c
index d97d4424721a423ac3631090faff354304021148..b623af57517d348592ea1d813b5bf37b54a60a15 100644 (file)
--- a/src/http_ana.c
+++ b/src/http_ana.c
@@ -439,7 +439,7 @@ int http_process_req_common(struct stream *s, struct channel *req, int an_bit, s
        if (!s->target && http_stats_check_uri(s, txn, px)) {
                s->target = &http_stats_applet.obj_type;
                if (unlikely(!sc_applet_create(s->scb, objt_applet(s->target)))) {
-                       s->logs.tv_request = now;
+                       s->logs.request_ts = tv_to_ns(&now);
                        if (!(s->flags & SF_ERR_MASK))
                                s->flags |= SF_ERR_RESOURCE;
                        goto return_int_err;
@@ -562,7 +562,7 @@ int http_process_req_common(struct stream *s, struct channel *req, int an_bit, s
        if (s->be->cookie_name || sess->fe->capture_name)
                http_manage_client_side_cookies(s, req);
 
-       s->logs.tv_request = now;
+       s->logs.request_ts = tv_to_ns(&now);
        stream_inc_http_err_ctr(s);
        _HA_ATOMIC_INC(&sess->fe->fe_counters.denied_req);
        if (s->flags & SF_BE_ASSIGNED)
@@ -716,7 +716,7 @@ int http_process_request(struct stream *s, struct channel *req, int an_bit)
        req->analyse_exp = TICK_ETERNITY;
        req->analysers &= ~an_bit;
 
-       s->logs.tv_request = now;
+       s->logs.request_ts = tv_to_ns(&now);
        /* OK let's go on with the BODY now */
        DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
        return 1;
@@ -782,7 +782,7 @@ int http_process_tarpit(struct stream *s, struct channel *req, int an_bit)
         * It will not cause trouble to the logs because we can exclude
         * the tarpitted connections by filtering on the 'PT' status flags.
         */
-       s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept));
+       s->logs.t_queue = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts);
 
        http_reply_and_close(s, txn->status, (!(s->scf->flags & SC_FL_ERROR) ? http_error_message(s) : NULL));
        http_set_term_flags(s);
@@ -824,7 +824,7 @@ int http_wait_for_request_body(struct stream *s, struct channel *req, int an_bit
 
  http_end:
        /* The situation will not evolve, so let's give up on the analysis. */
-       s->logs.tv_request = now;  /* update the request timer to reflect full request */
+       s->logs.request_ts = tv_to_ns(&now);  /* update the request timer to reflect full request */
        req->analysers &= ~an_bit;
        req->analyse_exp = TICK_ETERNITY;
        DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
@@ -1585,7 +1585,7 @@ int http_wait_for_response(struct stream *s, struct channel *rep, int an_bit)
 
   end:
        /* we want to have the response time before we start processing it */
-       s->logs.t_data = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept));
+       s->logs.t_data = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts);
 
        /* end of job, return OK */
        rep->analysers &= ~an_bit;
@@ -2442,7 +2442,7 @@ int http_apply_redirect_rule(struct redirect_rule *rule, struct stream *s, struc
 
        if (rule->flags & REDIRECT_FLAG_FROM_REQ) {
                /* let's log the request time */
-               s->logs.tv_request = now;
+               s->logs.request_ts = tv_to_ns(&now);
                req->analysers &= AN_REQ_FLT_END;
 
                if (s->sess->fe == s->be) /* report it if the request was intercepted by the frontend */

diff --git a/src/log.c b/src/log.c
index 175aea09ad94a128e9fae586b87e61115071fac3..60c7daad8567b2df78de2ca6c23a1c8c26d1e202 100644 (file)
--- a/src/log.c
+++ b/src/log.c
@@ -2010,15 +2010,15 @@ int sess_build_logline(struct session *sess, struct stream *s, char *dst, size_t
                uniq_id = _HA_ATOMIC_FETCH_ADD(&global.req_count, 1);
 
                /* prepare a valid log structure */
-               tmp_strm_log.tv_accept = sess->tv_accept;
+               tmp_strm_log.accept_ts = sess->accept_ts;
                tmp_strm_log.accept_date = sess->accept_date;
                tmp_strm_log.t_handshake = sess->t_handshake;
                tmp_strm_log.t_idle = (sess->t_idle >= 0 ? sess->t_idle : 0);
-               tv_zero(&tmp_strm_log.tv_request);
+               tmp_strm_log.request_ts = 0;
                tmp_strm_log.t_queue = -1;
                tmp_strm_log.t_connect = -1;
                tmp_strm_log.t_data = -1;
-               tmp_strm_log.t_close = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&sess->tv_accept));
+               tmp_strm_log.t_close = ns_to_ms(tv_to_ns(&now) - sess->accept_ts);
                tmp_strm_log.bytes_in = 0;
                tmp_strm_log.bytes_out = 0;
                tmp_strm_log.prx_queue_pos = 0;
@@ -2058,8 +2058,8 @@ int sess_build_logline(struct session *sess, struct stream *s, char *dst, size_t
        }
 
        t_request = -1;
-       if (tv_isge(&logs->tv_request, &logs->tv_accept))
-               t_request = ns_to_ms(tv_to_ns(&logs->tv_request) - tv_to_ns(&logs->tv_accept));
+       if ((llong)(logs->request_ts - logs->accept_ts) >= 0)
+               t_request = ns_to_ms(logs->request_ts - logs->accept_ts);
 
        tmplog = dst;
 

diff --git a/src/mux_h1.c b/src/mux_h1.c
index 9a986504c6e4ad178c205cc0749e37d2560ae6c9..57b083a1ff78a91ec4bf46fac0d59c1f60a64663 100644 (file)
--- a/src/mux_h1.c
+++ b/src/mux_h1.c
@@ -3017,7 +3017,7 @@ static int h1_process(struct h1c * h1c)
                }
 
                if (h1s->sess->t_idle == -1)
-                       h1s->sess->t_idle = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&h1s->sess->tv_accept)) - h1s->sess->t_handshake;
+                       h1s->sess->t_idle = ns_to_ms(tv_to_ns(&now) - h1s->sess->accept_ts) - h1s->sess->t_handshake;
 
                /* Get the stream rxbuf */
                buf = h1_get_buf(h1c, &h1s->rxbuf);
@@ -3427,7 +3427,7 @@ static void h1_detach(struct sedesc *sd)
        h1c = h1s->h1c;
 
        sess->accept_date = date;
-       sess->tv_accept   = now;
+       sess->accept_ts   = tv_to_ns(&now);
        sess->t_handshake = 0;
        sess->t_idle      = -1;
 

diff --git a/src/mux_h2.c b/src/mux_h2.c
index 41246793771894e2f014dfae0ffa68abc96303ae..16d73e6ca07574f5e5ea0f6cd3bdb4ea870666fd 100644 (file)
--- a/src/mux_h2.c
+++ b/src/mux_h2.c
@@ -1573,7 +1573,7 @@ static struct h2s *h2c_frt_stream_new(struct h2c *h2c, int id, struct buffer *in
         * request) and the idle time, which is the delay since the previous
         * request. We can set the value now, it will be copied by stream_new().
         */
-       sess->t_idle = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&sess->tv_accept)) - sess->t_handshake;
+       sess->t_idle = ns_to_ms(tv_to_ns(&now) - sess->accept_ts) - sess->t_handshake;
 
        if (!sc_new_from_endp(h2s->sd, sess, input))
                goto out_close;
@@ -1586,7 +1586,7 @@ static struct h2s *h2c_frt_stream_new(struct h2c *h2c, int id, struct buffer *in
         * right now.
         */
        sess->accept_date = date;
-       sess->tv_accept   = now;
+       sess->accept_ts   = tv_to_ns(&now);
        sess->t_handshake = 0;
        sess->t_idle = 0;
 

diff --git a/src/session.c b/src/session.c
index 382bef003889f8e97a1fe3818a2d66feca8c0fe3..f42c51410acdf11dbd408e546dd68f2b3b0640b3 100644 (file)
--- a/src/session.c
+++ b/src/session.c
@@ -45,7 +45,7 @@ struct session *session_new(struct proxy *fe, struct listener *li, enum obj_type
                sess->fe = fe;
                sess->origin = origin;
                sess->accept_date = date; /* user-visible date for logging */
-               sess->tv_accept   = now;  /* corrected date for internal use */
+               sess->accept_ts = tv_to_ns(&now);  /* corrected date for internal use */
                sess->stkctr = NULL;
                if (pool_head_stk_ctr) {
                        sess->stkctr = pool_alloc(pool_head_stk_ctr);
@@ -432,7 +432,7 @@ int conn_complete_session(struct connection *conn)
 {
        struct session *sess = conn->owner;
 
-       sess->t_handshake = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&sess->tv_accept));
+       sess->t_handshake = ns_to_ms(tv_to_ns(&now) - sess->accept_ts);
 
        if (conn->flags & CO_FL_ERROR)
                goto fail;

diff --git a/src/stream.c b/src/stream.c
index 94a429a985a6812bbfa05e095d08094b7860449a..82a06ed7664e7ba5e1cef4ab1840fe538fbd276f 100644 (file)
--- a/src/stream.c
+++ b/src/stream.c
@@ -364,7 +364,7 @@ struct stream *stream_new(struct session *sess, struct stconn *sc, struct buffer
        s->flags = 0;
        s->logs.logwait = sess->fe->to_log;
        s->logs.level = 0;
-       tv_zero(&s->logs.tv_request);
+       s->logs.request_ts = 0;
        s->logs.t_queue = -1;
        s->logs.t_connect = -1;
        s->logs.t_data = -1;
@@ -375,7 +375,7 @@ struct stream *stream_new(struct session *sess, struct stconn *sc, struct buffer
        s->obj_type = OBJ_TYPE_STREAM;
 
        s->logs.accept_date = sess->accept_date;
-       s->logs.tv_accept = sess->tv_accept;
+       s->logs.accept_ts = sess->accept_ts;
        s->logs.t_handshake = sess->t_handshake;
        s->logs.t_idle = sess->t_idle;
 
@@ -902,7 +902,7 @@ static void back_establish(struct stream *s)
        /* First, centralize the timers information, and clear any irrelevant
         * timeout.
         */
-       s->logs.t_connect = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept));
+       s->logs.t_connect = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts);
        s->conn_exp = TICK_ETERNITY;
        s->flags &= ~SF_CONN_EXP;
 
@@ -2595,7 +2595,7 @@ struct task *process_stream(struct task *t, void *context, unsigned int state)
        }
 
        if (!(s->flags & SF_IGNORE)) {
-               s->logs.t_close = ns_to_ms(tv_to_ns(&now) - tv_to_ns(&s->logs.tv_accept));
+               s->logs.t_close = ns_to_ms(tv_to_ns(&now) - s->logs.accept_ts);
 
                stream_process_counters(s);
 
@@ -2660,8 +2660,8 @@ void stream_update_time_stats(struct stream *s)
        if (t_connect < 0 || t_data < 0)
                return;
 
-       if (tv_isge(&s->logs.tv_request, &s->logs.tv_accept))
-               t_request = ns_to_ms(tv_to_ns(&s->logs.tv_request) - tv_to_ns(&s->logs.tv_accept));
+       if ((llong)(s->logs.request_ts - s->logs.accept_ts) >= 0)
+               t_request = ns_to_ms(s->logs.request_ts - s->logs.accept_ts);
 
        t_data    -= t_connect;
        t_connect -= t_queue;
@@ -3699,7 +3699,7 @@ static int cli_io_handler_dump_sess(struct appctx *appctx)
                chunk_appendf(&trash,
                             " ts=%02x epoch=%#x age=%s calls=%u rate=%u cpu=%llu lat=%llu",
                             curr_strm->task->state, curr_strm->stream_epoch,
-                            human_time(now.tv_sec - curr_strm->logs.tv_accept.tv_sec, 1),
+                            human_time(now.tv_sec - ns_to_sec(curr_strm->logs.accept_ts), 1),
                             curr_strm->task->calls, read_freq_ctr(&curr_strm->call_rate),
                             (unsigned long long)curr_strm->cpu_time, (unsigned long long)curr_strm->lat_time);