diff --git a/include/haproxy/mux_quic.h b/include/haproxy/mux_quic.h index ac87aee8c..9c643e9ab 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 46023f023..dff167ecb 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 fe85217c0..14293d5b8 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 085bb1bf7..7b8e12d3f 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 412cbfb29..5af4804fd 100644 --- a/src/cli.c +++ b/src/cli.c @@ -2626,7 +2626,7 @@ int pcli_wait_for_request(struct stream *s, struct channel *req, int an_bit) /* 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 b14ac838f..7c49f5e0b 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 596e68c54..07997fa18 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 d97d44247..b623af575 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 175aea09a..60c7daad8 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 9a986504c..57b083a1f 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 412467937..16d73e6ca 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 382bef003..f42c51410 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 94a429a98..82a06ed76 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);