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 <srakula@cisco.com>
Signed-off-by: Florin Coras <fcoras@cisco.com>
Change-Id: I9f401881b345bcae5f7d8050338637fd47b3723b
Signed-off-by: Srikanth Akula <srakula@cisco.com>

4 files changed, 231 insertions, 0 deletions

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