From 88c6e0086b15963b4d1a268e1fe8bbc2bcd9779c Mon Sep 17 00:00:00 2001 From: Dave Barach Date: Sun, 30 Sep 2018 15:54:06 -0400 Subject: [PATCH] vlib: barrier sync elog tracing improvements Change-Id: I2d3b8d5a7192ff68bee443a99346ecb807b2d833 Signed-off-by: Damjan Marion Signed-off-by: Dave Barach --- src/vlib/threads.c | 134 +++++++++---------------------------------------- src/vlib/threads.h | 92 ++++++++++++++++++++++++--------- src/vlib/threads_cli.c | 22 ++++++++ src/vpp/api/api_main.c | 1 + 4 files changed, 114 insertions(+), 135 deletions(-) diff --git a/src/vlib/threads.c b/src/vlib/threads.c index 1972886a78b..def8927e29f 100644 --- a/src/vlib/threads.c +++ b/src/vlib/threads.c @@ -42,11 +42,6 @@ vlib_thread_main_t vlib_thread_main; * imapacts observed timings. */ -#ifdef BARRIER_TRACING - /* - * Output of barrier tracing can be to syslog or elog as suits - */ -#ifdef BARRIER_TRACING_ELOG static u32 elog_id_for_msg_name (const char *msg_name) { @@ -69,24 +64,22 @@ elog_id_for_msg_name (const char *msg_name) return r; } - /* - * elog Barrier trace functions, which are nulled out if BARRIER_TRACING isn't - * defined - */ - static inline void barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed) { + if (!vlib_worker_threads->barrier_elog_enabled) + return; + /* *INDENT-OFF* */ ELOG_TYPE_DECLARE (e) = { - .format = "barrier <%d#%s(O:%dus:%dus)(%dus)", - .format_args = "i4T4i4i4i4", + .format = "bar-trace-%s-#%d", + .format_args = "T4i4", }; /* *INDENT-ON* */ struct { - u32 count, caller, t_entry, t_open, t_closed; + u32 caller, count, t_entry, t_open, t_closed; } *ed = 0; ed = ELOG_DATA (&vlib_global_main.elog_main, e); @@ -100,57 +93,64 @@ barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed) static inline void barrier_trace_sync_rec (f64 t_entry) { + if (!vlib_worker_threads->barrier_elog_enabled) + return; + /* *INDENT-OFF* */ ELOG_TYPE_DECLARE (e) = { - .format = "barrier <%d(%dus)%s", - .format_args = "i4i4T4", + .format = "bar-syncrec-%s-#%d", + .format_args = "T4i4", }; /* *INDENT-ON* */ struct { - u32 depth, t_entry, caller; + u32 caller, depth; } *ed = 0; ed = ELOG_DATA (&vlib_global_main.elog_main, e); ed->depth = (int) vlib_worker_threads[0].recursion_level - 1; - ed->t_entry = (int) (1000000.0 * t_entry); ed->caller = elog_id_for_msg_name (vlib_worker_threads[0].barrier_caller); } static inline void barrier_trace_release_rec (f64 t_entry) { + if (!vlib_worker_threads->barrier_elog_enabled) + return; + /* *INDENT-OFF* */ ELOG_TYPE_DECLARE (e) = { - .format = "barrier (%dus)%d>", - .format_args = "i4i4", + .format = "bar-relrrec-#%d", + .format_args = "i4", }; /* *INDENT-ON* */ struct { - u32 t_entry, depth; + u32 depth; } *ed = 0; ed = ELOG_DATA (&vlib_global_main.elog_main, e); - ed->t_entry = (int) (1000000.0 * t_entry); ed->depth = (int) vlib_worker_threads[0].recursion_level; } static inline void barrier_trace_release (f64 t_entry, f64 t_closed_total, f64 t_update_main) { + if (!vlib_worker_threads->barrier_elog_enabled) + return; + /* *INDENT-OFF* */ ELOG_TYPE_DECLARE (e) = { - .format = "barrier (%dus){%d}(C:%dus)#%d>", + .format = "bar-rel-#%d-e%d-u%d-t%d", .format_args = "i4i4i4i4", }; /* *INDENT-ON* */ struct { - u32 t_entry, t_update_main, t_closed_total, count; + u32 count, t_entry, t_update_main, t_closed_total; } *ed = 0; ed = ELOG_DATA (&vlib_global_main.elog_main, e); @@ -162,94 +162,6 @@ barrier_trace_release (f64 t_entry, f64 t_closed_total, f64 t_update_main) /* Reset context for next trace */ vlib_worker_threads[0].barrier_context = NULL; } -#else -char barrier_trace[65536]; -char *btp = barrier_trace; - - /* - * syslog Barrier trace functions, which are nulled out if BARRIER_TRACING - * isn't defined - */ - - -static inline void -barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed) -{ - btp += sprintf (btp, "<%u#%s", - (unsigned int) vlib_worker_threads[0].barrier_sync_count, - vlib_worker_threads[0].barrier_caller); - - if (vlib_worker_threads[0].barrier_context) - { - btp += sprintf (btp, "[%s]", vlib_worker_threads[0].barrier_context); - - } - - btp += sprintf (btp, "(O:%dus:%dus)(%dus):", - (int) (1000000.0 * t_entry), - (int) (1000000.0 * t_open), (int) (1000000.0 * t_closed)); - -} - -static inline void -barrier_trace_sync_rec (f64 t_entry) -{ - btp += sprintf (btp, "<%u(%dus)%s:", - (int) vlib_worker_threads[0].recursion_level - 1, - (int) (1000000.0 * t_entry), - vlib_worker_threads[0].barrier_caller); -} - -static inline void -barrier_trace_release_rec (f64 t_entry) -{ - btp += sprintf (btp, ":(%dus)%u>", (int) (1000000.0 * t_entry), - (int) vlib_worker_threads[0].recursion_level); -} - -static inline void -barrier_trace_release (f64 t_entry, f64 t_closed_total, f64 t_update_main) -{ - - btp += sprintf (btp, ":(%dus)", (int) (1000000.0 * t_entry)); - if (t_update_main > 0) - { - btp += sprintf (btp, "{%dus}", (int) (1000000.0 * t_update_main)); - } - - btp += sprintf (btp, "(C:%dus)#%u>", - (int) (1000000.0 * t_closed_total), - (int) vlib_worker_threads[0].barrier_sync_count); - - /* Dump buffer to syslog, and reset for next trace */ - fformat (stderr, "BTRC %s\n", barrier_trace); - btp = barrier_trace; - vlib_worker_threads[0].barrier_context = NULL; -} -#endif -#else - - /* Null functions for default case where barrier tracing isn't used */ -static inline void -barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed) -{ -} - -static inline void -barrier_trace_sync_rec (f64 t_entry) -{ -} - -static inline void -barrier_trace_release_rec (f64 t_entry) -{ -} - -static inline void -barrier_trace_release (f64 t_entry, f64 t_closed_total, f64 t_update_main) -{ -} -#endif uword os_get_nthreads (void) diff --git a/src/vlib/threads.h b/src/vlib/threads.h index 17944536b6c..7de0412362e 100644 --- a/src/vlib/threads.h +++ b/src/vlib/threads.h @@ -18,22 +18,6 @@ #include #include -/* - * To enable detailed tracing of barrier usage, including call stacks and - * timings, define BARRIER_TRACING here or in relevant TAGS. If also used - * with CLIB_DEBUG, timing will _not_ be representative of normal code - * execution. - * - */ - -// #define BARRIER_TRACING 1 - -/* - * Two options for barrier tracing output: syslog & elog. - */ - -// #define BARRIER_TRACING_ELOG 1 - extern vlib_main_t **vlib_mains; void vlib_set_thread_name (char *name); @@ -118,10 +102,9 @@ typedef struct vlib_thread_registration_t *registration; u8 *name; u64 barrier_sync_count; -#ifdef BARRIER_TRACING + u8 barrier_elog_enabled; const char *barrier_caller; const char *barrier_context; -#endif volatile u32 *node_reforks_required; long lwp; @@ -216,12 +199,7 @@ u32 vlib_frame_queue_main_init (u32 node_index, u32 frame_queue_nelts); #define BARRIER_SYNC_TIMEOUT (1.0) #endif -#ifdef BARRIER_TRACING #define vlib_worker_thread_barrier_sync(X) {vlib_worker_threads[0].barrier_caller=__FUNCTION__;vlib_worker_thread_barrier_sync_int(X);} -#else -#define vlib_worker_thread_barrier_sync(X) vlib_worker_thread_barrier_sync_int(X) -#endif - void vlib_worker_thread_barrier_sync_int (vlib_main_t * vm); void vlib_worker_thread_barrier_release (vlib_main_t * vm); @@ -410,7 +388,30 @@ vlib_worker_thread_barrier_check (void) { if (PREDICT_FALSE (*vlib_worker_threads->wait_at_barrier)) { - vlib_main_t *vm; + vlib_main_t *vm = vlib_get_main (); + u32 thread_index = vm->thread_index; + f64 t = vlib_time_now (vm); + + if (PREDICT_FALSE (vlib_worker_threads->barrier_elog_enabled)) + { + vlib_worker_thread_t *w = vlib_worker_threads + thread_index; + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = { + .format = "barrier-wait-thread-%d", + .format_args = "i4", + }; + /* *INDENT-ON* */ + + struct + { + u32 thread_index; + } __clib_packed *ed; + + ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main, e, + w->elog_track); + ed->thread_index = thread_index; + } + clib_smp_atomic_add (vlib_worker_threads->workers_at_barrier, 1); if (CLIB_DEBUG > 0) { @@ -425,12 +426,55 @@ vlib_worker_thread_barrier_check (void) if (PREDICT_FALSE (*vlib_worker_threads->node_reforks_required)) { + if (PREDICT_FALSE (vlib_worker_threads->barrier_elog_enabled)) + { + t = vlib_time_now (vm) - t; + vlib_worker_thread_t *w = vlib_worker_threads + thread_index; + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = { + .format = "barrier-refork-thread-%d", + .format_args = "i4", + }; + /* *INDENT-ON* */ + + struct + { + u32 thread_index; + } __clib_packed *ed; + + ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main, e, + w->elog_track); + ed->thread_index = thread_index; + } + vlib_worker_thread_node_refork (); clib_smp_atomic_add (vlib_worker_threads->node_reforks_required, -1); while (*vlib_worker_threads->node_reforks_required) ; } + if (PREDICT_FALSE (vlib_worker_threads->barrier_elog_enabled)) + { + t = vlib_time_now (vm) - t; + vlib_worker_thread_t *w = vlib_worker_threads + thread_index; + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = { + .format = "barrier-released-thread-%d: %dus", + .format_args = "i4i4", + }; + /* *INDENT-ON* */ + + struct + { + u32 thread_index; + u32 duration; + } __clib_packed *ed; + + ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main, e, + w->elog_track); + ed->thread_index = thread_index; + ed->duration = (int) (1000000.0 * t); + } } } diff --git a/src/vlib/threads_cli.c b/src/vlib/threads_cli.c index 02bdea5cb0f..bb9ddbc6e3c 100644 --- a/src/vlib/threads_cli.c +++ b/src/vlib/threads_cli.c @@ -574,6 +574,28 @@ VLIB_CLI_COMMAND (cmd_test_frame_queue_threshold,static) = { }; /* *INDENT-ON* */ +static clib_error_t * +test_threads_barrier_elog_command_fn (vlib_main_t * vm, + unformat_input_t * input, + vlib_cli_command_t * cmd) +{ + if (unformat (input, "enable")) + vlib_worker_threads->barrier_elog_enabled = 1; + else if (unformat (input, "disable")) + vlib_worker_threads->barrier_elog_enabled = 0; + else + return clib_error_return (0, "please choose enable or disable"); + return 0; +} + +/* *INDENT-OFF* */ +VLIB_CLI_COMMAND (test_elog_vector_length_trigger, static) = +{ + .path = "test threads barrier-elog", + .short_help = "test threads barrier-elog", + .function = test_threads_barrier_elog_command_fn, +}; +/* *INDENT-ON* */ /* * fd.io coding-style-patch-verification: ON diff --git a/src/vpp/api/api_main.c b/src/vpp/api/api_main.c index 0e05d3ed78e..8f33f042c5d 100644 --- a/src/vpp/api/api_main.c +++ b/src/vpp/api/api_main.c @@ -229,6 +229,7 @@ VLIB_CLI_COMMAND (api_command, static) = .path = "binary-api", .short_help = "binary-api [help] []", .function = api_command_fn, + .is_mp_safe = 1, }; /* *INDENT-ON* */ -- 2.16.6