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 ac87aee..9c643e9 100644
--- a/include/haproxy/mux_quic.h
+++ b/include/haproxy/mux_quic.h
@@ -101,7 +101,7 @@
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 @@
/* 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 46023f0..dff167e 100644
--- a/include/haproxy/session-t.h
+++ b/include/haproxy/session-t.h
@@ -49,7 +49,7 @@
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 fe85217..14293d5 100644
--- a/include/haproxy/stream-t.h
+++ b/include/haproxy/stream-t.h
@@ -185,10 +185,10 @@
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 085bb1b..7b8e12d 100644
--- a/src/backend.c
+++ b/src/backend.c
@@ -2024,7 +2024,7 @@
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 @@
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 @@
/* ... 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 @@
/* 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 @@
}
/* 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 @@
*/
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 412cbfb..5af4804 100644
--- a/src/cli.c
+++ b/src/cli.c
@@ -2626,7 +2626,7 @@
/* 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 @@
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 @@
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 b14ac83..7c49f5e 100644
--- a/src/hlua.c
+++ b/src/hlua.c
@@ -8295,7 +8295,7 @@
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 596e68c..07997fa 100644
--- a/src/http_act.c
+++ b/src/http_act.c
@@ -1284,7 +1284,7 @@
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 @@
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 d97d442..b623af5 100644
--- a/src/http_ana.c
+++ b/src/http_ana.c
@@ -439,7 +439,7 @@
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 @@
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 @@
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 @@
* 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 @@
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 @@
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 @@
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 175aea0..60c7daa 100644
--- a/src/log.c
+++ b/src/log.c
@@ -2010,15 +2010,15 @@
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 @@
}
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 9a98650..57b083a 100644
--- a/src/mux_h1.c
+++ b/src/mux_h1.c
@@ -3017,7 +3017,7 @@
}
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 @@
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 4124679..16d73e6 100644
--- a/src/mux_h2.c
+++ b/src/mux_h2.c
@@ -1573,7 +1573,7 @@
* 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 @@
* 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 382bef0..f42c514 100644
--- a/src/session.c
+++ b/src/session.c
@@ -45,7 +45,7 @@
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 @@
{
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 94a429a..82a06ed 100644
--- a/src/stream.c
+++ b/src/stream.c
@@ -364,7 +364,7 @@
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 @@
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 @@
/* 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 @@
}
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 @@
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 @@
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);