Improve main-loop event-logs

Change-Id: I984debeffe0dce36c9e7ab963f25d862cc7550cc
Signed-off-by: Dave Barach <dave@barachs.net>

4 files changed, 42 insertions, 15 deletions

diff --git a/vlib/vlib/main.c b/vlib/vlib/main.c
index 2ea91a91657..fe9a7da8243 100644
--- a/vlib/vlib/main.c
+++ b/vlib/vlib/main.c
@@ -46,9 +46,6 @@
 
 CJ_GLOBAL_LOG_PROTOTYPE;
 
-
-//#define VLIB_ELOG_MAIN_LOOP 1
-
 /* Actually allocate a few extra slots of vector data to support
    speculative vector enqueues which overflow vector data in next frame. */
 #define VLIB_FRAME_SIZE_ALLOC (VLIB_FRAME_SIZE + 4)
@@ -779,22 +776,26 @@ void vlib_gdb_show_event_log (void)
   elog_show_buffer_internal (vlib_get_main(), (u32)~0);
 }
 
-always_inline void
+static inline void
 vlib_elog_main_loop_event (vlib_main_t * vm,
 			   u32 node_index,
 			   u64 time,
 			   u32 n_vectors,
 			   u32 is_return)
 {
-  elog_main_t * em = &vm->elog_main;
+  vlib_main_t * evm = &vlib_global_main;
+  elog_main_t * em = &evm->elog_main;
 
-  if (VLIB_ELOG_MAIN_LOOP)
-    elog (em,
+  if (VLIB_ELOG_MAIN_LOOP && n_vectors)
+    elog_track (em,
 	  /* event type */
 	  vec_elt_at_index (is_return
-			    ? vm->node_return_elog_event_types
-			    : vm->node_call_elog_event_types,
+			    ? evm->node_return_elog_event_types
+			    : evm->node_call_elog_event_types,
 			    node_index),
+          /* track */
+          (vm->cpu_index ? &vlib_worker_threads[vm->cpu_index].elog_track :
+           &em->default_track),
 	  /* data to log */ n_vectors);
 }
 
diff --git a/vlib/vlib/node.c b/vlib/vlib/node.c
index 66a2d09fdb8..40ef7c71a51 100644
--- a/vlib/vlib/node.c
+++ b/vlib/vlib/node.c
@@ -61,13 +61,13 @@ static void node_set_elog_name (vlib_main_t * vm, uword node_index)
 
   t = vec_elt_at_index (vm->node_call_elog_event_types, node_index);
   vec_free (t->format);
-  t->format = (char *) format (0, "%v (%%d)", n->name);
+  t->format = (char *) format (0, "%v-call: %%d%c", n->name, 0);
 
   t = vec_elt_at_index (vm->node_return_elog_event_types, node_index);
   vec_free (t->format);
-  t->format = (char *) format (0, "%v () = %%d", n->name);
+  t->format = (char *) format (0, "%v-return: %%d%c", n->name, 0);
 
-  n->name_elog_string = elog_string (&vm->elog_main, "%v", n->name);
+  n->name_elog_string = elog_string (&vm->elog_main, "%v%c", n->name,0);
 }
 
 void vlib_node_rename (vlib_main_t * vm, u32 node_index, char * fmt, ...)
diff --git a/vppinfra/vppinfra/elog.c b/vppinfra/vppinfra/elog.c
index 3c327481141..222c55fd63e 100644
--- a/vppinfra/vppinfra/elog.c
+++ b/vppinfra/vppinfra/elog.c
@@ -52,7 +52,10 @@ static inline void elog_lock (elog_main_t * em)
 static inline void elog_unlock (elog_main_t * em)
 {
   if (PREDICT_FALSE(em->lock != 0))
-    *em->lock = 0;
+    {
+      CLIB_MEMORY_BARRIER();
+      *em->lock = 0;
+    }
 }
 
 /* Non-inline version. */
@@ -168,7 +171,6 @@ word elog_event_type_register (elog_main_t * em, elog_event_type_t * t)
   }
 
   new_event_type (em, l);
-  
   elog_unlock(em);
 
   return l;
diff --git a/vppinfra/vppinfra/elog.h b/vppinfra/vppinfra/elog.h
index 8c5482ae284..db84c95f7ca 100644
--- a/vppinfra/vppinfra/elog.h
+++ b/vppinfra/vppinfra/elog.h
@@ -273,7 +273,7 @@ elog_event_data_not_inline (elog_main_t * em,
   return elog_event_data (em, type, track, cpu_time);
 }
 
-/* Most common form: log a single 32 bit datum. */
+/* Most common forms: log a single 32 bit datum, w / w-out track */
 always_inline void
 elog (elog_main_t * em, elog_event_type_t * type, u32 data)
 {
@@ -297,6 +297,30 @@ elog_inline (elog_main_t * em, elog_event_type_t * type, u32 data)
   d[0] = data;
 }
 
+always_inline void
+elog_track (elog_main_t * em, elog_event_type_t * type, elog_track_t *track, 
+            u32 data)
+{
+  u32 * d = elog_event_data_not_inline
+    (em,
+     type,
+     track,
+     clib_cpu_time_now ());
+  d[0] = data;
+}
+
+always_inline void
+elog_track_inline (elog_main_t * em, elog_event_type_t * type, 
+                   elog_track_t *track, u32 data)
+{
+  u32 * d = elog_event_data_inline
+    (em,
+     type,
+     track,
+     clib_cpu_time_now ());
+  d[0] = data;
+}
+
 always_inline void *
 elog_data (elog_main_t * em, elog_event_type_t * type, elog_track_t * track)
 {