From bc867c3d2137dab4b1395196c1936233517980ab Mon Sep 17 00:00:00 2001 From: Dave Barach Date: Wed, 25 Nov 2020 10:07:09 -0500 Subject: 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 Change-Id: If496eb73b2e1fd9dd714142cd5195fa7ccd93ebd --- src/vlib/log.c | 34 ++++++++++++++++++++++++++++++++++ src/vlib/log.h | 1 + src/vlib/main.c | 20 ++++++++++---------- src/vlib/main.h | 1 + src/vlib/unix/main.c | 5 +++++ src/vppinfra/elog.c | 23 +++++++++++++++++------ src/vppinfra/elog.h | 1 + 7 files changed, 69 insertions(+), 16 deletions(-) diff --git a/src/vlib/log.c b/src/vlib/log.c index e1ab036b25c..bd456aeafe9 100644 --- a/src/vlib/log.c +++ b/src/vlib/log.c @@ -18,12 +18,14 @@ #include #include #include +#include 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)) { diff --git a/src/vlib/log.h b/src/vlib/log.h index 75bdceb806e..a94c57a51eb 100644 --- a/src/vlib/log.h +++ b/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; diff --git a/src/vlib/main.c b/src/vlib/main.c index f1de9090612..27cbcb0df18 100644 --- a/src/vlib/main.c +++ b/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 ", - .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); diff --git a/src/vlib/main.h b/src/vlib/main.h index c420d5f9d28..766c9ec3756 100644 --- a/src/vlib/main.h +++ b/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; diff --git a/src/vlib/unix/main.c b/src/vlib/unix/main.c index 2f1b6ecdae0..e86d421056c 100644 --- a/src/vlib/unix/main.c +++ b/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))) { diff --git a/src/vppinfra/elog.c b/src/vppinfra/elog.c index 6fa44cb82f9..423d8d5ba15 100644 --- a/src/vppinfra/elog.c +++ b/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 diff --git a/src/vppinfra/elog.h b/src/vppinfra/elog.h index 93ba4f5e8cc..d0825bdd5b2 100644 --- a/src/vppinfra/elog.h +++ b/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 * -- cgit 1.2.3-korg