vlib: barrier sync elog tracing improvements

Change-Id: I2d3b8d5a7192ff68bee443a99346ecb807b2d833
Signed-off-by: Damjan Marion <damarion@cisco.com>
Signed-off-by: Dave Barach <dave@barachs.net>

4 files changed, 114 insertions, 135 deletions

diff --git a/src/vlib/threads.c b/src/vlib/threads.c
index 1972886a78b..def8927e29f 100644
--- a/src/vlib/threads.c
+++ b/src/vlib/threads.c
@@ -42,11 +42,6 @@ vlib_thread_main_t vlib_thread_main;
  * imapacts observed timings.
  */
 
-#ifdef BARRIER_TRACING
- /*
-  * Output of barrier tracing can be to syslog or elog as suits
-  */
-#ifdef BARRIER_TRACING_ELOG
 static u32
 elog_id_for_msg_name (const char *msg_name)
 {
@@ -69,24 +64,22 @@ elog_id_for_msg_name (const char *msg_name)
   return r;
 }
 
-  /*
-   * elog Barrier trace functions, which are nulled out if BARRIER_TRACING isn't
-   * defined
-   */
-
 static inline void
 barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed)
 {
+  if (!vlib_worker_threads->barrier_elog_enabled)
+    return;
+
     /* *INDENT-OFF* */
     ELOG_TYPE_DECLARE (e) =
       {
-        .format = "barrier <%d#%s(O:%dus:%dus)(%dus)",
-        .format_args = "i4T4i4i4i4",
+        .format = "bar-trace-%s-#%d",
+        .format_args = "T4i4",
       };
     /* *INDENT-ON* */
   struct
   {
-    u32 count, caller, t_entry, t_open, t_closed;
+    u32 caller, count, t_entry, t_open, t_closed;
   } *ed = 0;
 
   ed = ELOG_DATA (&vlib_global_main.elog_main, e);
@@ -100,57 +93,64 @@ barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed)
 static inline void
 barrier_trace_sync_rec (f64 t_entry)
 {
+  if (!vlib_worker_threads->barrier_elog_enabled)
+    return;
+
     /* *INDENT-OFF* */
     ELOG_TYPE_DECLARE (e) =
       {
-        .format = "barrier    <%d(%dus)%s",
-        .format_args = "i4i4T4",
+        .format = "bar-syncrec-%s-#%d",
+        .format_args = "T4i4",
       };
     /* *INDENT-ON* */
   struct
   {
-    u32 depth, t_entry, caller;
+    u32 caller, depth;
   } *ed = 0;
 
   ed = ELOG_DATA (&vlib_global_main.elog_main, e);
   ed->depth = (int) vlib_worker_threads[0].recursion_level - 1;
-  ed->t_entry = (int) (1000000.0 * t_entry);
   ed->caller = elog_id_for_msg_name (vlib_worker_threads[0].barrier_caller);
 }
 
 static inline void
 barrier_trace_release_rec (f64 t_entry)
 {
+  if (!vlib_worker_threads->barrier_elog_enabled)
+    return;
+
     /* *INDENT-OFF* */
     ELOG_TYPE_DECLARE (e) =
       {
-        .format = "barrier      (%dus)%d>",
-        .format_args = "i4i4",
+        .format = "bar-relrrec-#%d",
+        .format_args = "i4",
       };
     /* *INDENT-ON* */
   struct
   {
-    u32 t_entry, depth;
+    u32 depth;
   } *ed = 0;
 
   ed = ELOG_DATA (&vlib_global_main.elog_main, e);
-  ed->t_entry = (int) (1000000.0 * t_entry);
   ed->depth = (int) vlib_worker_threads[0].recursion_level;
 }
 
 static inline void
 barrier_trace_release (f64 t_entry, f64 t_closed_total, f64 t_update_main)
 {
+  if (!vlib_worker_threads->barrier_elog_enabled)
+    return;
+
     /* *INDENT-OFF* */
     ELOG_TYPE_DECLARE (e) =
       {
-        .format = "barrier   (%dus){%d}(C:%dus)#%d>",
+        .format = "bar-rel-#%d-e%d-u%d-t%d",
         .format_args = "i4i4i4i4",
       };
     /* *INDENT-ON* */
   struct
   {
-    u32 t_entry, t_update_main, t_closed_total, count;
+    u32 count, t_entry, t_update_main, t_closed_total;
   } *ed = 0;
 
   ed = ELOG_DATA (&vlib_global_main.elog_main, e);
@@ -162,94 +162,6 @@ barrier_trace_release (f64 t_entry, f64 t_closed_total, f64 t_update_main)
   /* Reset context for next trace */
   vlib_worker_threads[0].barrier_context = NULL;
 }
