From ad5a5f677974d1dd16aa29c614e79fbe0e7d573f Mon Sep 17 00:00:00 2001 From: Willy Tarreau Date: Thu, 27 Apr 2023 09:46:02 +0200 Subject: [PATCH] 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. --- include/haproxy/mux_quic.h | 4 ++-- include/haproxy/session-t.h | 2 +- include/haproxy/stream-t.h | 4 ++-- src/backend.c | 16 ++++++++-------- src/cli.c | 8 ++++---- src/hlua.c | 2 +- src/http_act.c | 4 ++-- src/http_ana.c | 14 +++++++------- src/log.c | 10 +++++----- src/mux_h1.c | 4 ++-- src/mux_h2.c | 4 ++-- src/session.c | 4 ++-- src/stream.c | 14 +++++++------- 13 files changed, 45 insertions(+), 45 deletions(-) diff --git a/include/haproxy/mux_quic.h b/include/haproxy/mux_quic.h index ac87aee8cd..9c643e9ab3 100644 --- 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 46023f0239..dff167ecb5 100644 --- 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 fe85217c0a..14293d5b82 100644 --- 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 085bb1bf75..7b8e12d3f3 100644 --- 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 412cbfb292..5af4804fd3 100644 --- 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 b14ac838f8..7c49f5e0b5 100644 --- 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 596e68c546..07997fa188 100644 --- 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 d97d442472..b623af5751 100644 --- 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 175aea09ad..60c7daad85 100644 --- 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 9a986504c6..57b083a1ff 100644 --- 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 4124679377..16d73e6ca0 100644 --- 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 382bef0038..f42c51410a 100644 --- 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 94a429a985..82a06ed766 100644 --- 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); -- 2.39.5