session: cleanup debug code

Type: refactor

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

6 files changed, 363 insertions, 319 deletions

diff --git a/src/vnet/CMakeLists.txt b/src/vnet/CMakeLists.txt
index 151b0997e52..9911b0420a6 100644
--- a/src/vnet/CMakeLists.txt
+++ b/src/vnet/CMakeLists.txt
@@ -1159,6 +1159,7 @@ list(APPEND VNET_API_FILES devices/pipe/pipe.api)
 
 list(APPEND VNET_SOURCES
   session/session.c
+  session/session_debug.c
   session/session_table.c
   session/session_rules_table.c
   session/session_lookup.c
diff --git a/src/vnet/session/session.c b/src/vnet/session/session.c
index caa362e1f1d..1274408675f 100644
--- a/src/vnet/session/session.c
+++ b/src/vnet/session/session.c
@@ -18,17 +18,12 @@
  */
 
 #include <vnet/session/session.h>
-#include <vnet/session/session_debug.h>
 #include <vnet/session/application.h>
 #include <vnet/dpo/load_balance.h>
 #include <vnet/fib/ip4_fib.h>
 
 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)
@@ -1709,16 +1704,7 @@ 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 */
+  session_debug_init ();
 
   return 0;
 }
diff --git a/src/vnet/session/session_cli.c b/src/vnet/session/session_cli.c
index 563ee83c758..9f6d74c031d 100644
--- a/src/vnet/session/session_cli.c
+++ b/src/vnet/session/session_cli.c
@@ -14,7 +14,6 @@
  */
 #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)
