From b09f4d0adb8364b3516c3a64e8238715887ffec8 Mon Sep 17 00:00:00 2001 From: Dave Barach Date: Mon, 15 Jul 2019 16:00:03 -0400 Subject: api: enable binary API event logging in vat Cleaned up a few instances of side-bet elog_string hash table usage. Elog_string handles that problem itself. Add cli commands to vat to initialize, enable/disable, and save an event log. Event logging at the same time in both vpp and vat yields a pair of event logs which can be merged by the "test_elog" tool. Type: refactor Change-Id: I8d6a72206f2309c967ea1630077fba31aef47f93 Signed-off-by: Dave Barach --- src/vat/api_format.c | 102 +++++++++++++++++++++++++++++++++++++- src/vat/vat.h | 5 ++ src/vlib/cli.c | 18 ++++--- src/vlib/main.c | 25 ++++++++++ src/vlib/threads.c | 30 ++---------- src/vlib/threads.h | 2 - src/vlibapi/api_common.h | 5 ++ src/vlibapi/api_shared.c | 109 ++++++++++++++++++++++++++++++----------- src/vlibmemory/memory_shared.c | 23 ++++++++- 9 files changed, 254 insertions(+), 65 deletions(-) diff --git a/src/vat/api_format.c b/src/vat/api_format.c index 5bba7efea46..a8d4a0db09d 100644 --- a/src/vat/api_format.c +++ b/src/vat/api_format.c @@ -85,6 +85,9 @@ #define __plugin_msg_base 0 #include +void vl_api_set_elog_main (elog_main_t * m); +int vl_api_set_elog_trace_api_messages (int enable); + #if VPP_API_TEST_BUILTIN == 0 #include @@ -164,7 +167,8 @@ errmsg (char *fmt, ...) if (vam->ifp != stdin) fformat (vam->ofp, "%s(%d): \n", vam->current_file, vam->input_line_number); - fformat (vam->ofp, (char *) s); + else + fformat (vam->ofp, "%s\n", (char *) s); fflush (vam->ofp); } #endif @@ -21402,6 +21406,98 @@ comment (vat_main_t * vam) return 0; } +static int +elog_save (vat_main_t * vam) +{ +#if VPP_API_TEST_BUILTIN == 0 + elog_main_t *em = &vam->elog_main; + unformat_input_t *i = vam->input; + char *file, *chroot_file; + clib_error_t *error; + + if (!unformat (i, "%s", &file)) + { + errmsg ("expected file name, got `%U'", format_unformat_error, i); + return 0; + } + + /* It's fairly hard to get "../oopsie" through unformat; just in case */ + if (strstr (file, "..") || index (file, '/')) + { + errmsg ("illegal characters in filename '%s'", file); + return 0; + } + + chroot_file = (char *) format (0, "/tmp/%s%c", file, 0); + + vec_free (file); + + errmsg ("Saving %wd of %wd events to %s", + elog_n_events_in_buffer (em), + elog_buffer_capacity (em), chroot_file); + + error = elog_write_file (em, chroot_file, 1 /* flush ring */ ); + vec_free (chroot_file); + + if (error) + clib_error_report (error); +#else + errmsg ("Use the vpp event loger..."); +#endif + + return 0; +} + +static int +elog_setup (vat_main_t * vam) +{ +#if VPP_API_TEST_BUILTIN == 0 + elog_main_t *em = &vam->elog_main; + unformat_input_t *i = vam->input; + u32 nevents = 128 << 10; + + (void) unformat (i, "nevents %d", &nevents); + + elog_init (em, nevents); + vl_api_set_elog_main (em); + vl_api_set_elog_trace_api_messages (1); + errmsg ("Event logger initialized with %u events", nevents); +#else + errmsg ("Use the vpp event loger..."); +#endif + return 0; +} + +static int +elog_enable (vat_main_t * vam) +{ +#if VPP_API_TEST_BUILTIN == 0 + elog_main_t *em = &vam->elog_main; + + elog_enable_disable (em, 1 /* enable */ ); + vl_api_set_elog_trace_api_messages (1); + errmsg ("Event logger enabled..."); +#else + errmsg ("Use the vpp event loger..."); +#endif + return 0; +} + +static int +elog_disable (vat_main_t * vam) +{ +#if VPP_API_TEST_BUILTIN == 0 + elog_main_t *em = &vam->elog_main; + + elog_enable_disable (em, 0 /* enable */ ); + vl_api_set_elog_trace_api_messages (1); + errmsg ("Event logger disabled..."); +#else + errmsg ("Use the vpp event loger..."); +#endif + return 0; +} + static int statseg (vat_main_t * vam) { @@ -22286,6 +22382,10 @@ _(dump_ipv6_table, "usage: dump_ipv6_table") \ _(dump_macro_table, "usage: dump_macro_table ") \ _(dump_node_table, "usage: dump_node_table") \ _(dump_msg_api_table, "usage: dump_msg_api_table") \ +_(elog_setup, "usage: elog_setup [nevents, default 128K]") \ +_(elog_disable, "usage: elog_disable") \ +_(elog_enable, "usage: elog_enable") \ +_(elog_save, "usage: elog_save ") \ _(get_msg_id, "usage: get_msg_id name_and_crc") \ _(echo, "usage: echo ") \ _(exec, "usage: exec ") \ diff --git a/src/vat/vat.h b/src/vat/vat.h index c71446519a3..0d93af7b0f2 100644 --- a/src/vat/vat.h +++ b/src/vat/vat.h @@ -24,6 +24,7 @@ #include #include #include +#include #include #include #include @@ -215,6 +216,10 @@ typedef struct socket_client_main_t *socket_client_main; u8 *socket_name; +#if VPP_API_TEST_BUILTIN == 0 + elog_main_t elog_main; +#endif + /* Convenience */ vlib_main_t *vlib_main; } vat_main_t; diff --git a/src/vlib/cli.c b/src/vlib/cli.c index bf0670da1c9..60895bacb1c 100644 --- a/src/vlib/cli.c +++ b/src/vlib/cli.c @@ -44,6 +44,9 @@ #include #include +int vl_api_set_elog_trace_api_messages (int enable); +int vl_api_get_elog_trace_api_messages (void); + static void *current_traced_heap; /* Root of all show commands. */ @@ -633,7 +636,7 @@ vlib_cli_dispatch_sub_commands (vlib_main_t * vm, u32 c; } *ed; ed = ELOG_DATA (&vm->elog_main, e); - ed->c = elog_global_id_for_msg_name (c->path); + ed->c = elog_string (&vm->elog_main, c->path); } if (!c->is_mp_safe) @@ -658,16 +661,16 @@ vlib_cli_dispatch_sub_commands (vlib_main_t * vm, u32 c, err; } *ed; ed = ELOG_DATA (&vm->elog_main, e); - ed->c = elog_global_id_for_msg_name (c->path); + ed->c = elog_string (&vm->elog_main, c->path); if (c_error) { vec_add1 (c_error->what, 0); - ed->err = elog_global_id_for_msg_name - ((const char *) c_error->what); + ed->err = elog_string (&vm->elog_main, + (char *) c_error->what); _vec_len (c_error->what) -= 1; } else - ed->err = elog_global_id_for_msg_name ("OK"); + ed->err = elog_string (&vm->elog_main, "OK"); } if (c_error) @@ -1630,7 +1633,8 @@ elog_trace_command_fn (vlib_main_t * vm, } unformat_free (line_input); - vm->elog_trace_api_messages = api ? enable : vm->elog_trace_api_messages; + vl_api_set_elog_trace_api_messages + (api ? enable : vl_api_get_elog_trace_api_messages ()); vm->elog_trace_cli_commands = cli ? enable : vm->elog_trace_cli_commands; vm->elog_trace_graph_dispatch = dispatch ? enable : vm->elog_trace_graph_dispatch; @@ -1660,7 +1664,7 @@ print_status: vlib_cli_output (vm, " Event log API message trace: %s\n CLI command trace: %s", - vm->elog_trace_api_messages ? "on" : "off", + vl_api_get_elog_trace_api_messages ()? "on" : "off", vm->elog_trace_cli_commands ? "on" : "off"); vlib_cli_output (vm, " Barrier sync trace: %s", diff --git a/src/vlib/main.c b/src/vlib/main.c index 3c0e754169f..055ea93cec1 100644 --- a/src/vlib/main.c +++ b/src/vlib/main.c @@ -1990,6 +1990,29 @@ clib_error_t *name (vlib_main_t *vm) { return 0; } foreach_weak_reference_stub; #undef _ +void vl_api_set_elog_main (elog_main_t * m) __attribute__ ((weak)); +void +vl_api_set_elog_main (elog_main_t * m) +{ + clib_warning ("STUB"); +} + +int vl_api_set_elog_trace_api_messages (int enable) __attribute__ ((weak)); +int +vl_api_set_elog_trace_api_messages (int enable) +{ + clib_warning ("STUB"); + return 0; +} + +int vl_api_get_elog_trace_api_messages (void) __attribute__ ((weak)); +int +vl_api_get_elog_trace_api_messages (void) +{ + clib_warning ("STUB"); + return 0; +} + /* Main function. */ int vlib_main (vlib_main_t * volatile vm, unformat_input_t * input) @@ -2006,6 +2029,8 @@ vlib_main (vlib_main_t * volatile vm, unformat_input_t * input) 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); + vl_api_set_elog_main (&vm->elog_main); + (void) vl_api_set_elog_trace_api_messages (1); /* Default name. */ if (!vm->name) diff --git a/src/vlib/threads.c b/src/vlib/threads.c index 91125387248..e59919e7a26 100644 --- a/src/vlib/threads.c +++ b/src/vlib/threads.c @@ -44,28 +44,6 @@ vlib_thread_main_t vlib_thread_main; * imapacts observed timings. */ -u32 -elog_global_id_for_msg_name (const char *msg_name) -{ - uword *p, r; - static uword *h; - u8 *name_copy; - - if (!h) - h = hash_create_string (0, sizeof (uword)); - - p = hash_get_mem (h, msg_name); - if (p) - return p[0]; - r = elog_string (&vlib_global_main.elog_main, "%s", msg_name); - - name_copy = format (0, "%s%c", msg_name, 0); - - hash_set_mem (h, name_copy, r); - - return r; -} - static inline void barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed) { @@ -86,8 +64,8 @@ barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed) ed = ELOG_DATA (&vlib_global_main.elog_main, e); ed->count = (int) vlib_worker_threads[0].barrier_sync_count; - ed->caller = elog_global_id_for_msg_name - (vlib_worker_threads[0].barrier_caller); + ed->caller = elog_string (&vlib_global_main.elog_main, + (char *) vlib_worker_threads[0].barrier_caller); ed->t_entry = (int) (1000000.0 * t_entry); ed->t_open = (int) (1000000.0 * t_open); ed->t_closed = (int) (1000000.0 * t_closed); @@ -113,8 +91,8 @@ barrier_trace_sync_rec (f64 t_entry) ed = ELOG_DATA (&vlib_global_main.elog_main, e); ed->depth = (int) vlib_worker_threads[0].recursion_level - 1; - ed->caller = elog_global_id_for_msg_name - (vlib_worker_threads[0].barrier_caller); + ed->caller = elog_string (&vlib_global_main.elog_main, + (char *) vlib_worker_threads[0].barrier_caller); } static inline void diff --git a/src/vlib/threads.h b/src/vlib/threads.h index fc34074127f..79f44c8f502 100644 --- a/src/vlib/threads.h +++ b/src/vlib/threads.h @@ -613,8 +613,6 @@ void vlib_process_signal_event_mt_helper (vlib_process_signal_event_mt_args_t * args); void vlib_rpc_call_main_thread (void *function, u8 * args, u32 size); - -u32 elog_global_id_for_msg_name (const char *msg_name); #endif /* included_vlib_threads_h */ /* diff --git a/src/vlibapi/api_common.h b/src/vlibapi/api_common.h index 735921b30f7..98fcbdefef9 100644 --- a/src/vlibapi/api_common.h +++ b/src/vlibapi/api_common.h @@ -25,6 +25,7 @@ */ #include +#include #include #include #include @@ -339,6 +340,10 @@ typedef struct /** List of API client reaper functions */ _vl_msg_api_function_list_elt_t *reaper_function_registrations; + /** event log */ + elog_main_t *elog_main; + int elog_trace_api_messages; + } api_main_t; extern api_main_t api_main; diff --git a/src/vlibapi/api_shared.c b/src/vlibapi/api_shared.c index 9579fe1c60f..18eb83b68b7 100644 --- a/src/vlibapi/api_shared.c +++ b/src/vlibapi/api_shared.c @@ -398,6 +398,26 @@ msg_handler_internal (api_main_t * am, u16 id = clib_net_to_host_u16 (*((u16 *) the_msg)); u8 *(*print_fp) (void *, void *); + if (PREDICT_FALSE (am->elog_trace_api_messages)) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "api-msg: %s", + .format_args = "T4", + }; + /* *INDENT-ON* */ + struct + { + u32 c; + } *ed; + ed = ELOG_DATA (am->elog_main, e); + if (id < vec_len (am->msg_names)) + ed->c = elog_string (am->elog_main, (char *) am->msg_names[id]); + else + ed->c = elog_string (am->elog_main, "BOGUS"); + } + if (id < vec_len (am->msg_handlers) && am->msg_handlers[id]) { if (trace_it) @@ -436,28 +456,35 @@ msg_handler_internal (api_main_t * am, if (free_it) vl_msg_api_free (the_msg); -} -static u32 -elog_id_for_msg_name (vlib_main_t * vm, const char *msg_name) -{ - uword *p, r; - static uword *h; - u8 *name_copy; - - if (!h) - h = hash_create_string (0, sizeof (uword)); - - p = hash_get_mem (h, msg_name); - if (p) - return p[0]; - r = elog_string (&vm->elog_main, "%s", msg_name); - - name_copy = format (0, "%s%c", msg_name, 0); - - hash_set_mem (h, name_copy, r); + if (PREDICT_FALSE (am->elog_trace_api_messages)) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "api-msg-done(%s): %s", + .format_args = "t4T4", + .n_enum_strings = 2, + .enum_strings = + { + "barrier", + "mp-safe", + } + }; + /* *INDENT-ON* */ - return r; + struct + { + u32 barrier; + u32 c; + } *ed; + ed = ELOG_DATA (am->elog_main, e); + if (id < vec_len (am->msg_names)) + ed->c = elog_string (am->elog_main, (char *) am->msg_names[id]); + else + ed->c = elog_string (am->elog_main, "BOGUS"); + ed->barrier = !am->is_mp_safe[id]; + } } /* This is only to be called from a vlib/vnet app */ @@ -471,7 +498,7 @@ vl_msg_api_handler_with_vm_node (api_main_t * am, u8 *(*print_fp) (void *, void *); int is_mp_safe = 1; - if (PREDICT_FALSE (vm->elog_trace_api_messages)) + if (PREDICT_FALSE (am->elog_trace_api_messages)) { /* *INDENT-OFF* */ ELOG_TYPE_DECLARE (e) = @@ -484,11 +511,11 @@ vl_msg_api_handler_with_vm_node (api_main_t * am, { u32 c; } *ed; - ed = ELOG_DATA (&vm->elog_main, e); + ed = ELOG_DATA (am->elog_main, e); if (id < vec_len (am->msg_names)) - ed->c = elog_id_for_msg_name (vm, (const char *) am->msg_names[id]); + ed->c = elog_string (am->elog_main, (char *) am->msg_names[id]); else - ed->c = elog_id_for_msg_name (vm, "BOGUS"); + ed->c = elog_string (am->elog_main, "BOGUS"); } if (id < vec_len (am->msg_handlers) && am->msg_handlers[id]) @@ -534,7 +561,7 @@ vl_msg_api_handler_with_vm_node (api_main_t * am, if (!(am->message_bounce[id])) vl_msg_api_free (the_msg); - if (PREDICT_FALSE (vm->elog_trace_api_messages)) + if (PREDICT_FALSE (am->elog_trace_api_messages)) { /* *INDENT-OFF* */ ELOG_TYPE_DECLARE (e) = @@ -555,11 +582,11 @@ vl_msg_api_handler_with_vm_node (api_main_t * am, u32 barrier; u32 c; } *ed; - ed = ELOG_DATA (&vm->elog_main, e); + ed = ELOG_DATA (am->elog_main, e); if (id < vec_len (am->msg_names)) - ed->c = elog_id_for_msg_name (vm, (const char *) am->msg_names[id]); + ed->c = elog_string (am->elog_main, (char *) am->msg_names[id]); else - ed->c = elog_id_for_msg_name (vm, "BOGUS"); + ed->c = elog_string (am->elog_main, "BOGUS"); ed->barrier = is_mp_safe; } } @@ -1033,6 +1060,32 @@ vl_api_from_api_to_vec (vl_api_string_t * astr) return v; } +void +vl_api_set_elog_main (elog_main_t * m) +{ + api_main_t *am = &api_main; + am->elog_main = m; +} + +int +vl_api_set_elog_trace_api_messages (int enable) +{ + int rv; + api_main_t *am = &api_main; + + rv = am->elog_trace_api_messages; + am->elog_trace_api_messages = enable; + return rv; +} + +int +vl_api_get_elog_trace_api_messages (void) +{ + api_main_t *am = &api_main; + + return am->elog_trace_api_messages; +} + /* * fd.io coding-style-patch-verification: ON * diff --git a/src/vlibmemory/memory_shared.c b/src/vlibmemory/memory_shared.c index fa9936982ee..f44ab7c4106 100644 --- a/src/vlibmemory/memory_shared.c +++ b/src/vlibmemory/memory_shared.c @@ -29,6 +29,7 @@ #include #include #include +#include #include #include #include @@ -764,7 +765,27 @@ vl_msg_api_send_shmem (svm_queue_t * q, u8 * elem) */ if (PREDICT_FALSE (am->vl_clients /* vpp side */ && (q->cursize == q->maxsize))) - clib_warning ("WARNING: client input queue at %llx is stuffed...", q); + { + if (PREDICT_FALSE (am->elog_trace_api_messages)) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "api-client-queue-stuffed: %x%x", + .format_args = "i4i4", + }; + /* *INDENT-ON* */ + struct + { + u32 hi, low; + } *ed; + ed = ELOG_DATA (am->elog_main, e); + ed->hi = (uword) q >> 32; + ed->low = (uword) q & 0xFFFFFFFF; + clib_warning ("WARNING: client input queue at %llx is stuffed...", + q); + } + } (void) svm_queue_add (q, elem, 0 /* nowait */ ); } -- cgit 1.2.3-korg