-#else
-char barrier_trace[65536];
-char *btp = barrier_trace;
-
-  /*
-   * syslog Barrier trace functions, which are nulled out if BARRIER_TRACING
-   * isn't defined
-   */
-
-
-static inline void
-barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed)
-{
-  btp += sprintf (btp, "<%u#%s",
-		  (unsigned int) vlib_worker_threads[0].barrier_sync_count,
-		  vlib_worker_threads[0].barrier_caller);
-
-  if (vlib_worker_threads[0].barrier_context)
-    {
-      btp += sprintf (btp, "[%s]", vlib_worker_threads[0].barrier_context);
-
-    }
-
-  btp += sprintf (btp, "(O:%dus:%dus)(%dus):",
-		  (int) (1000000.0 * t_entry),
-		  (int) (1000000.0 * t_open), (int) (1000000.0 * t_closed));
-
-}
-
-static inline void
-barrier_trace_sync_rec (f64 t_entry)
-{
-  btp += sprintf (btp, "<%u(%dus)%s:",
-		  (int) vlib_worker_threads[0].recursion_level - 1,
-		  (int) (1000000.0 * t_entry),
-		  vlib_worker_threads[0].barrier_caller);
-}
-
-static inline void
-barrier_trace_release_rec (f64 t_entry)
-{
-  btp += sprintf (btp, ":(%dus)%u>", (int) (1000000.0 * t_entry),
-		  (int) vlib_worker_threads[0].recursion_level);
-}
-
-static inline void
-barrier_trace_release (f64 t_entry, f64 t_closed_total, f64 t_update_main)
-{
-
-  btp += sprintf (btp, ":(%dus)", (int) (1000000.0 * t_entry));
-  if (t_update_main > 0)
-    {
-      btp += sprintf (btp, "{%dus}", (int) (1000000.0 * t_update_main));
-    }
-
-  btp += sprintf (btp, "(C:%dus)#%u>",
-		  (int) (1000000.0 * t_closed_total),
-		  (int) vlib_worker_threads[0].barrier_sync_count);
-
-  /* Dump buffer to syslog, and reset for next trace */
-  fformat (stderr, "BTRC %s\n", barrier_trace);
-  btp = barrier_trace;
-  vlib_worker_threads[0].barrier_context = NULL;
-}
-#endif
-#else
-
-  /* Null functions for default case where barrier tracing isn't used */
-static inline void
-barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed)
-{
-}
-
-static inline void
-barrier_trace_sync_rec (f64 t_entry)
-{
-}
-
-static inline void
-barrier_trace_release_rec (f64 t_entry)
-{
-}
-
-static inline void
-barrier_trace_release (f64 t_entry, f64 t_closed_total, f64 t_update_main)
-{
-}
-#endif
 
 uword
 os_get_nthreads (void)
diff --git a/src/vlib/threads.h b/src/vlib/threads.h
index 17944536b6c..7de0412362e 100644
--- a/src/vlib/threads.h
+++ b/src/vlib/threads.h
@@ -18,22 +18,6 @@
 #include <vlib/main.h>
 #include <linux/sched.h>
 
-/*
- * To enable detailed tracing of barrier usage, including call stacks and
- * timings, define BARRIER_TRACING here or in relevant TAGS.  If also used
- * with CLIB_DEBUG, timing will _not_ be representative of normal code
- * execution.
- *
- */
-
-// #define BARRIER_TRACING 1
-
-/*
- * Two options for barrier tracing output: syslog & elog.
- */
-
-// #define BARRIER_TRACING_ELOG 1
-
 extern vlib_main_t **vlib_mains;
 
 void vlib_set_thread_name (char *name);
@@ -118,10 +102,9 @@ typedef struct
   vlib_thread_registration_t *registration;
   u8 *name;
   u64 barrier_sync_count;
-#ifdef BARRIER_TRACING
+  u8 barrier_elog_enabled;
   const char *barrier_caller;
   const char *barrier_context;
-#endif
   volatile u32 *node_reforks_required;
 
   long lwp;
@@ -216,12 +199,7 @@ u32 vlib_frame_queue_main_init (u32 node_index, u32 frame_queue_nelts);
 #define BARRIER_SYNC_TIMEOUT (1.0)
 #endif
 
-#ifdef BARRIER_TRACING
 #define vlib_worker_thread_barrier_sync(X) {vlib_worker_threads[0].barrier_caller=__FUNCTION__;vlib_worker_thread_barrier_sync_int(X);}
-#else
-#define vlib_worker_thread_barrier_sync(X) vlib_worker_thread_barrier_sync_int(X)
-#endif
-
 
 void vlib_worker_thread_barrier_sync_int (vlib_main_t * vm);
 void vlib_worker_thread_barrier_release (vlib_main_t * vm);
