vlib: add elog events for vlib log entries

Pretty interesting to see how long plugins take to load.

Type: improvement

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

src/vlib/log.c

@@ -18,12 +18,14 @@
 #include <vlib/log.h>
 #include <vlib/unix/unix.h>
 #include <syslog.h>
+#include <vppinfra/elog.h>
 
 vlib_log_main_t log_main = {
   .default_log_level = VLIB_LOG_LEVEL_NOTICE,
   .default_syslog_log_level = VLIB_LOG_LEVEL_WARNING,
   .unthrottle_time = 3,
   .size = 512,
+  .add_to_elog = 1,
   .default_rate_limit = 50,
 };
 
@@ -222,6 +224,36 @@ vlib_log (vlib_log_level_t level, vlib_log_class_t class, char *fmt, ...)
       e->timestamp = t;
       s = 0;
 
+      if (lm->add_to_elog)
+	{
+          /* *INDENT-OFF* */
+          ELOG_TYPE_DECLARE(ee) =
+            {
+             .format = "log-%s: %s",
+             .format_args = "t4T4",
+             .n_enum_strings = 9,
+             .enum_strings = {
+                "emerg",
+                "alert",
+                "crit",
+                "err",
+                "warn",
+                "notice",
+                "info",
+                "debug",
+                "disabled",
+                },
+            };
+          struct {
+            u32 log_level;
+            u32 string_index;
+          } *ed;
+          /* *INDENT-ON* */
+	  ed = ELOG_DATA (&vm->elog_main, ee);
+	  ed->log_level = level;
+	  ed->string_index = elog_string (&vm->elog_main, (char *) e->string);
+	}
+
       lm->next = (lm->next + 1) % lm->size;
       if (lm->size > lm->count)
 	lm->count++;
@@ -822,6 +854,8 @@ log_config (vlib_main_t * vm, unformat_input_t * input)
 			 unformat_vlib_log_level,
 			 &lm->default_syslog_log_level))
 	;
+      else if (unformat (input, "add-to-elog"))
+	lm->add_to_elog = 1;
       else if (unformat (input, "class %s %U", &class,
 			 unformat_vlib_cli_sub_input, &sub_input))
 	{

src/vlib/log.h

@@ -108,6 +108,7 @@ typedef struct
   /* config */
   vlib_log_class_config_t *configs;
   uword *config_index_by_name;
+  int add_to_elog;
 
   /* registrations */
   vlib_log_class_registration_t *registrations;

src/vlib/main.c

@@ -823,8 +823,8 @@ VLIB_CLI_COMMAND (elog_restart_cli, static) = {
 /* *INDENT-ON* */
 
 static clib_error_t *
-elog_resize (vlib_main_t * vm,
-	     unformat_input_t * input, vlib_cli_command_t * cmd)
+elog_resize_command_fn (vlib_main_t * vm,
+			unformat_input_t * input, vlib_cli_command_t * cmd)
 {
   elog_main_t *em = &vm->elog_main;
   u32 tmp;
@@ -848,7 +848,7 @@ elog_resize (vlib_main_t * vm,
 VLIB_CLI_COMMAND (elog_resize_cli, static) = {
   .path = "event-logger resize",
   .short_help = "event-logger resize <nnn>",
-  .function = elog_resize,
+  .function = elog_resize_command_fn,
 };
 /* *INDENT-ON* */
 
@@ -2051,8 +2051,9 @@ vlib_main_configure (vlib_main_t * vm, unformat_input_t * input)
 	turn_on_mem_trace = 1;
 
       else if (unformat (input, "elog-events %d",
-			 &vm->elog_main.event_ring_size))
-	;
+			 &vm->configured_elog_ring_size))
+	vm->configured_elog_ring_size =
+	  1 << max_log2 (vm->configured_elog_ring_size);
       else if (unformat (input, "elog-post-mortem-dump"))
 	vm->elog_post_mortem_dump = 1;
       else if (unformat (input, "buffer-alloc-success-rate %f",
@@ -2133,11 +2134,10 @@ vlib_main (vlib_main_t * volatile vm, unformat_input_t * input)
 
   vm->queue_signal_callback = placeholder_queue_signal_callback;
 
-  /* Turn on event log. */
-  if (!vm->elog_main.event_ring_size)
-    vm->elog_main.event_ring_size = 128 << 10;
-  elog_init (&vm->elog_main, vm->elog_main.event_ring_size);
-  elog_enable_disable (&vm->elog_main, 1);
+  /* Reconfigure event log which is enabled very early */
+  if (vm->configured_elog_ring_size &&
+      vm->configured_elog_ring_size != vm->elog_main.event_ring_size)
+    elog_resize (&vm->elog_main, vm->configured_elog_ring_size);
   vl_api_set_elog_main (&vm->elog_main);
   (void) vl_api_set_elog_trace_api_messages (1);
 

src/vlib/main.h

@@ -223,6 +223,7 @@ typedef struct vlib_main_t
 
   /* Event logger. */
   elog_main_t elog_main;
+  u32 configured_elog_ring_size;
 
   /* Event logger trace flags */
   int elog_trace_api_messages;

src/vlib/unix/main.c

@@ -706,6 +706,11 @@ vlib_unix_main (int argc, char *argv[])
 
   clib_time_init (&vm->clib_time);
 
+  /* Turn on the event logger at the first possible moment */
+  vm->configured_elog_ring_size = 128 << 10;
+  elog_init (&vm->elog_main, vm->configured_elog_ring_size);
+  elog_enable_disable (&vm->elog_main, 1);
+
   unformat_init_command_line (&input, (char **) vm->argv);
   if ((e = vlib_plugin_config (vm, &input)))
     {

src/vppinfra/elog.c

@@ -484,18 +484,29 @@ elog_nsec_per_clock (elog_main_t * em)
 					    &em->init_time));
 }
 
-__clib_export void
-elog_alloc (elog_main_t * em, u32 n_events)
+static void
+elog_alloc_internal (elog_main_t * em, u32 n_events, int free_ring)
 {
-  if (em->event_ring)
+  if (free_ring && em->event_ring)
     vec_free (em->event_ring);
 
   /* Ring size must be a power of 2. */
   em->event_ring_size = n_events = max_pow2 (n_events);
 
-  /* Leave an empty ievent at end so we can always speculatively write
-     and event there (possibly a long form event). */
-  vec_resize_aligned (em->event_ring, n_events, CLIB_CACHE_LINE_BYTES);
+  vec_validate_aligned (em->event_ring, n_events, CLIB_CACHE_LINE_BYTES);
+  _vec_len (em->event_ring) = n_events;
+}
+
+__clib_export void
+elog_alloc (elog_main_t * em, u32 n_events)
+{
+  elog_alloc_internal (em, n_events, 1 /* free ring */ );
+}
+
+__clib_export void
+elog_resize (elog_main_t * em, u32 n_events)
+{
+  elog_alloc_internal (em, n_events, 0 /* do not free ring */ );
 }
 
 __clib_export void

src/vppinfra/elog.h

@@ -526,6 +526,7 @@ void unserialize_elog_main (serialize_main_t * m, va_list * va);
 
 void elog_init (elog_main_t * em, u32 n_events);
 void elog_alloc (elog_main_t * em, u32 n_events);
+void elog_resize (elog_main_t * em, u32 n_events);
 
 #ifdef CLIB_UNIX
 always_inline clib_error_t *