@@ -880,84 +879,6 @@ 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.c b/src/vnet/session/session_debug.c
new file mode 100644
index 00000000000..33d1dc57196
--- /dev/null
+++ b/src/vnet/session/session_debug.c
@@ -0,0 +1,281 @@
+/*
+ * Copyright (c) 2020 Cisco and/or its affiliates.
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at:
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include <vnet/session/session_debug.h>
+#include <vnet/session/session.h>
+
+#if SESSION_DEBUG > 0
+
+session_dbg_main_t session_dbg_main;
+
+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->counters[SESS_Q_##sym].u64);		\
+      else								\
+	vlib_cli_output (vm, "\t %25s : %12.3f ", str,                  \
+	                 sdm->counters[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 *sde;
+  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++)
+    {
+      sde = &session_dbg_main.wrk[thread];
+      clib_memset (sde, 0, sizeof (session_dbg_evts_t));
+      sde->last_time = vlib_time_now (vlib_mains[thread]);
+      sde->start_time = sde->last_time;
+    }
+
+  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,
+};
+/* *INDENT-ON* */
+
+void
+session_debug_init (void)
+{
+  vlib_thread_main_t *vtm = vlib_get_thread_main ();
+  session_dbg_main_t *sdm = &session_dbg_main;
+  u32 num_threads, thread;
+
+  num_threads = vtm->n_vlib_mains;
+
+  vec_validate_aligned (sdm->wrk, num_threads - 1, CLIB_CACHE_LINE_BYTES);
+  for (thread = 0; thread < num_threads; thread++)
+    {
+      clib_memset (&sdm->wrk[thread], 0, sizeof (session_dbg_evts_t));
+      sdm->wrk[thread].start_time = vlib_time_now (vlib_mains[thread]);
+    }
+}
+#else
+void
+session_debug_init (void)
+{
+}
+#endif
+
+void
+dump_thread_0_event_queue (void)
+{
+  session_main_t *smm = vnet_get_session_main ();
+  vlib_main_t *vm = &vlib_global_main;
+  u32 my_thread_index = vm->thread_index;
+  session_event_t _e, *e = &_e;
+  svm_msg_q_ring_t *ring;
+  session_t *s0;
+  svm_msg_q_msg_t *msg;
+  svm_msg_q_t *mq;
+  int i, index;
+
+  mq = smm->wrk[my_thread_index].vpp_event_queue;
+  index = mq->q->head;
+
+  for (i = 0; i < mq->q->cursize; i++)
+    {
+      msg = (svm_msg_q_msg_t *) (&mq->q->data[0] + mq->q->elsize * index);
+      ring = svm_msg_q_ring (mq, msg->ring_index);
+      clib_memcpy_fast (e, svm_msg_q_msg_data (mq, msg), ring->elsize);
+
+      switch (e->event_type)
+	{
+	case SESSION_IO_EVT_TX:
+	  s0 = session_get_if_valid (e->session_index, my_thread_index);
+	  fformat (stdout, "[%04d] TX session %d\n", i, s0->session_index);
+	  break;
+
+	case SESSION_CTRL_EVT_CLOSE:
+	  s0 = session_get_from_handle (e->session_handle);
+	  fformat (stdout, "[%04d] disconnect session %d\n", i,
+		   s0->session_index);
+	  break;
+
+	case SESSION_IO_EVT_BUILTIN_RX:
+	  s0 = session_get_if_valid (e->session_index, my_thread_index);
+	  fformat (stdout, "[%04d] builtin_rx %d\n", i, s0->session_index);
+	  break;
+
+	case SESSION_CTRL_EVT_RPC:
+	  fformat (stdout, "[%04d] RPC call %llx with %llx\n",
+		   i, (u64) (uword) (e->rpc_args.fp),
+		   (u64) (uword) (e->rpc_args.arg));
+	  break;
+
+	default:
+	  fformat (stdout, "[%04d] unhandled event type %d\n",
+		   i, e->event_type);
+	  break;
+	}
+
+      index++;
+
+      if (index == mq->q->maxsize)
+	index = 0;
+    }
+}
+
+static u8
+session_node_cmp_event (session_event_t * e, svm_fifo_t * f)
+{
+  session_t *s;
+  switch (e->event_type)
+    {
+    case SESSION_IO_EVT_RX:
+    case SESSION_IO_EVT_TX:
+    case SESSION_IO_EVT_BUILTIN_RX:
+    case SESSION_IO_EVT_BUILTIN_TX:
+    case SESSION_IO_EVT_TX_FLUSH:
+      if (e->session_index == f->master_session_index)
+	return 1;
+      break;
+    case SESSION_CTRL_EVT_CLOSE:
+      break;
+    case SESSION_CTRL_EVT_RPC:
+      s = session_get_from_handle (e->session_handle);
+      if (!s)
+	{
+	  clib_warning ("session has event but doesn't exist!");
+	  break;
+	}
+      if (s->rx_fifo == f || s->tx_fifo == f)
+	return 1;
+      break;
+    default:
+      break;
+    }
+  return 0;
+}
+
+u8
+session_node_lookup_fifo_event (svm_fifo_t * f, session_event_t * e)
+{
+  session_evt_elt_t *elt;
+  session_worker_t *wrk;
+  int i, index, found = 0;
+  svm_msg_q_msg_t *msg;
+  svm_msg_q_ring_t *ring;
+  svm_msg_q_t *mq;
+  u8 thread_index;
+
+  ASSERT (e);
+  thread_index = f->master_thread_index;
+  wrk = session_main_get_worker (thread_index);
+
+  /*
+   * Search evt queue
+   */
+  mq = wrk->vpp_event_queue;
+  index = mq->q->head;
+  for (i = 0; i < mq->q->cursize; i++)
+    {
+      msg = (svm_msg_q_msg_t *) (&mq->q->data[0] + mq->q->elsize * index);
+      ring = svm_msg_q_ring (mq, msg->ring_index);
+      clib_memcpy_fast (e, svm_msg_q_msg_data (mq, msg), ring->elsize);
+      found = session_node_cmp_event (e, f);
+      if (found)
+	return 1;
+      index = (index + 1) % mq->q->maxsize;
+    }
+  /*
+   * Search pending events vector
+   */
+
+  /* *INDENT-OFF* */
+  clib_llist_foreach (wrk->event_elts, evt_list,
+                      pool_elt_at_index (wrk->event_elts, wrk->new_head),
+                      elt, ({
+    found = session_node_cmp_event (&elt->evt, f);
+    if (found)
+      {
+	clib_memcpy_fast (e, &elt->evt, sizeof (*e));
+	goto done;
+      }
+  }));
+  /* *INDENT-ON* */
+
+  /* *INDENT-OFF* */
+  clib_llist_foreach (wrk->event_elts, evt_list,
+                      pool_elt_at_index (wrk->event_elts, wrk->old_head),
+                      elt, ({
+    found = session_node_cmp_event (&elt->evt, f);
+    if (found)
+      {
+	clib_memcpy_fast (e, &elt->evt, sizeof (*e));
+	goto done;
+      }
+  }));
+  /* *INDENT-ON* */
+
+done:
+  return found;
+}
+
+/*
+ * fd.io coding-style-patch-verification: ON
+ *
+ * Local Variables:
+ * eval: (c-set-style "gnu")
+ * End:
+ */
diff --git a/src/vnet/session/session_debug.h b/src/vnet/session/session_debug.h
index 6140466998a..a42d90d471c 100644
--- a/src/vnet/session/session_debug.h
+++ b/src/vnet/session/session_debug.h
@@ -18,18 +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_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, "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
 {
@@ -38,29 +38,28 @@ 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") 	          	\
+#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")		\
-\
-_(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")                  \
+_(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")   \
-
+_(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
 {
@@ -83,8 +82,9 @@ 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 sess_dbg_evt_type[SESS_Q_MAX_EVT_TYPES];
+  session_dbg_counter_t counters[SESS_Q_MAX_EVT_TYPES];
 } session_dbg_evts_t;
 
 typedef struct session_dbg_main_
@@ -189,7 +189,7 @@ extern session_dbg_main_t session_dbg_main;
                 * 1000000.0;						\
 }
 #else
