commit ba13c3b3695cb4758848d856174b725afcc7cdb8
author Florin Coras <fcoras@cisco.com> Wed Oct 30 17:11:53 2019 -0700
committer Dave Wallace <dwallacelf@gmail.com> Thu Oct 31 13:42:02 2019 +0000
tree 0f679b4b451ab01e1827638edc877fcf618fa8cf
parent b31d39358b42bbe4e7754ea5a3f9c18da08bce18

session: fix dispatch event logging

Type: fix

Change-Id: Icf3c73cd7eb7565ed6e1b0371da172b5408a9d36
Signed-off-by: Florin Coras <fcoras@cisco.com>

src/vnet/session/session_debug.h

diff --git a/src/vnet/session/session_debug.h b/src/vnet/session/session_debug.h
index 228c1b3..a57b02d 100644
--- a/src/vnet/session/session_debug.h
+++ b/src/vnet/session/session_debug.h
@@ -37,6 +37,7 @@
 
 #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)
 
@@ -100,27 +101,35 @@
   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(_node_evt, _ntx)
+#endif /* SESSION_DISPATCH_DBG */
 
 #if SESSION_EVT_POLL_DBG && SESSION_DEBUG > 1
 #define SESSION_EVT_POLL_GAP(_wrk)					\
@@ -131,14 +140,15 @@
     .format_args = "i4",						\
   };									\
   DEC_SESSION_ED(_e, 1);						\
-  ed->data[0] =	(u32) ((now - _wrk->last_event_poll)*1000000.0);	\
+  ed->data[0] =	(u32) ((_wrk->last_vlib_time - _wrk->last_event_poll)	\
+			*1000000.0);					\
 }
 #define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_wrk)			\
 {									\
-  if (PREDICT_TRUE (smm->last_event_poll != 0.0))			\
-    if (now > smm->last_event_poll + 500e-6)				\
-      SESSION_EVT_POLL_GAP(smm, _ti);					\
-  _wrk->last_event_poll = 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(_wrk)			\
@@ -165,15 +175,16 @@
 #define SESSION_EVT_DISPATCH_START_HANDLER(_wrk)			\
 {									\
   if (SESSION_DEQ_EVTS > 1)						\
-    SESSION_EVT_DEQ_NODE_HANDLER (0);					\
+    SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 0, 0);				\
   SESSION_EVT_POLL_GAP_TRACK_HANDLER (wrk);				\
 }
 
 #define SESSION_EVT_DISPATCH_END_HANDLER(_wrk, _ntx)			\
 {									\
-  if (SESSION_DEQ_EVTS > 1 || _ntx)					\
-    SESSION_EVT_DEQ_NODE_HANDLER (1);					\
+  if (_ntx)								\
+    SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 1, _ntx);			\
   SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk);				\
+  _wrk->last_event_poll = vlib_time_now (_wrk->vm);			\
 }
 
 #define CONCAT_HELPER(_a, _b) _a##_b