From: Dave Barach Date: Tue, 3 Nov 2020 14:59:06 +0000 (-0500) Subject: vlib: add postmortem pcap dispatch trace X-Git-Tag: v21.06-rc0~232 X-Git-Url: https://gerrit.fd.io/r/gitweb?p=vpp.git;a=commitdiff_plain;h=27d978c9136e903244113a7ab57acea4b496898e 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 Change-Id: If093202ef071df46e290370bd9b33bf6560d30e6 --- 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 ] [file ] [status]\n" - " [buffer-trace ]", + " [buffer-trace ][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 (); }