summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorDave Barach <dave@barachs.net>2019-07-15 16:00:03 -0400
committerDamjan Marion <dmarion@me.com>2019-07-16 13:12:12 +0000
commitb09f4d0adb8364b3516c3a64e8238715887ffec8 (patch)
tree95f9f29d3d5a9c17fcff3cd670623cc16ff2806b
parent7b8a30d08bffcb8c6fe7faa8d7f7dc557e175770 (diff)
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 <dave@barachs.net>
-rw-r--r--src/vat/api_format.c102
-rw-r--r--src/vat/vat.h5
-rw-r--r--src/vlib/cli.c18
-rw-r--r--src/vlib/main.c25
-rw-r--r--src/vlib/threads.c30
-rw-r--r--src/vlib/threads.h2
-rw-r--r--src/vlibapi/api_common.h5
-rw-r--r--src/vlibapi/api_shared.c109
-rw-r--r--src/vlibmemory/memory_shared.c23
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 <vlibapi/vat_helper_macros.h>
+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 <netdb.h>
@@ -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
@@ -21403,6 +21407,98 @@ comment (vat_main_t * vam)
}
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)
{
ssvm_private_t *ssvmp = &vam->stat_segment;
@@ -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 <filename>") \
_(get_msg_id, "usage: get_msg_id name_and_crc") \
_(echo, "usage: echo <message>") \
_(exec, "usage: exec <vpe-debug-CLI-command>") \
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 <vppinfra/clib.h>
#include <vppinfra/format.h>
#include <vppinfra/error.h>
+#include <vppinfra/elog.h>
#include <vppinfra/time.h>
#include <vppinfra/macros.h>
#include <vppinfra/socket.h>
@@ -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 <unistd.h>
#include <ctype.h>
+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 <vppinfra/clib_error.h>
+#include <vppinfra/elog.h>
#include <vlibapi/api_types.h>
#include <svm/svm_common.h>
#include <svm/queue.h>
@@ -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 <vppinfra/format.h>
#include <vppinfra/byte_order.h>
#include <vppinfra/error.h>
+#include <vppinfra/elog.h>
#include <svm/queue.h>
#include <vlib/vlib.h>
#include <vlib/unix/unix.h>
@@ -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 */ );
}