#include <vnet/session/transport.h>
#include <vlib/vlib.h>
+#include <vpp/vnet/config.h>
-#define foreach_session_dbg_evt \
- _(ENQ, "enqueue") \
- _(DEQ, "dequeue") \
- _(DEQ_NODE, "dequeue") \
- _(POLL_GAP_TRACK, "poll gap track") \
- _(POLL_DISPATCH_TIME, "dispatch time")\
- _(DISPATCH_END, "dispatch end") \
- _(FREE, "session free") \
+#define foreach_session_dbg_evt \
+ _ (ENQ, DEQ_EVTS, 1, "enqueue") \
+ _ (DEQ, DEQ_EVTS, 1, "dequeue") \
+ _ (DEQ_NODE, DISPATCH_DBG, 1, "dequeue") \
+ _ (POLL_GAP_TRACK, EVT_POLL_DBG, 1, "poll gap track") \
+ _ (POLL_DISPATCH_TIME, EVT_POLL_DBG, 1, "dispatch time") \
+ _ (DISPATCH_START, CLOCKS_EVT_DBG, 1, "dispatch start") \
+ _ (DISPATCH_END, CLOCKS_EVT_DBG, 1, "dispatch end") \
+ _ (DSP_CNTRS, CLOCKS_EVT_DBG, 1, "dispatch counters") \
+ _ (STATE_CHANGE, SM, 1, "session state change") \
+ _ (FREE, SM, 1, "session free") \
+ _ (IO_EVT_COUNTS, COUNTS_EVT_DBG, 1, "io evt counts") \
+ _ (COUNTS, COUNTS_EVT_DBG, 1, "ctrl evt counts")
typedef enum _session_evt_dbg
{
-#define _(sym, str) SESSION_EVT_##sym,
+#define _(sym, grp, lvl, str) SESSION_EVT_##sym,
foreach_session_dbg_evt
#undef _
} session_evt_dbg_e;
-#define SESSION_DEBUG 0 * (TRANSPORT_DEBUG > 0)
-#define SESSION_DEQ_NODE_EVTS (0)
-#define SESSION_EVT_POLL_DBG (0)
-#define SESSION_SM (0)
+typedef enum session_evt_lvl_
+{
+#define _(sym, grp, lvl, str) SESSION_EVT_##sym##_LVL = lvl,
+ foreach_session_dbg_evt
+#undef _
+} session_evt_lvl_e;
+
+#define foreach_session_evt_grp \
+ _ (DEQ_EVTS, "dequeue/enqueue events") \
+ _ (DISPATCH_DBG, "dispatch") \
+ _ (EVT_POLL_DBG, "event poll") \
+ _ (SM, "state machine") \
+ _ (CLOCKS_EVT_DBG, "clocks events") \
+ _ (COUNTS_EVT_DBG, "counts events")
+
+typedef enum session_evt_grp_
+{
+#define _(sym, str) SESSION_EVT_GRP_##sym,
+ foreach_session_evt_grp
+#undef _
+ SESSION_EVT_N_GRP
+} session_evt_grp_e;
+
+typedef enum session_evt_to_grp_
+{
+#define _(sym, grp, lvl, str) SESSION_EVT_##sym##_GRP = SESSION_EVT_GRP_##grp,
+ foreach_session_dbg_evt
+#undef _
+} session_evt_to_grp_e;
+
+#define foreach_session_events \
+ _ (CLK_UPDATE_TIME, 1, 1, "Time Update Time") \
+ _ (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") \
+ _ (CLK_TOTAL, 1, 1, "Time Total in Node") \
+ _ (CLK_START, 1, 1, "Time Since Last Reset") \
+ \
+ _ (CNT_MQ_EVTS, 1, 0, "# of MQ Events Processed") \
+ _ (CNT_CTRL_EVTS, 1, 0, "# of Ctrl 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") \
+ _ (CNT_NODE_CALL, 1, 0, "# of Node Calls") \
+ \
+ _ (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_TX_MAIN, 1, 0, "# of IO Event TX Main")
+
+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;
+ f64 start_time;
+ u64 prev_io;
+ session_dbg_counter_t counters[SESS_Q_MAX_EVT_TYPES];
+} session_dbg_evts_t;
+
+typedef struct session_dbg_main_
+{
+ session_dbg_evts_t *wrk;
+ u8 grp_dbg_lvl[SESSION_EVT_N_GRP];
+} session_dbg_main_t;
+
+extern session_dbg_main_t session_dbg_main;
+
+#if defined VPP_SESSION_DEBUG && (TRANSPORT_DEBUG > 0)
+#define SESSION_DEBUG (1)
+#define SESSION_DEQ_EVTS (1)
+#define SESSION_DISPATCH_DBG (1)
+#define SESSION_EVT_POLL_DBG (1)
+#define SESSION_SM (1)
+#define SESSION_CLOCKS_EVT_DBG (1)
+#define SESSION_COUNTS_EVT_DBG (1)
+#else
+#define SESSION_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)
+#endif
#if SESSION_DEBUG
ed = ELOG_DATA (&vlib_global_main.elog_main, _e)
#if SESSION_SM
-#define SESSION_EVT_FREE_HANDLER(_s) \
-{ \
- ELOG_TYPE_DECLARE (_e) = \
- { \
- .format = "free: idx %u", \
- .format_args = "i4", \
- }; \
- DEC_SESSION_ETD(_s, _e, 1); \
- ed->data[0] = _s->session_index; \
-}
+#define SESSION_EVT_STATE_CHANGE_HANDLER(_s) \
+ { \
+ ELOG_TYPE_DECLARE (_e) = { \
+ .format = "%s: idx %u", \
+ .format_args = "t4i4", \
+ .n_enum_strings = 12, \
+ .enum_strings = { \
+ "created", \
+ "listening", \
+ "connecting", \
+ "accepting", \
+ "ready", \
+ "opened", \
+ "transport closing", \
+ "closing", \
+ "app closed", \
+ "transport closed", \
+ "closed", \
+ "transport deleted", \
+ }, \
+ }; \
+ DEC_SESSION_ETD (_s, _e, 2); \
+ ed->data[0] = _s->session_state; \
+ ed->data[1] = _s->session_index; \
+ }
+
+#define SESSION_EVT_FREE_HANDLER(_s) \
+ { \
+ ELOG_TYPE_DECLARE (_e) = { \
+ .format = "free: idx %u", \
+ .format_args = "i4", \
+ }; \
+ DEC_SESSION_ED (_e, 1); \
+ ed->data[0] = _s->session_index; \
+ }
#else
+#define SESSION_EVT_STATE_CHANGE_HANDLER(_s)
#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; \
}
+#else
+#define SESSION_EVT_DEQ_HANDLER(_s, _now, _max, _has_evt, _ts)
+#define SESSION_EVT_ENQ_HANDLER(_s, _body)
+#endif /* SESSION_DEQ_NODE_EVTS */
-#define SESSION_EVT_DEQ_NODE_HANDLER(_node_evt) \
+#if SESSION_DISPATCH_DBG
+#define SESSION_EVT_DEQ_NODE_HANDLER(_wrk, _node_evt, _ntx) \
{ \
ELOG_TYPE_DECLARE (_e) = \
{ \
- .format = "deq-node: %s", \
- .format_args = "t4", \
+ .format = "dispatch: %s pkts %u re-entry: %u dispatch %u", \
+ .format_args = "t4i4i4i4", \
.n_enum_strings = 2, \
.enum_strings = { \
"start", \
"end", \
}, \
}; \
- DEC_SESSION_ED(_e, 1); \
+ DEC_SESSION_ED(_e, 4); \
ed->data[0] = _node_evt; \
+ ed->data[1] = _ntx; \
+ ed->data[2] = (_wrk->last_vlib_time - _wrk->last_event_poll) \
+ * 1000000.0; \
+ ed->data[3] = (vlib_time_now (_wrk->vm) - _wrk->last_vlib_time) \
+ * 1000000.0; \
}
#else
-#define SESSION_EVT_DEQ_HANDLER(_s, _body)
-#define SESSION_EVT_ENQ_HANDLER(_s, _body)
-#define SESSION_EVT_DEQ_NODE_HANDLER(_node_evt)
-#endif /* SESSION_DEQ_NODE_EVTS */
+#define SESSION_EVT_DEQ_NODE_HANDLER(_wrk, _node_evt, _ntx)
+#endif /* SESSION_DISPATCH_DBG */
#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) = \
{ \
.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) ((_wrk->last_vlib_time - _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) \
- SESSION_EVT_POLL_GAP(smm, _ti); \
- _smm->last_event_poll_by_thread[_ti] = now; \
+ if (PREDICT_TRUE (_wrk->last_event_poll != 0.0)) \
+ if (_wrk->last_vlib_time > _wrk->last_event_poll + 500e-6) \
+ SESSION_EVT_POLL_GAP(_wrk); \
+ _wrk->last_event_poll = _wrk->last_vlib_time; \
}
-#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) = \
}
#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)
+#define SESSION_EVT_POLL_CLOCKS_TIME_HANDLER(_wrk)
+
#endif /* SESSION_EVT_POLL_DBG */
-#define SESSION_EVT_DISPATCH_END_HANDLER(_smm, _ti) \
+#if SESSION_CLOCKS_EVT_DBG
+
+#define SESSION_EVT_DSP_CNTRS_UPDATE_TIME_HANDLER(_wrk, _diff, _args...) \
+ session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index]; \
+ sde->counters[SESS_Q_CLK_UPDATE_TIME].f64 += _diff;
+
+#define SESSION_EVT_DSP_CNTRS_MQ_DEQ_HANDLER(_wrk, _diff, _cnt, _args...) \
+ session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index]; \
+ sde->counters[SESS_Q_CNT_MQ_EVTS].u64 += _cnt; \
+ sde->counters[SESS_Q_CLK_MQ_DEQ].f64 += _diff;
+
+#define SESSION_EVT_DSP_CNTRS_CTRL_EVTS_HANDLER(_wrk, _diff, _args...) \
+ session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index]; \
+ sde->counters[SESS_Q_CLK_CTRL_EVTS].f64 += _diff; \
+ sde->prev_io = sde->counters[SESS_Q_CNT_IO_EVTS].u64; \
+
+#define SESSION_EVT_DSP_CNTRS_NEW_IO_EVTS_HANDLER(_wrk, _diff, _args...) \
+ session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index]; \
+ sde->counters[SESS_Q_CLK_NEW_IO_EVTS].f64 += _diff; \
+ sde->counters[SESS_Q_CNT_NEW_EVTS].u64 += \
+ sde->counters[SESS_Q_CNT_IO_EVTS].u64 - sde->prev_io; \
+ sde->prev_io = sde->counters[SESS_Q_CNT_IO_EVTS].u64; \
+
+#define SESSION_EVT_DSP_CNTRS_OLD_IO_EVTS_HANDLER(_wrk, _diff, _args...) \
+ session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index]; \
+ sde->counters[SESS_Q_CLK_OLD_IO_EVTS].f64 += _diff; \
+ sde->counters[SESS_Q_CNT_OLD_EVTS].u64 += \
+ sde->counters[SESS_Q_CNT_IO_EVTS].u64 - sde->prev_io; \
+
+#define SESSION_EVT_DSP_CNTRS_HANDLER(_disp_evt, _wrk, _args...) \
+{ \
+ f64 time_now = vlib_time_now (_wrk->vm), diff; \
+ 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_DSP_CNTRS_HANDLER(_disp_evt, _wrk, _args...)
+#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]. \
+ counters[SESS_Q_##_node_evt].u64 += _cnt; \
+}
+
+#define SESSION_EVT_IO_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk) \
+ { \
+ u8 type = SESS_Q_BASE_OFFSET_IO_EVTS + _node_evt + 1; \
+ session_dbg_evts_t *sde; \
+ sde = &session_dbg_main.wrk[_wrk->vm->thread_index]; \
+ sde->counters[type].u64 += _cnt; \
+ sde->counters[SESS_Q_CNT_IO_EVTS].u64 += _cnt; \
+ }
+#else
+#define SESSION_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)
+#define SESSION_EVT_IO_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)
+#endif /*SESSION_COUNTS_EVT_DBG */
+
+
+#define SESSION_EVT_DISPATCH_START_HANDLER(_wrk) \
{ \
- SESSION_EVT_DEQ_NODE_HANDLER(1); \
- SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_smm, _ti); \
+ session_dbg_evts_t *sde; \
+ sde = &session_dbg_main.wrk[_wrk->vm->thread_index]; \
+ if (SESSION_DEQ_EVTS > 1) \
+ SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 0, 0); \
+ SESSION_EVT_POLL_GAP_TRACK_HANDLER (wrk); \
+ sde->counters[SESS_Q_##CNT_NODE_CALL].u64 +=1; \
+ sde->last_time = vlib_time_now (_wrk->vm); \
+}
+
+#define SESSION_EVT_DISPATCH_END_HANDLER(_wrk, _ntx) \
+{ \
+ f64 now = vlib_time_now (_wrk->vm); \
+ session_dbg_evts_t *sde; \
+ sde = &session_dbg_main.wrk[_wrk->vm->thread_index]; \
+ if (_ntx) \
+ SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 1, _ntx); \
+ SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk); \
+ _wrk->last_event_poll = now; \
+ sde->counters[SESS_Q_CLK_TOTAL].f64 += now - _wrk->last_vlib_time; \
+ sde->counters[SESS_Q_CLK_START].f64 = now - sde->start_time; \
}
#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_lvl(_evt) CC (_evt, _LVL)
+#define session_evt_grp(_evt) CC (_evt, _GRP)
+#define session_evt_grp_dbg_lvl(_evt) \
+ session_dbg_main.grp_dbg_lvl[session_evt_grp (_evt)]
+#define SESSION_EVT(_evt, _args...) \
+ if (PREDICT_FALSE (session_evt_grp_dbg_lvl (_evt) >= \
+ session_evt_lvl (_evt))) \
+ CC (_evt, _HANDLER) (_args)
#else
-#define SESSION_EVT_DBG(_evt, _args...)
+#define SESSION_EVT(_evt, _args...)
#define SESSION_DBG(_fmt, _args...)
#endif /* SESSION_DEBUG */
+void session_debug_init (void);
+
#endif /* SRC_VNET_SESSION_SESSION_DEBUG_H_ */
/*
* fd.io coding-style-patch-verification: ON