summaryrefslogtreecommitdiffstats
path: root/src/vlib
diff options
context:
space:
mode:
authorDave Barach <dave@barachs.net>2018-09-30 15:54:06 -0400
committerDave Barach <dave@barachs.net>2018-09-30 15:55:09 -0400
commit88c6e0086b15963b4d1a268e1fe8bbc2bcd9779c (patch)
tree4a084fdfab1d4390753402a0972cfddc33c52be5 /src/vlib
parent762d83c198c6c24cce4eb94a6d027f520d0b8383 (diff)
vlib: barrier sync elog tracing improvements
Change-Id: I2d3b8d5a7192ff68bee443a99346ecb807b2d833 Signed-off-by: Damjan Marion <damarion@cisco.com> Signed-off-by: Dave Barach <dave@barachs.net>
Diffstat (limited to 'src/vlib')
-rw-r--r--src/vlib/threads.c134
-rw-r--r--src/vlib/threads.h92
-rw-r--r--src/vlib/threads_cli.c22
3 files changed, 113 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 <vlib/main.h>
#include <linux/sched.h>
-/*
- * 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