RepoMirrors/haproxy
1
0
Fork 0
mirror of http://git.haproxy.org/git/haproxy.git/ synced 2025-03-07 11:58:55 +00:00
Code Issues Packages Projects Releases Wiki Activity

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

Browse Source 
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.
This commit is contained in:
Willy Tarreau 2023-04-27 09:46:02 +02:00
parent aaebcae58b
commit ad5a5f6779
13 changed files with 45 additions and 45 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
include/haproxy/mux_quic.h
View File

@ -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;

2
include/haproxy/session-t.h
View File

@ -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 */

4
include/haproxy/stream-t.h
View File

@ -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 ... */

16
src/backend.c
View File

@ -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);
}

8
src/cli.c
View File

@ -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;

2
src/hlua.c
View File

@ -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);
}

4
src/http_act.c
View File

@ -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 */

14
src/http_ana.c
View File

@ -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 */

10
src/log.c
View File

@ -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;

4
src/mux_h1.c
View File

@ -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;

4
src/mux_h2.c
View File

@ -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;

4
src/session.c
View File

@ -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;

14
src/stream.c
View File

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