diff options
Diffstat (limited to 'src')
| -rw-r--r-- | src/vlib/cli.c | 43 | ||||
| -rw-r--r-- | src/vlib/main.c | 294 | ||||
| -rw-r--r-- | src/vlib/main.h | 3 |
3 files changed, 214 insertions, 126 deletions
diff --git a/src/vlib/cli.c b/src/vlib/cli.c index 4c33914e8cc..4e8f3ae5ae5 100644 --- a/src/vlib/cli.c +++ b/src/vlib/cli.c @@ -1465,7 +1465,8 @@ elog_trace_command_fn (vlib_main_t * vm, { unformat_input_t _line_input, *line_input = &_line_input; int enable = 1; - int api = 0, cli = 0, barrier = 0; + int api = 0, cli = 0, barrier = 0, dispatch = 0, circuit = 0; + u32 circuit_node_index; if (!unformat_user (input, unformat_line_input, line_input)) goto print_status; @@ -1474,6 +1475,11 @@ elog_trace_command_fn (vlib_main_t * vm, { if (unformat (line_input, "api")) api = 1; + else if (unformat (line_input, "dispatch")) + dispatch = 1; + else if (unformat (line_input, "circuit-node %U", + unformat_vlib_node, vm, &circuit_node_index)) + circuit = 1; else if (unformat (line_input, "cli")) cli = 1; else if (unformat (line_input, "barrier")) @@ -1489,8 +1495,28 @@ elog_trace_command_fn (vlib_main_t * vm, vm->elog_trace_api_messages = api ? enable : vm->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; + vm->elog_trace_graph_circuit = circuit ? + enable : vm->elog_trace_graph_circuit; vlib_worker_threads->barrier_elog_enabled = barrier ? enable : vlib_worker_threads->barrier_elog_enabled; + vm->elog_trace_graph_circuit_node_index = circuit_node_index; + + /* + * Set up start-of-buffer logic-analyzer trigger + * for main loop event logs, which are fairly heavyweight. + * See src/vlib/main/vlib_elog_main_loop_event(...), which + * will fully disable the scheme when the elog buffer fills. + */ + if (dispatch || circuit) + { + elog_main_t *em = &vm->elog_main; + + em->n_total_events_disable_limit = + em->n_total_events + vec_len (em->event_ring); + } + print_status: vlib_cli_output (vm, "Current status:"); @@ -1502,6 +1528,16 @@ print_status: vlib_cli_output (vm, " Barrier sync trace: %s", vlib_worker_threads->barrier_elog_enabled ? "on" : "off"); + vlib_cli_output + (vm, " Graph Dispatch: %s", + vm->elog_trace_graph_dispatch ? "on" : "off"); + vlib_cli_output + (vm, " Graph Circuit: %s", + vm->elog_trace_graph_circuit ? "on" : "off"); + if (vm->elog_trace_graph_circuit) + vlib_cli_output + (vm, " node %U", + format_vlib_node_name, vm, vm->elog_trace_graph_circuit_node_index); return 0; } @@ -1515,6 +1551,8 @@ print_status: * @clistart * elog trace api cli barrier * elog trace api cli barrier disable + * elog trace dispatch + * elog trace circuit-node ethernet-input * elog trace * @cliend * @cliexcmd{elog trace [api][cli][barrier][disable]} @@ -1523,7 +1561,8 @@ print_status: VLIB_CLI_COMMAND (elog_trace_command, static) = { .path = "elog trace", - .short_help = "elog trace [api][cli][barrier][disable]", + .short_help = "elog trace [api][cli][barrier][dispatch]\n" + "[circuit-node <name> e.g. ethernet-input][disable]", .function = elog_trace_command_fn, }; /* *INDENT-ON* */ diff --git a/src/vlib/main.c b/src/vlib/main.c index c5153abc0cc..eed627cf215 100644 --- a/src/vlib/main.c +++ b/src/vlib/main.c @@ -912,18 +912,35 @@ vlib_elog_main_loop_event (vlib_main_t * vm, { vlib_main_t *evm = &vlib_global_main; elog_main_t *em = &evm->elog_main; + int enabled = evm->elog_trace_graph_dispatch | + evm->elog_trace_graph_circuit; - if (VLIB_ELOG_MAIN_LOOP && n_vectors) - elog_track (em, - /* event type */ - vec_elt_at_index (is_return - ? evm->node_return_elog_event_types - : evm->node_call_elog_event_types, - node_index), - /* track */ - (vm->thread_index ? &vlib_worker_threads[vm->thread_index]. - elog_track : &em->default_track), - /* data to log */ n_vectors); + if (PREDICT_FALSE (enabled && n_vectors)) + { + if (PREDICT_FALSE (!elog_is_enabled (em))) + { + evm->elog_trace_graph_dispatch = 0; + evm->elog_trace_graph_circuit = 0; + return; + } + if (PREDICT_TRUE + (evm->elog_trace_graph_dispatch || + (evm->elog_trace_graph_circuit && + node_index == evm->elog_trace_graph_circuit_node_index))) + { + elog_track (em, + /* event type */ + vec_elt_at_index (is_return + ? evm->node_return_elog_event_types + : evm->node_call_elog_event_types, + node_index), + /* track */ + (vm->thread_index ? + &vlib_worker_threads[vm->thread_index].elog_track + : &em->default_track), + /* data to log */ n_vectors); + } + } } #if VLIB_BUFFER_TRACE_TRAJECTORY > 0 @@ -1116,6 +1133,7 @@ dispatch_node (vlib_main_t * vm, u64 t; vlib_node_main_t *nm = &vm->node_main; vlib_next_frame_t *nf; + u64 pmc_before[2], pmc_after[2], pmc_delta[2]; if (CLIB_DEBUG > 0) { @@ -1151,142 +1169,142 @@ dispatch_node (vlib_main_t * vm, vm->cpu_time_last_node_dispatch = last_time_stamp; - if (1 /* || vm->thread_index == node->thread_index */ ) - { - u64 pmc_before[2], pmc_after[2], pmc_delta[2]; - - vlib_elog_main_loop_event (vm, node->node_index, - last_time_stamp, - frame ? frame->n_vectors : 0, - /* is_after */ 0); + vlib_elog_main_loop_event (vm, node->node_index, + last_time_stamp, frame ? frame->n_vectors : 0, + /* is_after */ 0); - vlib_node_runtime_perf_counter (vm, &pmc_before[0], &pmc_before[1]); + vlib_node_runtime_perf_counter (vm, &pmc_before[0], &pmc_before[1]); - /* - * Turn this on if you run into - * "bad monkey" contexts, and you want to know exactly - * which nodes they've visited... See ixge.c... - */ - if (VLIB_BUFFER_TRACE_TRAJECTORY && frame) - { - int i; - u32 *from; - from = vlib_frame_vector_args (frame); - for (i = 0; i < frame->n_vectors; i++) - { - vlib_buffer_t *b = vlib_get_buffer (vm, from[i]); - add_trajectory_trace (b, node->node_index); - } - if (PREDICT_FALSE (vm->dispatch_pcap_enable)) - dispatch_pcap_trace (vm, node, frame); - n = node->function (vm, node, frame); - } - else + /* + * Turn this on if you run into + * "bad monkey" contexts, and you want to know exactly + * which nodes they've visited... See ixge.c... + */ + if (VLIB_BUFFER_TRACE_TRAJECTORY && frame) + { + int i; + u32 *from; + from = vlib_frame_vector_args (frame); + for (i = 0; i < frame->n_vectors; i++) { - if (PREDICT_FALSE (vm->dispatch_pcap_enable)) - dispatch_pcap_trace (vm, node, frame); - n = node->function (vm, node, frame); + vlib_buffer_t *b = vlib_get_buffer (vm, from[i]); + add_trajectory_trace (b, node->node_index); } + if (PREDICT_FALSE (vm->dispatch_pcap_enable)) + dispatch_pcap_trace (vm, node, frame); + n = node->function (vm, node, frame); + } + else + { + if (PREDICT_FALSE (vm->dispatch_pcap_enable)) + dispatch_pcap_trace (vm, node, frame); + n = node->function (vm, node, frame); + } - t = clib_cpu_time_now (); + t = clib_cpu_time_now (); - /* - * To validate accounting: pmc_delta = t - pmc_before; - * perf ticks should equal clocks/pkt... - */ - vlib_node_runtime_perf_counter (vm, &pmc_after[0], &pmc_after[1]); - - pmc_delta[0] = pmc_after[0] - pmc_before[0]; - pmc_delta[1] = pmc_after[1] - pmc_before[1]; - - vlib_elog_main_loop_event (vm, node->node_index, t, n, /* is_after */ - 1); - - vm->main_loop_vectors_processed += n; - vm->main_loop_nodes_processed += n > 0; - - v = vlib_node_runtime_update_stats (vm, node, - /* n_calls */ 1, - /* n_vectors */ n, - /* n_clocks */ t - last_time_stamp, - pmc_delta[0] /* PMC0 */ , - pmc_delta[1] /* PMC1 */ ); - - /* When in interrupt mode and vector rate crosses threshold switch to - polling mode. */ - if ((dispatch_state == VLIB_NODE_STATE_INTERRUPT) - || (dispatch_state == VLIB_NODE_STATE_POLLING - && (node->flags - & VLIB_NODE_FLAG_SWITCH_FROM_INTERRUPT_TO_POLLING_MODE))) - { -#ifdef DISPATCH_NODE_ELOG_REQUIRED - ELOG_TYPE_DECLARE (e) = - { - .function = (char *) __FUNCTION__,.format = - "%s vector length %d, switching to %s",.format_args = - "T4i4t4",.n_enum_strings = 2,.enum_strings = - { - "interrupt", "polling",},}; - struct - { - u32 node_name, vector_length, is_polling; - } *ed; - vlib_worker_thread_t *w = vlib_worker_threads + vm->thread_index; -#endif + /* + * To validate accounting: pmc_delta = t - pmc_before; + * perf ticks should equal clocks/pkt... + */ + vlib_node_runtime_perf_counter (vm, &pmc_after[0], &pmc_after[1]); + + pmc_delta[0] = pmc_after[0] - pmc_before[0]; + pmc_delta[1] = pmc_after[1] - pmc_before[1]; + + vlib_elog_main_loop_event (vm, node->node_index, t, n, 1 /* is_after */ ); + + vm->main_loop_vectors_processed += n; + vm->main_loop_nodes_processed += n > 0; + + v = vlib_node_runtime_update_stats (vm, node, + /* n_calls */ 1, + /* n_vectors */ n, + /* n_clocks */ t - last_time_stamp, + pmc_delta[0] /* PMC0 */ , + pmc_delta[1] /* PMC1 */ ); + + /* When in interrupt mode and vector rate crosses threshold switch to + polling mode. */ + if (PREDICT_FALSE ((dispatch_state == VLIB_NODE_STATE_INTERRUPT) + || (dispatch_state == VLIB_NODE_STATE_POLLING + && (node->flags + & + VLIB_NODE_FLAG_SWITCH_FROM_INTERRUPT_TO_POLLING_MODE)))) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .function = (char *) __FUNCTION__, + .format = "%s vector length %d, switching to %s", + .format_args = "T4i4t4", + .n_enum_strings = 2, + .enum_strings = { + "interrupt", "polling", + }, + }; + /* *INDENT-ON* */ + struct + { + u32 node_name, vector_length, is_polling; + } *ed; - if ((dispatch_state == VLIB_NODE_STATE_INTERRUPT - && v >= nm->polling_threshold_vector_length) && - !(node->flags & - VLIB_NODE_FLAG_SWITCH_FROM_INTERRUPT_TO_POLLING_MODE)) + if ((dispatch_state == VLIB_NODE_STATE_INTERRUPT + && v >= nm->polling_threshold_vector_length) && + !(node->flags & + VLIB_NODE_FLAG_SWITCH_FROM_INTERRUPT_TO_POLLING_MODE)) + { + vlib_node_t *n = vlib_get_node (vm, node->node_index); + n->state = VLIB_NODE_STATE_POLLING; + node->state = VLIB_NODE_STATE_POLLING; + node->flags &= + ~VLIB_NODE_FLAG_SWITCH_FROM_POLLING_TO_INTERRUPT_MODE; + node->flags |= VLIB_NODE_FLAG_SWITCH_FROM_INTERRUPT_TO_POLLING_MODE; + nm->input_node_counts_by_state[VLIB_NODE_STATE_INTERRUPT] -= 1; + nm->input_node_counts_by_state[VLIB_NODE_STATE_POLLING] += 1; + + if (PREDICT_FALSE (vlib_global_main.elog_trace_graph_dispatch)) { - vlib_node_t *n = vlib_get_node (vm, node->node_index); - n->state = VLIB_NODE_STATE_POLLING; - node->state = VLIB_NODE_STATE_POLLING; - node->flags &= - ~VLIB_NODE_FLAG_SWITCH_FROM_POLLING_TO_INTERRUPT_MODE; - node->flags |= - VLIB_NODE_FLAG_SWITCH_FROM_INTERRUPT_TO_POLLING_MODE; - nm->input_node_counts_by_state[VLIB_NODE_STATE_INTERRUPT] -= 1; - nm->input_node_counts_by_state[VLIB_NODE_STATE_POLLING] += 1; + vlib_worker_thread_t *w = vlib_worker_threads + + vm->thread_index; -#ifdef DISPATCH_NODE_ELOG_REQUIRED ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main, e, w->elog_track); ed->node_name = n->name_elog_string; ed->vector_length = v; ed->is_polling = 1; -#endif } - else if (dispatch_state == VLIB_NODE_STATE_POLLING - && v <= nm->interrupt_threshold_vector_length) + } + else if (dispatch_state == VLIB_NODE_STATE_POLLING + && v <= nm->interrupt_threshold_vector_length) + { + vlib_node_t *n = vlib_get_node (vm, node->node_index); + if (node->flags & + VLIB_NODE_FLAG_SWITCH_FROM_POLLING_TO_INTERRUPT_MODE) { - vlib_node_t *n = vlib_get_node (vm, node->node_index); - if (node->flags & - VLIB_NODE_FLAG_SWITCH_FROM_POLLING_TO_INTERRUPT_MODE) - { - /* Switch to interrupt mode after dispatch in polling one more time. - This allows driver to re-enable interrupts. */ - n->state = VLIB_NODE_STATE_INTERRUPT; - node->state = VLIB_NODE_STATE_INTERRUPT; - node->flags &= - ~VLIB_NODE_FLAG_SWITCH_FROM_INTERRUPT_TO_POLLING_MODE; - nm->input_node_counts_by_state[VLIB_NODE_STATE_POLLING] -= - 1; - nm->input_node_counts_by_state[VLIB_NODE_STATE_INTERRUPT] += - 1; + /* Switch to interrupt mode after dispatch in polling one more time. + This allows driver to re-enable interrupts. */ + n->state = VLIB_NODE_STATE_INTERRUPT; + node->state = VLIB_NODE_STATE_INTERRUPT; + node->flags &= + ~VLIB_NODE_FLAG_SWITCH_FROM_INTERRUPT_TO_POLLING_MODE; + nm->input_node_counts_by_state[VLIB_NODE_STATE_POLLING] -= 1; + nm->input_node_counts_by_state[VLIB_NODE_STATE_INTERRUPT] += 1; - } - else + } + else + { + vlib_worker_thread_t *w = vlib_worker_threads + + vm->thread_index; + node->flags |= + VLIB_NODE_FLAG_SWITCH_FROM_POLLING_TO_INTERRUPT_MODE; + if (PREDICT_FALSE (vlib_global_main.elog_trace_graph_dispatch)) { - node->flags |= - VLIB_NODE_FLAG_SWITCH_FROM_POLLING_TO_INTERRUPT_MODE; -#ifdef DISPATCH_NODE_ELOG_REQUIRED ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main, e, w->elog_track); ed->node_name = n->name_elog_string; ed->vector_length = v; ed->is_polling = 0; -#endif } } } @@ -1778,9 +1796,30 @@ vlib_main_or_worker_loop (vlib_main_t * vm, int is_main) if (is_main) { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (es) = + { + .format = "process tw start", + .format_args = "", + }; + ELOG_TYPE_DECLARE (ee) = + { + .format = "process tw end: %d", + .format_args = "i4", + }; + /* *INDENT-ON* */ + + struct + { + int nready_procs; + } *ed; + /* Check if process nodes have expired from timing wheel. */ ASSERT (nm->data_from_advancing_timing_wheel != 0); + if (PREDICT_FALSE (vm->elog_trace_graph_dispatch)) + ed = ELOG_DATA (&vlib_global_main.elog_main, es); + nm->data_from_advancing_timing_wheel = TW (tw_timer_expire_timers_vec) ((TWT (tw_timer_wheel) *) nm->timing_wheel, vlib_time_now (vm), @@ -1788,6 +1827,13 @@ vlib_main_or_worker_loop (vlib_main_t * vm, int is_main) ASSERT (nm->data_from_advancing_timing_wheel != 0); + if (PREDICT_FALSE (vm->elog_trace_graph_dispatch)) + { + ed = ELOG_DATA (&vlib_global_main.elog_main, ee); + ed->nready_procs = + _vec_len (nm->data_from_advancing_timing_wheel); + } + if (PREDICT_FALSE (_vec_len (nm->data_from_advancing_timing_wheel) > 0)) { diff --git a/src/vlib/main.h b/src/vlib/main.h index 920e5f3f95a..f89ecd3299f 100644 --- a/src/vlib/main.h +++ b/src/vlib/main.h @@ -155,6 +155,9 @@ typedef struct vlib_main_t /* Event logger trace flags */ int elog_trace_api_messages; int elog_trace_cli_commands; + int elog_trace_graph_dispatch; + int elog_trace_graph_circuit; + u32 elog_trace_graph_circuit_node_index; /* Node call and return event types. */ elog_event_type_t *node_call_elog_event_types; |