-#define SESSION_EVT_DEQ_NODE_HANDLER(_node_evt, _ntx)
+#define SESSION_EVT_DEQ_NODE_HANDLER(_wrk, _node_evt, _ntx)
 #endif /* SESSION_DISPATCH_DBG */
 
 #if SESSION_EVT_POLL_DBG && SESSION_DEBUG > 1
@@ -238,79 +238,86 @@ extern session_dbg_main_t session_dbg_main;
 #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;       		\
+  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 *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_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 *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;		\
+  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 *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;		\
+  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 *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;		\
+  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);                                      \
-  f64 diff = time_now - session_dbg_main.wrk[_wrk->vm->thread_index].last_time; \
+  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_CLOCKS_HANDLER(_node_evt, _wrk)
+#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) 	 \
+#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;     	\
+	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_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 ;     \
+#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, _wrk)
+#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_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);				\
-  session_dbg_main.wrk[_wrk->vm->thread_index].                         \
-	sess_dbg_evt_type[SESS_Q_##NODE_CALL_CNT].u64 +=1;              \
+  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 = vlib_time_now (_wrk->vm);			\
+  _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
@@ -322,6 +329,8 @@ extern session_dbg_main_t session_dbg_main;
 #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
diff --git a/src/vnet/session/session_node.c b/src/vnet/session/session_node.c
index 867ff4fcaf7..0f5030b4d31 100644
--- a/src/vnet/session/session_node.c
+++ b/src/vnet/session/session_node.c
@@ -1317,7 +1317,7 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node,
   session_evt_elt_t *elt, *ctrl_he, *new_he, *old_he;
   clib_llist_index_t ei, next_ei, old_ti;
   svm_msg_q_msg_t _msg, *msg = &_msg;
-  int i, n_tx_packets;
+  int i = 0, n_tx_packets;
   session_event_t *evt;
   svm_msg_q_t *mq;
 
@@ -1351,9 +1351,10 @@ 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);
     }
 
+  SESSION_EVT (SESSION_EVT_DSP_CNTRS, MQ_DEQ, wrk, n_to_dequeue, !i);
+
   /*
    * Handle control events
    */
@@ -1440,161 +1441,6 @@ VLIB_REGISTER_NODE (session_queue_node) =
 };
 /* *INDENT-ON* */
 