@@ -410,7 +388,30 @@ vlib_worker_thread_barrier_check (void)
 {
   if (PREDICT_FALSE (*vlib_worker_threads->wait_at_barrier))
     {
-      vlib_main_t *vm;
+      vlib_main_t *vm = vlib_get_main ();
+      u32 thread_index = vm->thread_index;
+      f64 t = vlib_time_now (vm);
+
+      if (PREDICT_FALSE (vlib_worker_threads->barrier_elog_enabled))
+	{
+	  vlib_worker_thread_t *w = vlib_worker_threads + thread_index;
+	  /* *INDENT-OFF* */
+	  ELOG_TYPE_DECLARE (e) = {
+	    .format = "barrier-wait-thread-%d",
+	    .format_args = "i4",
+	  };
+	  /* *INDENT-ON* */
+
+	  struct
+	  {
+	    u32 thread_index;
+	  } __clib_packed *ed;
+
+	  ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main, e,
+				w->elog_track);
+	  ed->thread_index = thread_index;
+	}
+
       clib_smp_atomic_add (vlib_worker_threads->workers_at_barrier, 1);
       if (CLIB_DEBUG > 0)
 	{
@@ -425,12 +426,55 @@ vlib_worker_thread_barrier_check (void)
 
       if (PREDICT_FALSE (*vlib_worker_threads->node_reforks_required))
 	{
+	  if (PREDICT_FALSE (vlib_worker_threads->barrier_elog_enabled))
+	    {
+	      t = vlib_time_now (vm) - t;
+	      vlib_worker_thread_t *w = vlib_worker_threads + thread_index;
+              /* *INDENT-OFF* */
+              ELOG_TYPE_DECLARE (e) = {
+                .format = "barrier-refork-thread-%d",
+                .format_args = "i4",
+              };
+              /* *INDENT-ON* */
+
+	      struct
+	      {
+		u32 thread_index;
+	      } __clib_packed *ed;
+
+	      ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main, e,
+				    w->elog_track);
+	      ed->thread_index = thread_index;
+	    }
+
 	  vlib_worker_thread_node_refork ();
 	  clib_smp_atomic_add (vlib_worker_threads->node_reforks_required,
 			       -1);
 	  while (*vlib_worker_threads->node_reforks_required)
 	    ;
 	}
+      if (PREDICT_FALSE (vlib_worker_threads->barrier_elog_enabled))
+	{
+	  t = vlib_time_now (vm) - t;
+	  vlib_worker_thread_t *w = vlib_worker_threads + thread_index;
+	  /* *INDENT-OFF* */
+	  ELOG_TYPE_DECLARE (e) = {
+	    .format = "barrier-released-thread-%d: %dus",
+	    .format_args = "i4i4",
+	  };
+	  /* *INDENT-ON* */
+
+	  struct
+	  {
+	    u32 thread_index;
+	    u32 duration;
+	  } __clib_packed *ed;
+
+	  ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main, e,
+				w->elog_track);
+	  ed->thread_index = thread_index;
+	  ed->duration = (int) (1000000.0 * t);
+	}
     }
 }
 
diff --git a/src/vlib/threads_cli.c b/src/vlib/threads_cli.c
index 02bdea5cb0f..bb9ddbc6e3c 100644
--- a/src/vlib/threads_cli.c
+++ b/src/vlib/threads_cli.c
@@ -574,6 +574,28 @@ VLIB_CLI_COMMAND (cmd_test_frame_queue_threshold,static) = {
 };
 /* *INDENT-ON* */
 
+static clib_error_t *
+test_threads_barrier_elog_command_fn (vlib_main_t * vm,
+				      unformat_input_t * input,
+				      vlib_cli_command_t * cmd)
+{
+  if (unformat (input, "enable"))
+    vlib_worker_threads->barrier_elog_enabled = 1;
+  else if (unformat (input, "disable"))
+    vlib_worker_threads->barrier_elog_enabled = 0;
+  else
+    return clib_error_return (0, "please choose enable or disable");
+  return 0;
+}
+
+/* *INDENT-OFF* */
+VLIB_CLI_COMMAND (test_elog_vector_length_trigger, static) =
+{
+  .path = "test threads barrier-elog",
+  .short_help = "test threads barrier-elog",
+  .function = test_threads_barrier_elog_command_fn,
+};
+/* *INDENT-ON* */
 
 /*
  * fd.io coding-style-patch-verification: ON
diff --git a/src/vpp/api/api_main.c b/src/vpp/api/api_main.c
index 0e05d3ed78e..8f33f042c5d 100644
--- a/src/vpp/api/api_main.c
+++ b/src/vpp/api/api_main.c
@@ -229,6 +229,7 @@ VLIB_CLI_COMMAND (api_command, static) =
   .path = "binary-api",
   .short_help = "binary-api [help] <name> [<args>]",
   .function = api_command_fn,
+  .is_mp_safe = 1,
 };
 /* *INDENT-ON* */