From: Srikanth Akula Date: Tue, 7 Apr 2020 02:19:49 +0000 (-0700) Subject: session: adding debug events X-Git-Tag: v20.09-rc0~222 X-Git-Url: https://gerrit.fd.io/r/gitweb?p=vpp.git;a=commitdiff_plain;h=7357043d2abc8d3811362f256e7c9086e7b0d378 session: adding debug events Type: feature Enhancing the debugging capability of tcp session layer by measing time spent for various events. This is meant only for debugging purpose Signed-off-by: Srikanth Akula Signed-off-by: Florin Coras Change-Id: I9f401881b345bcae5f7d8050338637fd47b3723b Signed-off-by: Srikanth Akula --- diff --git a/src/vnet/session/session.c b/src/vnet/session/session.c index d2dc85efa4e..caa362e1f1d 100644 --- a/src/vnet/session/session.c +++ b/src/vnet/session/session.c @@ -25,6 +25,10 @@ session_main_t session_main; +#if SESSION_DEBUG +session_dbg_main_t session_dbg_main; +#endif + static inline int session_send_evt_to_thread (void *data, void *args, u32 thread_index, session_evt_type_t evt_type) @@ -1705,6 +1709,17 @@ session_manager_main_enable (vlib_main_t * vm) /* Enable transports */ transport_enable_disable (vm, 1); + +#if SESSION_DEBUG + session_dbg_main_t *sdm = &session_dbg_main; + vec_validate_aligned (sdm->wrk, num_threads - 1, CLIB_CACHE_LINE_BYTES); + int thread; + for (thread = 0; thread < num_threads; thread++) + { + clib_memset (&sdm->wrk[thread], 0, sizeof (session_dbg_evts_t)); + } +#endif /* SESSION_DEBUG */ + return 0; } diff --git a/src/vnet/session/session_cli.c b/src/vnet/session/session_cli.c index 9f6d74c031d..563ee83c758 100644 --- a/src/vnet/session/session_cli.c +++ b/src/vnet/session/session_cli.c @@ -14,6 +14,7 @@ */ #include #include +#include u8 * format_session_fifos (u8 * s, va_list * args) @@ -879,6 +880,84 @@ VLIB_CLI_COMMAND (session_enable_disable_command, static) = }; /* *INDENT-ON* */ +#if SESSION_DEBUG + +static clib_error_t * +show_session_dbg_clock_cycles_fn (vlib_main_t * vm, unformat_input_t * input, + vlib_cli_command_t * cmd) +{ + u32 thread; + + if (unformat_check_input (input) != UNFORMAT_END_OF_INPUT) + return clib_error_return (0, "unknown input `%U'", format_unformat_error, + input); + + for (thread = 0; thread < vec_len (session_dbg_main.wrk); thread++) + { + vlib_cli_output (vm, "Threads %u:\n", thread); + session_dbg_evts_t *sdm = &session_dbg_main.wrk[thread]; + +#define _(sym, disp, type, str) \ + if(disp) \ + { \ + if (!type) \ + vlib_cli_output (vm, "\t %25s : %12lu ", \ + str, sdm->sess_dbg_evt_type[SESS_Q_##sym].u64);\ + else \ + vlib_cli_output (vm, "\t %25s : %12.3f ", \ + str, sdm->sess_dbg_evt_type[SESS_Q_##sym].f64);\ + } + + foreach_session_events +#undef _ + } + return 0; +} + + +/* *INDENT-OFF* */ +VLIB_CLI_COMMAND (show_session_dbg_clock_cycles_command, static) = +{ + .path = "show session dbg clock_cycles", + .short_help = "show session dbg clock_cycles", + .function = show_session_dbg_clock_cycles_fn, +}; +/* *INDENT-ON* */ + + +static clib_error_t * +clear_session_dbg_clock_cycles_fn (vlib_main_t * vm, unformat_input_t * input, + vlib_cli_command_t * cmd) +{ + session_dbg_evts_t *sdb; + u32 thread; + + if (unformat_check_input (input) != UNFORMAT_END_OF_INPUT) + return clib_error_return (0, "unknown input `%U'", format_unformat_error, + input); + + for (thread = 0; thread < vec_len (session_dbg_main.wrk); thread++) + { + sdb = &session_dbg_main.wrk[thread]; + clib_memset (sdb, 0, sizeof (session_dbg_evts_t)); + sdb->last_time = vlib_time_now (vlib_mains[thread]); + } + + return 0; +} + + +/* *INDENT-OFF* */ +VLIB_CLI_COMMAND (clear_session_clock_cycles_command, static) = +{ + .path = "clear session dbg clock_cycles", + .short_help = "clear session dbg clock_cycles", + .function = clear_session_dbg_clock_cycles_fn, +}; +#endif /* #if SESSION_DEBUG */ + +/* *INDENT-ON* */ + /* * fd.io coding-style-patch-verification: ON * diff --git a/src/vnet/session/session_debug.h b/src/vnet/session/session_debug.h index a57b02d228e..6140466998a 100644 --- a/src/vnet/session/session_debug.h +++ b/src/vnet/session/session_debug.h @@ -27,6 +27,9 @@ _(DISPATCH_START, "dispatch start") \ _(DISPATCH_END, "dispatch end") \ _(FREE, "session free") \ + _(DSP_CNTRS, "dispatch counters") \ + _(IO_EVT_COUNTS, "io evt counts") \ + _(EVT_COUNTS, "ctrl evt counts") \ typedef enum _session_evt_dbg { @@ -35,11 +38,69 @@ typedef enum _session_evt_dbg #undef _ } session_evt_dbg_e; +#define foreach_session_events \ +_(CLK_UPDATE_TIME, 1, 1, "Time Session Update Timers") \ +_(CLK_MQ_DEQ, 1, 1, "Time MQ Dequeue") \ +_(CLK_CTRL_EVTS, 1, 1, "Time Ctrl Events") \ +_(CLK_NEW_IO_EVTS, 1, 1, "Time New IO Events") \ +_(CLK_OLD_IO_EVTS, 1, 1, "Time Old IO Events") \ +\ +_(CNT_MQ_EVTS, 1, 0, "# of MQ Events Processed" ) \ +_(CNT_CTRL_EVTS, 1, 0, "# of Cntrl Events Processed" ) \ +_(CNT_NEW_EVTS, 1, 0, "# of New Events Processed" ) \ +_(CNT_OLD_EVTS, 1, 0, "# of Old Events Processed" ) \ +_(CNT_IO_EVTS, 1, 0, "# of Events Processed" ) \ +_(NODE_CALL_CNT, 1, 0, "Node call count") \ +_(NEW_IO_EVTS, 1, 0, "New IO Events") \ +_(OLD_IO_EVTS, 1, 0, "Old IO Events") \ +\ +_(BASE_OFFSET_IO_EVTS, 0, 0, "NULL") \ +_(SESSION_IO_EVT_RX, 1, 0, "# of IO Event RX") \ +_(SESSION_IO_EVT_TX, 1, 0, "# of IO Event TX") \ +_(SESSION_IO_EVT_TX_FLUSH, 1, 0, "# of IO Event TX Flush") \ +_(SESSION_IO_EVT_BUILTIN_RX, 1, 0, "# of IO Event BuiltIn RX") \ +_(SESSION_IO_EVT_BUILTIN_TX, 1, 0, "# of IO Event BuiltIn TX") \ + + +typedef enum +{ +#define _(sym, disp, type, str) SESS_Q_##sym, + foreach_session_events +#undef _ + SESS_Q_MAX_EVT_TYPES +} sess_q_node_events_types_t; + +typedef struct session_dbg_counter_ +{ + union + { + f64 f64; + u64 u64; + }; +} session_dbg_counter_t; + +typedef struct session_dbg_evts_t +{ + CLIB_CACHE_LINE_ALIGN_MARK (cacheline0); + f64 last_time; + u64 prev_io; + session_dbg_counter_t sess_dbg_evt_type[SESS_Q_MAX_EVT_TYPES]; +} session_dbg_evts_t; + +typedef struct session_dbg_main_ +{ + session_dbg_evts_t *wrk; +} session_dbg_main_t; + +extern session_dbg_main_t session_dbg_main; + #define SESSION_DEBUG 0 * (TRANSPORT_DEBUG > 0) #define SESSION_DEQ_EVTS (0) #define SESSION_DISPATCH_DBG (0) #define SESSION_EVT_POLL_DBG (0) #define SESSION_SM (0) +#define SESSION_CLOCKS_EVT_DBG (0) +#define SESSION_COUNTS_EVT_DBG (0) #if SESSION_DEBUG @@ -170,13 +231,78 @@ typedef enum _session_evt_dbg #define SESSION_EVT_POLL_GAP(_wrk) #define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_wrk) #define SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk) +#define SESSION_EVT_POLL_CLOCKS_TIME_HANDLER(_wrk) + #endif /* SESSION_EVT_POLL_DBG */ +#if SESSION_CLOCKS_EVT_DBG + +#define SESSION_EVT_DSP_CNTRS_UPDATE_TIME_HANDLER(_wrk, _diff, _args...) \ + session_dbg_evts_t *sdm = &session_dbg_main.wrk[_wrk->vm->thread_index]; \ + sdm->sess_dbg_evt_type[SESS_Q_CLK_UPDATE_TIME].f64 += _diff; \ + +#define SESSION_EVT_DSP_CNTRS_MQ_DEQ_HANDLER(_wrk, _diff, _cnt, _args...) \ + session_dbg_evts_t *sdm = &session_dbg_main.wrk[_wrk->vm->thread_index]; \ + sdm->sess_dbg_evt_type[SESS_Q_CNT_MQ_EVTS].u64 += _cnt; \ + sdm->sess_dbg_evt_type[SESS_Q_CLK_MQ_DEQ].f64 += _diff; \ + +#define SESSION_EVT_DSP_CNTRS_CTRL_EVTS_HANDLER(_wrk, _diff, _args...) \ + session_dbg_evts_t *sdm = &session_dbg_main.wrk[_wrk->vm->thread_index]; \ + sdm->sess_dbg_evt_type[SESS_Q_CLK_CTRL_EVTS].f64 += _diff; \ + sdm->prev_io = sdm->sess_dbg_evt_type[SESS_Q_CNT_IO_EVTS].u64; \ + +#define SESSION_EVT_DSP_CNTRS_NEW_IO_EVTS_HANDLER(_wrk, _diff, _args...) \ + session_dbg_evts_t *sdm = &session_dbg_main.wrk[_wrk->vm->thread_index]; \ + sdm->sess_dbg_evt_type[SESS_Q_CLK_NEW_IO_EVTS].f64 += _diff; \ + sdm->sess_dbg_evt_type[SESS_Q_CNT_NEW_EVTS].u64 += \ + sdm->sess_dbg_evt_type[SESS_Q_CNT_IO_EVTS].u64 - sdm->prev_io; \ + sdm->prev_io = sdm->sess_dbg_evt_type[SESS_Q_CNT_IO_EVTS].u64; \ + +#define SESSION_EVT_DSP_CNTRS_OLD_IO_EVTS_HANDLER(_wrk, _diff, _args...) \ + session_dbg_evts_t *sdm = &session_dbg_main.wrk[_wrk->vm->thread_index]; \ + sdm->sess_dbg_evt_type[SESS_Q_CLK_OLD_IO_EVTS].f64 += _diff; \ + sdm->sess_dbg_evt_type[SESS_Q_CNT_OLD_EVTS].u64 += \ + sdm->sess_dbg_evt_type[SESS_Q_CNT_IO_EVTS].u64 - sdm->prev_io; \ + +#define SESSION_EVT_DSP_CNTRS_HANDLER(_disp_evt, _wrk, _args...) \ +{ \ + f64 time_now = vlib_time_now (_wrk->vm); \ + f64 diff = time_now - session_dbg_main.wrk[_wrk->vm->thread_index].last_time; \ + session_dbg_main.wrk[_wrk->vm->thread_index].last_time = time_now; \ + CC(CC(SESSION_EVT_DSP_CNTRS_,_disp_evt),_HANDLER)(wrk, diff, _args); \ +} +#else +#define SESSION_EVT_CLOCKS_HANDLER(_node_evt, _wrk) +#endif /*SESSION_CLOCKS_EVT_DBG */ + +#if SESSION_COUNTS_EVT_DBG +#define SESSION_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk) \ +{ \ + session_dbg_main.wrk[_wrk->vm->thread_index]. \ + sess_dbg_evt_type[SESS_Q_##_node_evt].u64 += _cnt; \ +} + +#define SESSION_IO_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk) \ +{ \ + u8 type = SESS_Q_BASE_OFFSET_IO_EVTS + _node_evt +1 ; \ + session_dbg_main.wrk[_wrk->vm->thread_index]. \ + sess_dbg_evt_type[type].u64 += _cnt ; \ + session_dbg_main.wrk[_wrk->vm->thread_index]. \ + sess_dbg_evt_type[SESS_Q_CNT_IO_EVTS].u64 += _cnt ; \ +} +#else +#define SESSION_EVT_COUNTS_HANDLER(_node_evt, _wrk) +#define SESSION_IO_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk) +#endif /*SESSION_COUNTS_EVT_DBG */ + + #define SESSION_EVT_DISPATCH_START_HANDLER(_wrk) \ { \ if (SESSION_DEQ_EVTS > 1) \ SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 0, 0); \ SESSION_EVT_POLL_GAP_TRACK_HANDLER (wrk); \ + session_dbg_main.wrk[_wrk->vm->thread_index]. \ + sess_dbg_evt_type[SESS_Q_##NODE_CALL_CNT].u64 +=1; \ } #define SESSION_EVT_DISPATCH_END_HANDLER(_wrk, _ntx) \ diff --git a/src/vnet/session/session_node.c b/src/vnet/session/session_node.c index f98e7ccdb27..867ff4fcaf7 100644 --- a/src/vnet/session/session_node.c +++ b/src/vnet/session/session_node.c @@ -1196,6 +1196,7 @@ session_event_dispatch_ctrl (session_worker_t * wrk, session_evt_elt_t * elt) session_evt_ctrl_data_free (wrk, elt); session_evt_elt_free (wrk, elt); } + SESSION_EVT (SESSION_EVT_COUNTS, CNT_CTRL_EVTS, 1, wrk); } always_inline void @@ -1250,6 +1251,8 @@ session_event_dispatch_io (session_worker_t * wrk, vlib_node_runtime_t * node, clib_warning ("unhandled event type %d", e->event_type); } + SESSION_EVT (SESSION_IO_EVT_COUNTS, e->event_type, 1, wrk); + /* Regrab elements in case pool moved */ elt = pool_elt_at_index (wrk->event_elts, ei); if (!clib_llist_elt_is_linked (elt, evt_list)) @@ -1328,6 +1331,7 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node, */ transport_update_time (wrk->last_vlib_time, thread_index); n_tx_packets = vec_len (wrk->pending_tx_buffers); + SESSION_EVT (SESSION_EVT_DSP_CNTRS, UPDATE_TIME, wrk); /* * Dequeue and handle new events @@ -1347,6 +1351,7 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node, svm_msg_q_free_msg (mq, msg); } svm_msg_q_unlock (mq); + SESSION_EVT (SESSION_EVT_DSP_CNTRS, MQ_DEQ, wrk, n_to_dequeue); } /* @@ -1362,6 +1367,8 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node, })); /* *INDENT-ON* */ + SESSION_EVT (SESSION_EVT_DSP_CNTRS, CTRL_EVTS, wrk); + /* * Handle the new io events. */ @@ -1379,6 +1386,8 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node, session_event_dispatch_io (wrk, node, elt, thread_index, &n_tx_packets); } + SESSION_EVT (SESSION_EVT_DSP_CNTRS, NEW_IO_EVTS, wrk); + /* * Handle the old io events, if we had any prior to processing the new ones */ @@ -1404,6 +1413,8 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node, }; } + SESSION_EVT (SESSION_EVT_DSP_CNTRS, OLD_IO_EVTS, wrk); + if (vec_len (wrk->pending_tx_buffers)) session_flush_pending_tx_buffers (wrk, node);