-void
-dump_thread_0_event_queue (void)
-{
-  session_main_t *smm = vnet_get_session_main ();
-  vlib_main_t *vm = &vlib_global_main;
-  u32 my_thread_index = vm->thread_index;
-  session_event_t _e, *e = &_e;
-  svm_msg_q_ring_t *ring;
-  session_t *s0;
-  svm_msg_q_msg_t *msg;
-  svm_msg_q_t *mq;
-  int i, index;
-
-  mq = smm->wrk[my_thread_index].vpp_event_queue;
-  index = mq->q->head;
-
-  for (i = 0; i < mq->q->cursize; i++)
-    {
-      msg = (svm_msg_q_msg_t *) (&mq->q->data[0] + mq->q->elsize * index);
-      ring = svm_msg_q_ring (mq, msg->ring_index);
-      clib_memcpy_fast (e, svm_msg_q_msg_data (mq, msg), ring->elsize);
-
-      switch (e->event_type)
-	{
-	case SESSION_IO_EVT_TX:
-	  s0 = session_event_get_session (e, my_thread_index);
-	  fformat (stdout, "[%04d] TX session %d\n", i, s0->session_index);
-	  break;
-
-	case SESSION_CTRL_EVT_CLOSE:
-	  s0 = session_get_from_handle (e->session_handle);
-	  fformat (stdout, "[%04d] disconnect session %d\n", i,
-		   s0->session_index);
-	  break;
-
-	case SESSION_IO_EVT_BUILTIN_RX:
-	  s0 = session_event_get_session (e, my_thread_index);
-	  fformat (stdout, "[%04d] builtin_rx %d\n", i, s0->session_index);
-	  break;
-
-	case SESSION_CTRL_EVT_RPC:
-	  fformat (stdout, "[%04d] RPC call %llx with %llx\n",
-		   i, (u64) (uword) (e->rpc_args.fp),
-		   (u64) (uword) (e->rpc_args.arg));
-	  break;
-
-	default:
-	  fformat (stdout, "[%04d] unhandled event type %d\n",
-		   i, e->event_type);
-	  break;
-	}
-
-      index++;
-
-      if (index == mq->q->maxsize)
-	index = 0;
-    }
-}
-
-static u8
-session_node_cmp_event (session_event_t * e, svm_fifo_t * f)
-{
-  session_t *s;
-  switch (e->event_type)
-    {
-    case SESSION_IO_EVT_RX:
-    case SESSION_IO_EVT_TX:
-    case SESSION_IO_EVT_BUILTIN_RX:
-    case SESSION_IO_EVT_BUILTIN_TX:
-    case SESSION_IO_EVT_TX_FLUSH:
-      if (e->session_index == f->master_session_index)
-	return 1;
-      break;
-    case SESSION_CTRL_EVT_CLOSE:
-      break;
-    case SESSION_CTRL_EVT_RPC:
-      s = session_get_from_handle (e->session_handle);
-      if (!s)
-	{
-	  clib_warning ("session has event but doesn't exist!");
-	  break;
-	}
-      if (s->rx_fifo == f || s->tx_fifo == f)
-	return 1;
-      break;
-    default:
-      break;
-    }
-  return 0;
-}
-
-u8
-session_node_lookup_fifo_event (svm_fifo_t * f, session_event_t * e)
-{
-  session_evt_elt_t *elt;
-  session_worker_t *wrk;
-  int i, index, found = 0;
-  svm_msg_q_msg_t *msg;
-  svm_msg_q_ring_t *ring;
-  svm_msg_q_t *mq;
-  u8 thread_index;
-
-  ASSERT (e);
-  thread_index = f->master_thread_index;
-  wrk = session_main_get_worker (thread_index);
-
-  /*
-   * Search evt queue
-   */
-  mq = wrk->vpp_event_queue;
-  index = mq->q->head;
-  for (i = 0; i < mq->q->cursize; i++)
-    {
-      msg = (svm_msg_q_msg_t *) (&mq->q->data[0] + mq->q->elsize * index);
-      ring = svm_msg_q_ring (mq, msg->ring_index);
-      clib_memcpy_fast (e, svm_msg_q_msg_data (mq, msg), ring->elsize);
-      found = session_node_cmp_event (e, f);
-      if (found)
-	return 1;
-      index = (index + 1) % mq->q->maxsize;
-    }
-  /*
-   * Search pending events vector
-   */
-
-  /* *INDENT-OFF* */
-  clib_llist_foreach (wrk->event_elts, evt_list,
-                      pool_elt_at_index (wrk->event_elts, wrk->new_head),
-                      elt, ({
-    found = session_node_cmp_event (&elt->evt, f);
-    if (found)
-      {
-	clib_memcpy_fast (e, &elt->evt, sizeof (*e));
-	goto done;
-      }
-  }));
-  /* *INDENT-ON* */
-
-  /* *INDENT-OFF* */
-  clib_llist_foreach (wrk->event_elts, evt_list,
-                      pool_elt_at_index (wrk->event_elts, wrk->old_head),
-                      elt, ({
-    found = session_node_cmp_event (&elt->evt, f);
-    if (found)
-      {
-	clib_memcpy_fast (e, &elt->evt, sizeof (*e));
-	goto done;
-      }
-  }));
-  /* *INDENT-ON* */
-
-done:
-  return found;
-}
-
 static clib_error_t *
 session_queue_exit (vlib_main_t * vm)
 {