session: add session debug cli

- add session debug cli to enable fine control of which event logs
are enable/disable with below syntax
  session debug {show | group <list> level <n>}
  list may be entered with a dash, "0-4"
  or it may be entered with a comma, "0,1,4"
- fix compilation errors when SESSION_EVT is enable
- change SESSION_EVT_FREE_HANDLER to use DEC_SESSION_ED instead of
DEC_SESSION_ETD because the transport may already be free when the
handler is called

Type: improvement

Signed-off-by: Steven Luong <sluong@cisco.com>
Change-Id: Iab2989e0a847bb59002ef16494eebcc1d112b2ae

4 files changed, 176 insertions, 54 deletions

diff --git a/src/vnet/session/session.c b/src/vnet/session/session.c
index 54d9b22c838..4c57b1ac9bb 100644
--- a/src/vnet/session/session.c
+++ b/src/vnet/session/session.c
@@ -216,15 +216,12 @@ session_alloc (u32 thread_index)
 void
 session_free (session_t * s)
 {
-  if (CLIB_DEBUG)
-    {
-      u8 thread_index = s->thread_index;
-      clib_memset (s, 0xFA, sizeof (*s));
-      pool_put (session_main.wrk[thread_index].sessions, s);
-      return;
-    }
+  session_worker_t *wrk = &session_main.wrk[s->thread_index];
+
   SESSION_EVT (SESSION_EVT_FREE, s);
-  pool_put (session_main.wrk[s->thread_index].sessions, s);
+  if (CLIB_DEBUG)
+    clib_memset (s, 0xFA, sizeof (*s));
+  pool_put (wrk->sessions, s);
 }
 
 u8
diff --git a/src/vnet/session/session_debug.c b/src/vnet/session/session_debug.c
index e4efe1b244e..a6c4adb2bdc 100644
--- a/src/vnet/session/session_debug.c
+++ b/src/vnet/session/session_debug.c
@@ -117,12 +117,96 @@ session_debug_init (void)
       sdm->wrk[thread].start_time = session_dbg_time_now (thread);
     }
 }
+
+static const char *session_evt_grp_str[] = {
+#define _(sym, str) str,
+  foreach_session_evt_grp
+#undef _
+};
+
+static void
+session_debug_show_groups (vlib_main_t *vm)
+{
+  session_dbg_main_t *sdm = &session_dbg_main;
+  int i = 0;
+
+  vlib_cli_output (vm, "%-10s%-30s%-10s", "Index", "Group", "Level");
+
+  for (i = 0; i < SESSION_EVT_N_GRP; i++)
+    vlib_cli_output (vm, "%-10d%-30s%-10d", i, session_evt_grp_str[i],
+		     sdm->grp_dbg_lvl[i]);
+}
+
+static clib_error_t *
+session_debug_fn (vlib_main_t *vm, unformat_input_t *input,
+		  vlib_cli_command_t *cmd)
+{
+  session_dbg_main_t *sdm = &session_dbg_main;
+  u32 group, level = ~0;
+  clib_error_t *error = 0;
+  u8 is_show = 0;
+  uword *bitmap = 0;
+
+  while (unformat_check_input (input) != UNFORMAT_END_OF_INPUT)
+    {
+      if (unformat (input, "show"))
+	is_show = 1;
+      else if (unformat (input, "group %U", unformat_bitmap_list, &bitmap))
+	;
+      else if (unformat (input, "level %d", &level))
+	;
+      else
+	{
+	  error = clib_error_return (0, "unknown input `%U'",
+				     format_unformat_error, input);
+	  goto done;
+	}
+    }
+
+  if (is_show)
+    {
+      session_debug_show_groups (vm);
+      goto done;
+    }
+  if (level == ~0)
+    {
+      vlib_cli_output (vm, "level must be entered");
+      goto done;
+    }
+
+  group = clib_bitmap_last_set (bitmap);
+  if (group == ~0)
+    {
+      vlib_cli_output (vm, "group must be entered");
+      goto done;
+    }
+  if (group >= SESSION_EVT_N_GRP)
+    {
+      vlib_cli_output (vm, "group out of bounds");
+      goto done;
+    }
+  clib_bitmap_foreach (group, bitmap)
+    sdm->grp_dbg_lvl[group] = level;
+
+done:
+
+  clib_bitmap_free (bitmap);
+  return error;
+}
+
+VLIB_CLI_COMMAND (session_debug_command, static) = {
+  .path = "session debug",
+  .short_help = "session debug {show | debug group <list> level <n>}",
+  .function = session_debug_fn,
+  .is_mp_safe = 1,
+};
+
 #else
 void
 session_debug_init (void)
 {
 }
-#endif
+#endif /* SESSION_DEBUG */
 
 void
 dump_thread_0_event_queue (void)
diff --git a/src/vnet/session/session_debug.h b/src/vnet/session/session_debug.h
index 4f49ea1d2f2..588d58c790c 100644
--- a/src/vnet/session/session_debug.h
+++ b/src/vnet/session/session_debug.h
@@ -19,26 +19,56 @@
 #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_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")		\
+#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")                       \
+  _ (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;
 
+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") 	          		\
@@ -91,22 +121,28 @@ typedef struct 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;
 
-#ifdef VPP_SESSION_DEBUG
-#define SESSION_DEBUG 1 * (TRANSPORT_DEBUG > 0)
+#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 * (TRANSPORT_DEBUG > 0)
-#endif
-
-#define SESSION_DEQ_EVTS (0)
-#define SESSION_DISPATCH_DBG (0)
-#define SESSION_EVT_POLL_DBG (0)
-#define SESSION_SM (0)
+#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
 
@@ -129,16 +165,15 @@ extern session_dbg_main_t session_dbg_main;
   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_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_FREE_HANDLER(_s)
 #endif
@@ -288,17 +323,17 @@ extern session_dbg_main_t session_dbg_main;
 	counters[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_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 ;     		\
-}
+#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_IO_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)
+#define SESSION_EVT_IO_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)
 #endif /*SESSION_COUNTS_EVT_DBG */
 
 
@@ -328,8 +363,14 @@ extern session_dbg_main_t session_dbg_main;
 
 #define CONCAT_HELPER(_a, _b) _a##_b
 #define CC(_a, _b) CONCAT_HELPER(_a, _b)
-#define SESSION_EVT(_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(_evt, _args...)
 #define SESSION_DBG(_fmt, _args...)
diff --git a/src/vnet/session/session_node.c b/src/vnet/session/session_node.c
index 1908a58f08f..c29e0590aa8 100644
--- a/src/vnet/session/session_node.c
+++ b/src/vnet/session/session_node.c
@@ -1552,7 +1552,7 @@ session_tx_fifo_read_and_snd_i (session_worker_t * wrk,
   *n_tx_packets += ctx->n_segs_per_evt;
 
   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);
+	       ctx->s->tx_fifo->shr->has_event, wrk->last_vlib_time);
 
   ASSERT (ctx->left_to_snd == 0);
 
@@ -1790,7 +1790,7 @@ 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);
+  SESSION_EVT (SESSION_EVT_IO_EVT_COUNTS, e->event_type, 1, wrk);
 
   /* Regrab elements in case pool moved */
   elt = clib_llist_elt (wrk->event_elts, ei);