aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorDave Barach <dave@barachs.net>2020-11-03 09:59:06 -0500
committerFlorin Coras <florin.coras@gmail.com>2020-11-04 17:39:10 +0000
commit27d978c9136e903244113a7ab57acea4b496898e (patch)
tree1520252a663db663b0634633149e5f83a9c23f53
parenta210433d534fe0039ddc2a9aa9840895aef0405d (diff)
vlib: add postmortem pcap dispatch trace
Inspired by a real-life conundrum: scenario X involves a vpp crash in ip4-load-balance because vnet_buffer(b)->ip.adj_index[VLIB_TX] is (still) set to ~0. The problem takes most of a day to occur, and we need to see the broken packet's graph trajectory, metadata, etc. to understand the problem. Fix a signed/unsigned ASSERT bug in vlib_get_trace_count(). Rename elog_post_mortem_dump() -> vlib_post_mortem_dump(), add dispatch trace post-mortem dump. Add FILTER_FLAG_POST_MORTEM so we can (putatively) capture a ludicrous number of buffer traces, without actually using more than one dispatch cycle's worth of memory. Type: improvement Signed-off-by: Dave Barach <dave@barachs.net> Change-Id: If093202ef071df46e290370bd9b33bf6560d30e6
-rw-r--r--src/vlib/main.c88
-rw-r--r--src/vlib/main.h2
-rw-r--r--src/vlib/trace.c9
-rw-r--r--src/vlib/trace.h1
-rw-r--r--src/vlib/trace_funcs.h6
-rw-r--r--src/vpp/vnet/main.c6
6 files changed, 95 insertions, 17 deletions
diff --git a/src/vlib/main.c b/src/vlib/main.c
index b868a64e4b5..f1de9090612 100644
--- a/src/vlib/main.c
+++ b/src/vlib/main.c
@@ -734,21 +734,44 @@ elog_save_buffer (vlib_main_t * vm,
}
void
-elog_post_mortem_dump (void)
+vlib_post_mortem_dump (void)
{
vlib_main_t *vm = &vlib_global_main;
elog_main_t *em = &vm->elog_main;
+
u8 *filename;
clib_error_t *error;
- if (!vm->elog_post_mortem_dump)
+ if ((vm->elog_post_mortem_dump + vm->dispatch_pcap_postmortem) == 0)
return;
- filename = format (0, "/tmp/elog_post_mortem.%d%c", getpid (), 0);
- error = elog_write_file (em, (char *) filename, 1 /* flush ring */ );
- if (error)
- clib_error_report (error);
- vec_free (filename);
+ if (vm->dispatch_pcap_postmortem)
+ {
+ clib_error_t *error;
+ pcap_main_t *pm = &vm->dispatch_pcap_main;
+
+ pm->n_packets_to_capture = pm->n_packets_captured;
+ pm->file_name = (char *) format (0, "/tmp/dispatch_post_mortem.%d%c",
+ getpid (), 0);
+ error = pcap_write (pm);
+ pcap_close (pm);
+ if (error)
+ clib_error_report (error);
+ /*
+ * We're in the middle of crashing. Don't try to free the filename.
+ */
+ }
+
+ if (vm->elog_post_mortem_dump)
+ {
+ filename = format (0, "/tmp/elog_post_mortem.%d%c", getpid (), 0);
+ error = elog_write_file (em, (char *) filename, 1 /* flush ring */ );
+ if (error)
+ clib_error_report (error);
+ /*
+ * We're in the middle of crashing. Don't try to free the filename.
+ */
+ }
}
/* *INDENT-OFF* */
@@ -1698,6 +1721,19 @@ dispatch_pending_interrupts (vlib_main_t * vm, vlib_node_main_t * nm,
return cpu_time_now;
}
+static inline void
+pcap_postmortem_reset (vlib_main_t * vm)
+{
+ pcap_main_t *pm = &vm->dispatch_pcap_main;
+
+ /* Reset the trace buffer and capture count */
+ clib_spinlock_lock_if_init (&pm->lock);
+ vec_reset_length (pm->pcap_data);
+ pm->n_packets_captured = 0;
+ clib_spinlock_unlock_if_init (&pm->lock);
+}
+
+
static_always_inline void
vlib_main_or_worker_loop (vlib_main_t * vm, int is_main)
{
@@ -1799,6 +1835,17 @@ vlib_main_or_worker_loop (vlib_main_t * vm, int is_main)
clib_call_callbacks (vm->worker_thread_main_loop_callbacks, vm,
cpu_time_now);
+ /*
+ * When trying to understand aggravating, hard-to-reproduce
+ * bugs: reset / restart the pcap dispatch trace once per
+ * main thread dispatch cycle. All threads share the same
+ * (spinlock-protected) dispatch trace buffer. It might take
+ * a few tries to capture a good post-mortem trace of
+ * a multi-thread issue. Best we can do without a big refactor job.
+ */
+ if (is_main && PREDICT_FALSE (vm->dispatch_pcap_postmortem != 0))
+ pcap_postmortem_reset (vm);
+
/* Process pre-input nodes. */
cpu_time_now = clib_cpu_time_now ();
vec_foreach (n, nm->nodes_by_type[VLIB_NODE_TYPE_PRE_INPUT])
@@ -2303,6 +2350,11 @@ vlib_pcap_dispatch_trace_configure (vlib_pcap_dispatch_trace_args_t * a)
vec_validate (tm->nodes, a->buffer_trace_node_index);
tn = tm->nodes + a->buffer_trace_node_index;
tn->limit += a->buffer_traces_to_capture;
+ if (a->post_mortem)
+ {
+ tm->filter_flag = FILTER_FLAG_POST_MORTEM;
+ tm->filter_count = ~0;
+ }
tm->trace_enable = 1;
}));
/* *INDENT-ON* */
@@ -2328,14 +2380,23 @@ vlib_pcap_dispatch_trace_configure (vlib_pcap_dispatch_trace_args_t * a)
pm->n_packets_captured = 0;
pm->packet_type = PCAP_PACKET_TYPE_vpp;
pm->n_packets_to_capture = a->packets_to_capture;
+ vm->dispatch_pcap_postmortem = a->post_mortem;
/* *INDENT-OFF* */
- foreach_vlib_main (({this_vlib_main->dispatch_pcap_enable = 1;}));
+ foreach_vlib_main (({ this_vlib_main->dispatch_pcap_enable = 1;}));
/* *INDENT-ON* */
}
else
{
/* *INDENT-OFF* */
- foreach_vlib_main (({this_vlib_main->dispatch_pcap_enable = 0;}));
+ foreach_vlib_main ((
+ {
+ this_vlib_main->dispatch_pcap_enable = 0;
+ this_vlib_main->dispatch_pcap_postmortem = 0;
+ tm = &this_vlib_main->trace_main;
+ tm->filter_flag = 0;
+ tm->filter_count = 0;
+ tm->trace_enable = 0;
+ }));
/* *INDENT-ON* */
vec_reset_length (vm->dispatch_buffer_trace_nodes);
if (pm->n_packets_captured)
@@ -2373,6 +2434,7 @@ dispatch_trace_command_fn (vlib_main_t * vm,
int rv;
int enable = 0;
int status = 0;
+ int post_mortem = 0;
u32 node_index = ~0, buffer_traces_to_capture = 100;
/* Get a line of input. */
@@ -2402,6 +2464,8 @@ dispatch_trace_command_fn (vlib_main_t * vm,
unformat_vlib_node, vm, &node_index,
&buffer_traces_to_capture))
;
+ else if (unformat (line_input, "post-mortem %=", &post_mortem, 1))
+ ;
else
{
return clib_error_return (0, "unknown input `%U'",
@@ -2418,6 +2482,7 @@ dispatch_trace_command_fn (vlib_main_t * vm,
a->packets_to_capture = max;
a->buffer_trace_node_index = node_index;
a->buffer_traces_to_capture = buffer_traces_to_capture;
+ a->post_mortem = post_mortem;
rv = vlib_pcap_dispatch_trace_configure (a);
@@ -2498,6 +2563,9 @@ dispatch_trace_command_fn (vlib_main_t * vm,
* @cliexstart{vppctl pcap dispatch trace off}
* captured 21 pkts...
* saved to /tmp/dispatchTrace.pcap...
+ * Example of how to start a post-mortem dispatch trace:
+ * pcap dispatch trace on max 20000 buffer-trace
+ * dpdk-input 3000000000 post-mortem
* @cliexend
?*/
/* *INDENT-OFF* */
@@ -2505,7 +2573,7 @@ VLIB_CLI_COMMAND (pcap_dispatch_trace_command, static) = {
.path = "pcap dispatch trace",
.short_help =
"pcap dispatch trace [on|off] [max <nn>] [file <name>] [status]\n"
- " [buffer-trace <input-node-name> <nn>]",
+ " [buffer-trace <input-node-name> <nn>][post-mortem]",
.function = dispatch_trace_command_fn,
};
/* *INDENT-ON* */
diff --git a/src/vlib/main.h b/src/vlib/main.h
index c582bc12f4e..c420d5f9d28 100644
--- a/src/vlib/main.h
+++ b/src/vlib/main.h
@@ -197,6 +197,7 @@ typedef struct vlib_main_t
/* Pcap dispatch trace main */
pcap_main_t dispatch_pcap_main;
uword dispatch_pcap_enable;
+ uword dispatch_pcap_postmortem;
u32 *dispatch_buffer_trace_nodes;
u8 *pcap_buffer;
@@ -483,6 +484,7 @@ typedef struct
u8 *filename;
int enable;
int status;
+ int post_mortem;
u32 packets_to_capture;
u32 buffer_trace_node_index;
u32 buffer_traces_to_capture;
diff --git a/src/vlib/trace.c b/src/vlib/trace.c
index abd116622c7..f90f275fa87 100644
--- a/src/vlib/trace.c
+++ b/src/vlib/trace.c
@@ -201,6 +201,15 @@ filter_accept (vlib_trace_main_t * tm, vlib_trace_header_t * h)
if (tm->filter_flag == 0)
return 1;
+ /*
+ * When capturing a post-mortem dispatch trace,
+ * toss all existing traces once per dispatch cycle.
+ * So we can trace 4 billion pkts without running out of
+ * memory...
+ */
+ if (tm->filter_flag == FILTER_FLAG_POST_MORTEM)
+ return 0;
+
if (tm->filter_flag == FILTER_FLAG_INCLUDE)
{
while (h < e)
diff --git a/src/vlib/trace.h b/src/vlib/trace.h
index 54b7c294569..ae9bd6913d3 100644
--- a/src/vlib/trace.h
+++ b/src/vlib/trace.h
@@ -91,6 +91,7 @@ typedef struct
#define FILTER_FLAG_NONE 0
#define FILTER_FLAG_INCLUDE 1
#define FILTER_FLAG_EXCLUDE 2
+#define FILTER_FLAG_POST_MORTEM 3
u32 filter_count;
/* set on trace add, cleared on clear trace */
diff --git a/src/vlib/trace_funcs.h b/src/vlib/trace_funcs.h
index 98bdb7e0a06..fba55bfc3d3 100644
--- a/src/vlib/trace_funcs.h
+++ b/src/vlib/trace_funcs.h
@@ -194,15 +194,13 @@ vlib_get_trace_count (vlib_main_t * vm, vlib_node_runtime_t * rt)
{
vlib_trace_main_t *tm = &vm->trace_main;
vlib_trace_node_t *tn;
- int n;
if (rt->node_index >= vec_len (tm->nodes))
return 0;
tn = tm->nodes + rt->node_index;
- n = tn->limit - tn->count;
- ASSERT (n >= 0);
+ ASSERT (tn->count <= tn->limit);
- return n;
+ return tn->limit - tn->count;
}
always_inline void
diff --git a/src/vpp/vnet/main.c b/src/vpp/vnet/main.c
index 397cf8328c5..582ad5fdc31 100644
--- a/src/vpp/vnet/main.c
+++ b/src/vpp/vnet/main.c
@@ -399,13 +399,13 @@ test_plugin_path_config (vlib_main_t * vm, unformat_input_t * input)
VLIB_CONFIG_FUNCTION (test_plugin_path_config, "test_plugin_path");
void vl_msg_api_post_mortem_dump (void);
-void elog_post_mortem_dump (void);
+void vlib_post_mortem_dump (void);
void
os_panic (void)
{
vl_msg_api_post_mortem_dump ();
- elog_post_mortem_dump ();
+ vlib_post_mortem_dump ();
abort ();
}
@@ -428,7 +428,7 @@ os_exit (int code)
recursion_block = 1;
vl_msg_api_post_mortem_dump ();
- elog_post_mortem_dump ();
+ vlib_post_mortem_dump ();
vhost_user_unmap_all ();
abort ();
}