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>

1 files changed, 68 insertions, 24 deletions

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);
+	}
     }
 }