X-Git-Url: https://gerrit.fd.io/r/gitweb?a=blobdiff_plain;f=src%2Fvnet%2Fsession%2Fsession_debug.h;h=a42d90d471c185f2a4769b56e23898ae2e85fe02;hb=111666766d9db5a2546a6cdb0f296977472c5993;hp=a26cd7f2636e1823c86bb70815b9cf1a3518b853;hpb=6416e6274d0817a347d5b54bc61b4f1b617ff363;p=vpp.git

diff --git a/src/vnet/session/session_debug.h b/src/vnet/session/session_debug.h
index a26cd7f2636..a42d90d471c 100644
--- a/src/vnet/session/session_debug.h
+++ b/src/vnet/session/session_debug.h
@@ -18,14 +18,18 @@
 #include <vnet/session/transport.h>
 #include <vlib/vlib.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, "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")		\
 
 typedef enum _session_evt_dbg
 {
@@ -34,10 +38,69 @@ typedef enum _session_evt_dbg
 #undef _
 } session_evt_dbg_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_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;
+  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;
+} session_dbg_main_t;
+
+extern session_dbg_main_t session_dbg_main;
+
 #define SESSION_DEBUG 0 * (TRANSPORT_DEBUG > 0)
-#define SESSION_DEQ_NODE_EVTS (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
 
@@ -74,52 +137,63 @@ typedef enum _session_evt_dbg
 #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) =						\
   {									\
@@ -127,21 +201,20 @@ typedef enum _session_evt_dbg
     .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) =						\
@@ -155,26 +228,109 @@ typedef enum _session_evt_dbg
 }
 
 #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, _dq, _args...)	\
+  session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index];	\
+  sde->counters[SESS_Q_CNT_MQ_EVTS].u64 += _dq * _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_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)
+#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(_evt, _args...) 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