From cca9618a5e1b126263ef262974b0b4d6ac6352a2 Mon Sep 17 00:00:00 2001 From: Florin Coras Date: Fri, 19 Jul 2019 07:34:13 -0700 Subject: session: improve event logging Type:feature Change-Id: I67a52ee48963a66915e2ebd116626eb9c296a9a5 Signed-off-by: Florin Coras --- src/vnet/session/session.c | 13 ++------ src/vnet/session/session.h | 12 +++----- src/vnet/session/session_debug.h | 66 +++++++++++++++++++++++----------------- src/vnet/session/session_node.c | 18 +++-------- 4 files changed, 49 insertions(+), 60 deletions(-) diff --git a/src/vnet/session/session.c b/src/vnet/session/session.c index 9769c013e2f..4e340687041 100644 --- a/src/vnet/session/session.c +++ b/src/vnet/session/session.c @@ -176,7 +176,7 @@ session_free (session_t * s) pool_put (session_main.wrk[thread_index].sessions, s); return; } - SESSION_EVT_DBG (SESSION_EVT_FREE, s); + SESSION_EVT (SESSION_EVT_FREE, s); pool_put (session_main.wrk[s->thread_index].sessions, s); } @@ -518,12 +518,7 @@ session_enqueue_notify_inline (session_t * s) return 0; } - /* *INDENT-OFF* */ - SESSION_EVT_DBG(SESSION_EVT_ENQ, s, ({ - ed->data[0] = SESSION_IO_EVT_RX; - ed->data[1] = svm_fifo_max_dequeue_prod (s->rx_fifo); - })); - /* *INDENT-ON* */ + SESSION_EVT (SESSION_EVT_ENQ, s, svm_fifo_max_dequeue_prod (s->rx_fifo)); s->flags &= ~SESSION_F_RX_EVT; if (PREDICT_FALSE (app_worker_lock_and_send_event (app_wrk, s, @@ -1393,10 +1388,6 @@ session_manager_main_enable (vlib_main_t * vm) clib_rwlock_init (&smm->wrk[i].peekers_rw_locks); } -#if SESSION_DEBUG - vec_validate (smm->last_event_poll_by_thread, num_threads - 1); -#endif - /* Allocate vpp event queues segment and queue */ session_vpp_event_queues_allocate (smm); diff --git a/src/vnet/session/session.h b/src/vnet/session/session.h index 73c6dc82988..1e3229171da 100644 --- a/src/vnet/session/session.h +++ b/src/vnet/session/session.h @@ -113,6 +113,10 @@ typedef struct session_worker_ u32 last_tx_packets; +#if SESSION_DEBUG + /** last event poll time by thread */ + f64 last_event_poll; +#endif } session_worker_t; typedef int (session_fifo_rx_fn) (vlib_main_t * vm, @@ -178,14 +182,6 @@ typedef struct session_main_ /** Preallocate session config parameter */ u32 preallocated_sessions; -#if SESSION_DEBUG - /** - * last event poll time by thread - * Debug only. Will cause false cache-line sharing as-is - */ - f64 *last_event_poll_by_thread; -#endif - } session_main_t; extern session_main_t session_main; diff --git a/src/vnet/session/session_debug.h b/src/vnet/session/session_debug.h index a26cd7f2636..228c1b36ac6 100644 --- a/src/vnet/session/session_debug.h +++ b/src/vnet/session/session_debug.h @@ -24,6 +24,7 @@ _(DEQ_NODE, "dequeue") \ _(POLL_GAP_TRACK, "poll gap track") \ _(POLL_DISPATCH_TIME, "dispatch time")\ + _(DISPATCH_START, "dispatch start") \ _(DISPATCH_END, "dispatch end") \ _(FREE, "session free") \ @@ -35,7 +36,7 @@ typedef enum _session_evt_dbg } session_evt_dbg_e; #define SESSION_DEBUG 0 * (TRANSPORT_DEBUG > 0) -#define SESSION_DEQ_NODE_EVTS (0) +#define SESSION_DEQ_EVTS (0) #define SESSION_EVT_POLL_DBG (0) #define SESSION_SM (0) @@ -74,27 +75,30 @@ typedef enum _session_evt_dbg #define SESSION_EVT_FREE_HANDLER(_s) #endif -#if SESSION_DEQ_NODE_EVTS && SESSION_DEBUG > 1 -#define SESSION_EVT_DEQ_HANDLER(_s, _body) \ +#if SESSION_DEQ_EVTS +#define SESSION_EVT_DEQ_HANDLER(_s, _now, _max, _has_evt, _ts) \ { \ ELOG_TYPE_DECLARE (_e) = \ { \ - .format = "deq: id %d len %d rd %d wnd %d", \ + .format = "deq: now %u max %d evt %u ts %d", \ .format_args = "i4i4i4i4", \ }; \ DEC_SESSION_ETD(_s, _e, 4); \ - do { _body; } while (0); \ + ed->data[0] = _now; \ + ed->data[1] = _max; \ + ed->data[2] = _has_evt; \ + ed->data[3] = _ts * 1000000.0; \ } -#define SESSION_EVT_ENQ_HANDLER(_s, _body) \ +#define SESSION_EVT_ENQ_HANDLER(_s, _len) \ { \ ELOG_TYPE_DECLARE (_e) = \ { \ - .format = "enq: id %d length %d", \ - .format_args = "i4i4", \ + .format = "enq: length %d", \ + .format_args = "i4", \ }; \ - DEC_SESSION_ETD(_s, _e, 2); \ - do { _body; } while (0); \ + DEC_SESSION_ETD(_s, _e, 1); \ + ed->data[0] = _len; \ } #define SESSION_EVT_DEQ_NODE_HANDLER(_node_evt) \ @@ -119,7 +123,7 @@ typedef enum _session_evt_dbg #endif /* SESSION_DEQ_NODE_EVTS */ #if SESSION_EVT_POLL_DBG && SESSION_DEBUG > 1 -#define SESSION_EVT_POLL_GAP(_smm, _ti) \ +#define SESSION_EVT_POLL_GAP(_wrk) \ { \ ELOG_TYPE_DECLARE (_e) = \ { \ @@ -127,21 +131,19 @@ typedef enum _session_evt_dbg .format_args = "i4", \ }; \ DEC_SESSION_ED(_e, 1); \ - ed->data[0] = (u32) ((now - \ - _smm->last_event_poll_by_thread[_ti])*1000000.0); \ + ed->data[0] = (u32) ((now - _wrk->last_event_poll)*1000000.0); \ } -#define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_smm, _ti) \ +#define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_wrk) \ { \ - if (PREDICT_TRUE (smm->last_event_poll_by_thread[_ti] != 0.0)) \ - if (now > smm->last_event_poll_by_thread[_ti] + 500e-6) \ + if (PREDICT_TRUE (smm->last_event_poll != 0.0)) \ + if (now > smm->last_event_poll + 500e-6) \ SESSION_EVT_POLL_GAP(smm, _ti); \ - _smm->last_event_poll_by_thread[_ti] = now; \ + _wrk->last_event_poll = now; \ } -#define SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_smm, _ti) \ +#define SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk) \ { \ - f64 diff = vlib_time_now (vlib_get_main ()) - \ - _smm->last_event_poll_by_thread[_ti]; \ + f64 diff = vlib_time_now (vlib_get_main ()) - _wrk->last_event_poll; \ if (diff > 5e-2) \ { \ ELOG_TYPE_DECLARE (_e) = \ @@ -155,23 +157,31 @@ typedef enum _session_evt_dbg } #else -#define SESSION_EVT_POLL_GAP(_smm, _my_thread_index) -#define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_smm, _my_thread_index) -#define SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_smm, _ti) +#define SESSION_EVT_POLL_GAP(_wrk) +#define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_wrk) +#define SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk) #endif /* SESSION_EVT_POLL_DBG */ -#define SESSION_EVT_DISPATCH_END_HANDLER(_smm, _ti) \ +#define SESSION_EVT_DISPATCH_START_HANDLER(_wrk) \ +{ \ + if (SESSION_DEQ_EVTS > 1) \ + SESSION_EVT_DEQ_NODE_HANDLER (0); \ + SESSION_EVT_POLL_GAP_TRACK_HANDLER (wrk); \ +} + +#define SESSION_EVT_DISPATCH_END_HANDLER(_wrk, _ntx) \ { \ - SESSION_EVT_DEQ_NODE_HANDLER(1); \ - SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_smm, _ti); \ + if (SESSION_DEQ_EVTS > 1 || _ntx) \ + SESSION_EVT_DEQ_NODE_HANDLER (1); \ + SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk); \ } #define CONCAT_HELPER(_a, _b) _a##_b #define CC(_a, _b) CONCAT_HELPER(_a, _b) -#define SESSION_EVT_DBG(_evt, _args...) CC(_evt, _HANDLER)(_args) +#define SESSION_EVT(_evt, _args...) CC(_evt, _HANDLER)(_args) #else -#define SESSION_EVT_DBG(_evt, _args...) +#define SESSION_EVT(_evt, _args...) #define SESSION_DBG(_fmt, _args...) #endif /* SESSION_DEBUG */ diff --git a/src/vnet/session/session_node.c b/src/vnet/session/session_node.c index ca6663c0b01..a8478884806 100644 --- a/src/vnet/session/session_node.c +++ b/src/vnet/session/session_node.c @@ -508,15 +508,6 @@ session_tx_fill_buffer (vlib_main_t * vm, session_tx_context_t * ctx, */ if (PREDICT_FALSE (ctx->n_bufs_per_seg > 1 && ctx->left_to_snd)) session_tx_fifo_chain_tail (vm, ctx, b, n_bufs, peek_data); - - /* *INDENT-OFF* */ - SESSION_EVT_DBG(SESSION_EVT_DEQ, ctx->s, ({ - ed->data[0] = SESSION_IO_EVT_TX; - ed->data[1] = ctx->max_dequeue; - ed->data[2] = len_to_deq; - ed->data[3] = ctx->left_to_snd; - })); - /* *INDENT-ON* */ } always_inline u8 @@ -777,6 +768,9 @@ session_tx_fifo_read_and_snd_i (vlib_main_t * vm, vlib_node_runtime_t * node, transport_connection_update_tx_stats (ctx->tc, ctx->max_len_to_snd); vlib_put_next_frame (vm, node, next_index, n_left_to_next); + SESSION_EVT (SESSION_EVT_DEQ, ctx->s, ctx->max_len_to_snd, ctx->max_dequeue, + ctx->s->tx_fifo->has_event, wrk->last_vlib_time); + /* If we couldn't dequeue all bytes mark as partially read */ ASSERT (ctx->left_to_snd == 0); if (ctx->max_len_to_snd < ctx->max_dequeue) @@ -865,7 +859,7 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node, svm_msg_q_t *mq; void (*fp) (void *); - SESSION_EVT_DBG (SESSION_EVT_POLL_GAP_TRACK, smm, thread_index); + SESSION_EVT (SESSION_EVT_DISPATCH_START, wrk); /* * Update transport time @@ -873,8 +867,6 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node, session_update_dispatch_period (wrk, now, thread_index); transport_update_time (now, thread_index); - SESSION_EVT_DBG (SESSION_EVT_DEQ_NODE, 0); - /* Make sure postponed events are handled first */ new_he = pool_elt_at_index (wrk->event_elts, wrk->new_head); new_te = clib_llist_prev (wrk->event_elts, evt_list, new_he); @@ -1032,7 +1024,7 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node, vlib_node_increment_counter (vm, session_queue_node.index, SESSION_QUEUE_ERROR_TX, n_tx_packets); - SESSION_EVT_DBG (SESSION_EVT_DISPATCH_END, smm, thread_index); + SESSION_EVT (SESSION_EVT_DISPATCH_END, wrk, n_tx_packets); return n_tx_packets; } -- cgit 1.2.3-korg