vlib: barrier sync elog tracing improvements
[vpp.git] / src / vlib / threads.c
index bbe94c7..def8927 100644 (file)
@@ -24,7 +24,7 @@
 
 DECLARE_CJ_GLOBAL_LOG;
 
-#define FRAME_QUEUE_NELTS 32
+#define FRAME_QUEUE_NELTS 64
 
 u32
 vl (void *p)
@@ -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)
@@ -348,9 +260,13 @@ vlib_thread_init (vlib_main_t * vm)
     }
 
   /* grab cpu for main thread */
-  if (!tm->main_lcore)
+  if (tm->main_lcore == ~0)
     {
-      tm->main_lcore = clib_bitmap_first_set (avail_cpu);
+      /* if main-lcore is not set, we try to use lcore 1 */
+      if (clib_bitmap_get (avail_cpu, 1))
+       tm->main_lcore = 1;
+      else
+       tm->main_lcore = clib_bitmap_first_set (avail_cpu);
       if (tm->main_lcore == (u8) ~ 0)
        return clib_error_return (0, "no available cpus to be used for the"
                                  " main thread");
@@ -723,7 +639,6 @@ start_workers (vlib_main_t * vm)
   u32 n_vlib_mains = tm->n_vlib_mains;
   u32 worker_thread_index;
   u8 *main_heap = clib_mem_get_per_cpu_heap ();
-  mheap_t *main_heap_header = mheap_header (main_heap);
 
   vec_reset_length (vlib_worker_threads);
 
@@ -738,12 +653,6 @@ start_workers (vlib_main_t * vm)
       vlib_set_thread_name ((char *) w->name);
     }
 
-  /*
-   * Truth of the matter: we always use at least two
-   * threads. So, make the main heap thread-safe
-   * and make the event log thread-safe.
-   */
-  main_heap_header->flags |= MHEAP_FLAG_THREAD_SAFE;
   vm->elog_main.lock =
     clib_mem_alloc_aligned (CLIB_CACHE_LINE_BYTES, CLIB_CACHE_LINE_BYTES);
   vm->elog_main.lock[0] = 0;
@@ -797,9 +706,17 @@ start_workers (vlib_main_t * vm)
              vlib_node_t *n;
 
              vec_add2 (vlib_worker_threads, w, 1);
+             /* Currently unused, may not really work */
              if (tr->mheap_size)
-               w->thread_mheap =
-                 mheap_alloc (0 /* use VM */ , tr->mheap_size);
+               {
+#if USE_DLMALLOC == 0
+                 w->thread_mheap =
+                   mheap_alloc (0 /* use VM */ , tr->mheap_size);
+#else
+                 w->thread_mheap = create_mspace (tr->mheap_size,
+                                                  0 /* unlocked */ );
+#endif
+               }
              else
                w->thread_mheap = main_heap;
 
@@ -827,6 +744,8 @@ start_workers (vlib_main_t * vm)
 
              vm_clone->thread_index = worker_thread_index;
              vm_clone->heap_base = w->thread_mheap;
+             vm_clone->heap_aligned_base = (void *)
+               (((uword) w->thread_mheap) & ~(VLIB_FRAME_ALIGN - 1));
              vm_clone->init_functions_called =
                hash_create (0, /* value bytes */ 0);
              vm_clone->pending_rpc_requests = 0;
