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/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);