ligang/vpp
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

session: adding debug events

Browse Source 
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 <srakula@cisco.com>
Signed-off-by: Florin Coras <fcoras@cisco.com>
Change-Id: I9f401881b345bcae5f7d8050338637fd47b3723b
Signed-off-by: Srikanth Akula <srakula@cisco.com>
This commit is contained in:
Srikanth Akula
2020-04-06 19:19:49 -07:00
committed by Florin Coras
parent c39150df4d
commit 7357043d2a
4 changed files with 231 additions and 0 deletions

15
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;
}

79
src/vnet/session/session_cli.c

@ -14,6 +14,7 @@
*/
#include <vnet/session/application.h>
#include <vnet/session/session.h>
#include <vnet/session/session_debug.h>
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
*

126
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) \

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