@@ -955,8 +874,15 @@ start_workers (vlib_main_t * vm)
            {
              vec_add2 (vlib_worker_threads, w, 1);
              if (tr->mheap_size)
-               w->thread_mheap =
-                 mheap_alloc (0 /* use VM */ , tr->mheap_size);
+               {
+#if USE_DLMALLOC == 0
+                 w->thread_mheap =
+                   mheap_alloc (0 /* use VM */ , tr->mheap_size);
+#else
+                 w->thread_mheap =
+                   create_mspace (tr->mheap_size, 0 /* locked */ );
+#endif
+               }
              else
                w->thread_mheap = main_heap;
              w->thread_stack =
@@ -1253,7 +1179,6 @@ cpu_config (vlib_main_t * vm, unformat_input_t * input)
   uword *p;
   vlib_thread_main_t *tm = &vlib_thread_main;
   u8 *name;
-  u64 coremask;
   uword *bitmap;
   u32 count;
 
@@ -1262,6 +1187,7 @@ cpu_config (vlib_main_t * vm, unformat_input_t * input)
   tm->n_thread_stacks = 1;     /* account for main thread */
   tm->sched_policy = ~0;
   tm->sched_priority = ~0;
+  tm->main_lcore = ~0;
 
   tr = tm->next;
 
@@ -1281,25 +1207,10 @@ cpu_config (vlib_main_t * vm, unformat_input_t * input)
        ;
       else if (unformat (input, "skip-cores %u", &tm->skip_cores))
        ;
-      else if (unformat (input, "coremask-%s %llx", &name, &coremask))
-       {
-         p = hash_get_mem (tm->thread_registrations_by_name, name);
-         if (p == 0)
-           return clib_error_return (0, "no such thread type '%s'", name);
-
-         tr = (vlib_thread_registration_t *) p[0];
-
-         if (tr->use_pthreads)
-           return clib_error_return (0,
-                                     "coremask cannot be set for '%s' threads",
-                                     name);
-
-         tr->coremask = clib_bitmap_set_multiple
-           (tr->coremask, 0, coremask, BITS (coremask));
-         tr->count = clib_bitmap_count_set_bits (tr->coremask);
-       }
-      else if (unformat (input, "corelist-%s %U", &name, unformat_bitmap_list,
-                        &bitmap))
+      else if (unformat (input, "coremask-%s %U", &name,
+                        unformat_bitmap_mask, &bitmap) ||
+              unformat (input, "corelist-%s %U", &name,
+                        unformat_bitmap_list, &bitmap))
        {
          p = hash_get_mem (tm->thread_registrations_by_name, name);
          if (p == 0)
@@ -1467,9 +1378,21 @@ vlib_worker_thread_barrier_sync_int (vlib_main_t * vm)
 
   /* Enforce minimum barrier open time to minimize packet loss */
   ASSERT (vm->barrier_no_close_before <= (now + BARRIER_MINIMUM_OPEN_LIMIT));
-  while ((now = vlib_time_now (vm)) < vm->barrier_no_close_before)
-    ;
 
+  while (1)
+    {
+      now = vlib_time_now (vm);
+      /* Barrier hold-down timer expired? */
+      if (now >= vm->barrier_no_close_before)
+       break;
+      if ((vm->barrier_no_close_before - now)
+         > (2.0 * BARRIER_MINIMUM_OPEN_LIMIT))
+       {
+         clib_warning ("clock change: would have waited for %.4f seconds",
+                       (vm->barrier_no_close_before - now));
+         break;
+       }
+    }
   /* Record time of closure */
   t_open = now - vm->barrier_epoch;
   vm->barrier_epoch = now;
@@ -1492,6 +1415,18 @@ vlib_worker_thread_barrier_sync_int (vlib_main_t * vm)
 
 }
 
+void vlib_stat_segment_lock (void) __attribute__ ((weak));
+void
+vlib_stat_segment_lock (void)
+{
+}
+
+void vlib_stat_segment_unlock (void) __attribute__ ((weak));
+void
+vlib_stat_segment_unlock (void)
+{
+}
+
 void
 vlib_worker_thread_barrier_release (vlib_main_t * vm)
 {
@@ -1521,6 +1456,13 @@ vlib_worker_thread_barrier_release (vlib_main_t * vm)
   /* Update (all) node runtimes before releasing the barrier, if needed */
   if (vm->need_vlib_worker_thread_node_runtime_update)
     {
+      /*
+       * Lock stat segment here, so we's safe when
+       * rebuilding the stat segment node clones from the
+       * stat thread...
+       */
+      vlib_stat_segment_lock ();
+
       /* Do stats elements on main thread */
       worker_thread_node_runtime_update_internal ();
       vm->need_vlib_worker_thread_node_runtime_update = 0;
@@ -1562,6 +1504,7 @@ vlib_worker_thread_barrier_release (vlib_main_t * vm)
              os_panic ();
            }
        }
+      vlib_stat_segment_unlock ();
     }
 
   t_closed_total = now - vm->barrier_epoch;
@@ -1760,16 +1703,29 @@ vlib_frame_queue_main_init (u32 node_index, u32 frame_queue_nelts)
   if (frame_queue_nelts == 0)
     frame_queue_nelts = FRAME_QUEUE_NELTS;
 
+  ASSERT (frame_queue_nelts >= 8);
+
   vec_add2 (tm->frame_queue_mains, fqm, 1);
 
   fqm->node_index = node_index;
+  fqm->frame_queue_nelts = frame_queue_nelts;
+  fqm->queue_hi_thresh = frame_queue_nelts - 2;
 
   vec_validate (fqm->vlib_frame_queues, tm->n_vlib_mains - 1);
+  vec_validate (fqm->per_thread_data, tm->n_vlib_mains - 1);
   _vec_len (fqm->vlib_frame_queues) = 0;
   for (i = 0; i < tm->n_vlib_mains; i++)
     {
+      vlib_frame_queue_per_thread_data_t *ptd;
       fq = vlib_frame_queue_alloc (frame_queue_nelts);
       vec_add1 (fqm->vlib_frame_queues, fq);
+
+      ptd = vec_elt_at_index (fqm->per_thread_data, i);
+      vec_validate (ptd->handoff_queue_elt_by_thread_index,
+                   tm->n_vlib_mains - 1);
+      vec_validate_init_empty (ptd->congested_handoff_queue_by_thread_index,
+                              tm->n_vlib_mains - 1,
+                              (vlib_frame_queue_t *) (~0));
     }
 
   return (fqm - tm->frame_queue_mains);