session: improve event logging

Type:feature

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

diff --git a/src/vnet/session/session.c b/src/vnet/session/session.c
index 9769c01..4e34068 100644 (file)
--- a/src/vnet/session/session.c
+++ b/src/vnet/session/session.c
@@ -176,7 +176,7 @@ session_free (session_t * s)
       pool_put (session_main.wrk[thread_index].sessions, s);
       return;
     }
-  SESSION_EVT_DBG (SESSION_EVT_FREE, s);
+  SESSION_EVT (SESSION_EVT_FREE, s);
   pool_put (session_main.wrk[s->thread_index].sessions, s);
 }
 
@@ -518,12 +518,7 @@ session_enqueue_notify_inline (session_t * s)
       return 0;
     }
 
-  /* *INDENT-OFF* */
-  SESSION_EVT_DBG(SESSION_EVT_ENQ, s, ({
-      ed->data[0] = SESSION_IO_EVT_RX;
-      ed->data[1] = svm_fifo_max_dequeue_prod (s->rx_fifo);
-  }));
-  /* *INDENT-ON* */
+  SESSION_EVT (SESSION_EVT_ENQ, s, svm_fifo_max_dequeue_prod (s->rx_fifo));
 
   s->flags &= ~SESSION_F_RX_EVT;
   if (PREDICT_FALSE (app_worker_lock_and_send_event (app_wrk, s,
@@ -1393,10 +1388,6 @@ session_manager_main_enable (vlib_main_t * vm)
        clib_rwlock_init (&smm->wrk[i].peekers_rw_locks);
     }
 
-#if SESSION_DEBUG
-  vec_validate (smm->last_event_poll_by_thread, num_threads - 1);
-#endif
-
   /* Allocate vpp event queues segment and queue */
   session_vpp_event_queues_allocate (smm);
 

diff --git a/src/vnet/session/session.h b/src/vnet/session/session.h
index 73c6dc8..1e32291 100644 (file)
--- a/src/vnet/session/session.h
+++ b/src/vnet/session/session.h
@@ -113,6 +113,10 @@ typedef struct session_worker_
 
   u32 last_tx_packets;
 
+#if SESSION_DEBUG
+  /** last event poll time by thread */
+  f64 last_event_poll;
+#endif
 } session_worker_t;
 
 typedef int (session_fifo_rx_fn) (vlib_main_t * vm,
@@ -178,14 +182,6 @@ typedef struct session_main_
   /** Preallocate session config parameter */
   u32 preallocated_sessions;
 
-#if SESSION_DEBUG
-  /**
-   * last event poll time by thread
-   * Debug only. Will cause false cache-line sharing as-is
-   */
-  f64 *last_event_poll_by_thread;
-#endif
-
 } session_main_t;
 
 extern session_main_t session_main;

diff --git a/src/vnet/session/session_debug.h b/src/vnet/session/session_debug.h
index a26cd7f..228c1b3 100644 (file)
--- a/src/vnet/session/session_debug.h
+++ b/src/vnet/session/session_debug.h
@@ -24,6 +24,7 @@
   _(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")              \
 
@@ -35,7 +36,7 @@ typedef enum _session_evt_dbg
 } session_evt_dbg_e;
 
 #define SESSION_DEBUG 0 * (TRANSPORT_DEBUG > 0)
-#define SESSION_DEQ_NODE_EVTS (0)
+#define SESSION_DEQ_EVTS (0)
 #define SESSION_EVT_POLL_DBG (0)
 #define SESSION_SM (0)
 
@@ -74,27 +75,30 @@ 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;                                                  \
 }
 
 #define SESSION_EVT_DEQ_NODE_HANDLER(_node_evt)                                \
@@ -119,7 +123,7 @@ typedef enum _session_evt_dbg
 #endif /* SESSION_DEQ_NODE_EVTS */
 
 #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 +131,19 @@ 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) ((now - _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)            \
+  if (PREDICT_TRUE (smm->last_event_poll != 0.0))                      \
+    if (now > smm->last_event_poll + 500e-6)                           \
       SESSION_EVT_POLL_GAP(smm, _ti);                                  \
-  _smm->last_event_poll_by_thread[_ti] = now;                          \
+  _wrk->last_event_poll = now;                                         \
 }
 
-#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,23 +157,31 @@ 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)
 #endif /* SESSION_EVT_POLL_DBG */
 
-#define SESSION_EVT_DISPATCH_END_HANDLER(_smm, _ti)                    \
+#define SESSION_EVT_DISPATCH_START_HANDLER(_wrk)                       \
+{                                                                      \
+  if (SESSION_DEQ_EVTS > 1)                                            \
+    SESSION_EVT_DEQ_NODE_HANDLER (0);                                  \
+  SESSION_EVT_POLL_GAP_TRACK_HANDLER (wrk);                            \
+}
+
+#define SESSION_EVT_DISPATCH_END_HANDLER(_wrk, _ntx)                   \
 {                                                                      \
-  SESSION_EVT_DEQ_NODE_HANDLER(1);                                     \
-  SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_smm, _ti);                   \
+  if (SESSION_DEQ_EVTS > 1 || _ntx)                                    \
+    SESSION_EVT_DEQ_NODE_HANDLER (1);                                  \
+  SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk);                                \
 }
 
 #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 */
 

diff --git a/src/vnet/session/session_node.c b/src/vnet/session/session_node.c
index ca6663c..a847888 100644 (file)
--- a/src/vnet/session/session_node.c
+++ b/src/vnet/session/session_node.c
@@ -508,15 +508,6 @@ session_tx_fill_buffer (vlib_main_t * vm, session_tx_context_t * ctx,
    */
   if (PREDICT_FALSE (ctx->n_bufs_per_seg > 1 && ctx->left_to_snd))
     session_tx_fifo_chain_tail (vm, ctx, b, n_bufs, peek_data);
-
-  /* *INDENT-OFF* */
-  SESSION_EVT_DBG(SESSION_EVT_DEQ, ctx->s, ({
-       ed->data[0] = SESSION_IO_EVT_TX;
-       ed->data[1] = ctx->max_dequeue;
-       ed->data[2] = len_to_deq;
-       ed->data[3] = ctx->left_to_snd;
-  }));
-  /* *INDENT-ON* */
 }
 
 always_inline u8
@@ -777,6 +768,9 @@ session_tx_fifo_read_and_snd_i (vlib_main_t * vm, vlib_node_runtime_t * node,
   transport_connection_update_tx_stats (ctx->tc, ctx->max_len_to_snd);
   vlib_put_next_frame (vm, node, next_index, n_left_to_next);
 
+  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);
+
   /* If we couldn't dequeue all bytes mark as partially read */
   ASSERT (ctx->left_to_snd == 0);
   if (ctx->max_len_to_snd < ctx->max_dequeue)
@@ -865,7 +859,7 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node,
   svm_msg_q_t *mq;
   void (*fp) (void *);
 
-  SESSION_EVT_DBG (SESSION_EVT_POLL_GAP_TRACK, smm, thread_index);
+  SESSION_EVT (SESSION_EVT_DISPATCH_START, wrk);
 
   /*
    *  Update transport time
@@ -873,8 +867,6 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node,
   session_update_dispatch_period (wrk, now, thread_index);
   transport_update_time (now, thread_index);
 
-  SESSION_EVT_DBG (SESSION_EVT_DEQ_NODE, 0);
-
   /* Make sure postponed events are handled first */
   new_he = pool_elt_at_index (wrk->event_elts, wrk->new_head);
   new_te = clib_llist_prev (wrk->event_elts, evt_list, new_he);
@@ -1032,7 +1024,7 @@ session_queue_node_fn (vlib_main_t * vm, vlib_node_runtime_t * node,
   vlib_node_increment_counter (vm, session_queue_node.index,
                               SESSION_QUEUE_ERROR_TX, n_tx_packets);
 
-  SESSION_EVT_DBG (SESSION_EVT_DISPATCH_END, smm, thread_index);
+  SESSION_EVT (SESSION_EVT_DISPATCH_END, wrk, n_tx_packets);
 
   return n_tx_packets;
 }