From 5fcaccbce7683a6af772d6f37d03fb01cf248a84 Mon Sep 17 00:00:00 2001 From: Mathieu Desnoyers Date: Thu, 20 Nov 2014 07:40:41 +0100 Subject: [PATCH] Fix: add missing synchronization point for before app test case MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit Fixes a race where the application could generate all its events before trace start. Signed-off-by: Mathieu Desnoyers Signed-off-by: Jérémie Galarneau --- .../tools/snapshots/test_ust_streaming | 2 +- tests/regression/tools/snapshots/ust_test | 2 +- tests/regression/tools/streaming/test_ust | 21 +++++-- .../ust/before-after/test_before_after | 11 +++- .../ust/buffers-pid/test_buffers_pid | 26 ++++++-- tests/regression/ust/java-jul/test_java_jul | 11 +++- .../regression/ust/java-log4j/test_java_log4j | 11 +++- .../regression/ust/nprocesses/test_nprocesses | 14 +++-- .../test_periodical_metadata_flush | 2 +- .../testapp/gen-ust-events/gen-ust-events.c | 63 +++++++++++++++---- 10 files changed, 126 insertions(+), 37 deletions(-) diff --git a/tests/regression/tools/snapshots/test_ust_streaming b/tests/regression/tools/snapshots/test_ust_streaming index 55c1087d9..ef38bd599 100755 --- a/tests/regression/tools/snapshots/test_ust_streaming +++ b/tests/regression/tools/snapshots/test_ust_streaming @@ -58,7 +58,7 @@ function snapshot_add_output () # Start trace application and return once one event has been hit. function start_test_app() { - local tmp_file="/tmp/lttng_test_ust.42.file" + local tmp_file=$(mktemp -u) # Start application with a temporary file. $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT $tmp_file & diff --git a/tests/regression/tools/snapshots/ust_test b/tests/regression/tools/snapshots/ust_test index 1541e6e1e..cbc205828 100755 --- a/tests/regression/tools/snapshots/ust_test +++ b/tests/regression/tools/snapshots/ust_test @@ -49,7 +49,7 @@ NUM_TESTS=$(($NUM_TESTS + ($NR_SNAPSHOT * 2))) function start_test_app() { - local tmp_file="/tmp/lttng_test_ust.42.file" + local tmp_file=$(mktemp -u) # Start application with a temporary file. $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT $tmp_file & diff --git a/tests/regression/tools/streaming/test_ust b/tests/regression/tools/streaming/test_ust index 480717515..e6a0bb846 100755 --- a/tests/regression/tools/streaming/test_ust +++ b/tests/regression/tools/streaming/test_ust @@ -49,40 +49,51 @@ function lttng_create_session_uri function test_ust_before_start () { + local file_sync_after_first=$(mktemp -u) + local file_sync_before_last=$(mktemp -u) + diag "Test UST streaming BEFORE tracing starts" lttng_create_session_uri enable_ust_lttng_event $SESSION_NAME $EVENT_NAME # Run 5 times with a 1 second delay - $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT >/dev/null 2>&1 & - - #FIXME: racy missing synchro + $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT ${file_sync_after_first} ${file_sync_before_last} /dev/null 2>&1 & start_lttng_tracing $SESSION_NAME + + touch ${file_sync_before_last} + # Wait for the applications started in background wait stop_lttng_tracing $SESSION_NAME destroy_lttng_session $SESSION_NAME + rm -f ${file_sync_after_first} + rm -f ${file_sync_before_last} } function test_ust_after_start () { + local file_sync_after_first=$(mktemp -u) + diag "Test UST streaming AFTER tracing starts" lttng_create_session_uri enable_ust_lttng_event $SESSION_NAME $EVENT_NAME start_lttng_tracing $SESSION_NAME # Run 5 times with a 1 second delay - $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT >/dev/null 2>&1 + $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT ${file_sync_after_first} >/dev/null 2>&1 - #FIXME: racy missing synchro + while [ ! -f "${file_sync_after_first}" ]; do + sleep 0.5 + done stop_lttng_tracing $SESSION_NAME destroy_lttng_session $SESSION_NAME # Wait for the applications started in background wait + rm -f ${file_sync_after_first} } plan_tests $NUM_TESTS diff --git a/tests/regression/ust/before-after/test_before_after b/tests/regression/ust/before-after/test_before_after index 1535f3627..460b04c4e 100755 --- a/tests/regression/ust/before-after/test_before_after +++ b/tests/regression/ust/before-after/test_before_after @@ -57,22 +57,27 @@ function test_before_apps() function test_after_apps() { local out + local file_sync_after_first=$(mktemp -u) + local file_sync_before_last=$(mktemp -u) create_lttng_session $SESSION_NAME $TRACE_PATH enable_ust_lttng_event $SESSION_NAME $EVENT_NAME - $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT & + $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT ${file_sync_after_first} ${file_sync_before_last} & ok $? "Application started in background." - #FIXME: racy missing synchronization - start_lttng_tracing $SESSION_NAME + touch ${file_sync_before_last} + wait stop_lttng_tracing $SESSION_NAME destroy_lttng_session $SESSION_NAME + rm -f ${file_sync_after_first} + rm -f ${file_sync_before_last} + validate_trace $EVENT_NAME $TRACE_PATH out=$? diff --git a/tests/regression/ust/buffers-pid/test_buffers_pid b/tests/regression/ust/buffers-pid/test_buffers_pid index 0258e890c..c95a4a1f9 100755 --- a/tests/regression/ust/buffers-pid/test_buffers_pid +++ b/tests/regression/ust/buffers-pid/test_buffers_pid @@ -74,22 +74,26 @@ test_after_multiple_apps() { test_before_multiple_apps() { local out local i + local file_sync_after_first=$(mktemp -u) + local file_sync_before_last=$(mktemp -u) diag "Start multiple applications BEFORE tracing is started" for i in `seq 1 5`; do - $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT >/dev/null 2>&1 & + $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT ${file_sync_after_first}_${i} ${file_sync_before_last}_${i} >/dev/null 2>&1 & ok $? "Start application $i for tracing" done - #FIXME: racy missing synchronization - # BEFORE application is spawned create_lttng_session $SESSION_NAME $TRACE_PATH enable_channel_per_pid $SESSION_NAME "channel0" enable_ust_lttng_event $SESSION_NAME $EVENT_NAME "channel0" start_lttng_tracing $SESSION_NAME + for i in `seq 1 5`; do + touch ${file_sync_before_last}_${i} + done + diag "Waiting for applications to end" wait pass "Waiting done" @@ -97,6 +101,11 @@ test_before_multiple_apps() { stop_lttng_tracing $SESSION_NAME destroy_lttng_session $SESSION_NAME + for i in `seq 1 5`; do + rm -f ${file_sync_after_first}_${i} + rm -f ${file_sync_before_last}_${i} + done + out=$(babeltrace $TRACE_PATH | grep $EVENT_NAME | wc -l) if [ $out -eq 0 ]; then fail "Trace validation" @@ -136,6 +145,8 @@ test_after_app() { test_before_app() { local out + local file_sync_after_first=$(mktemp -u) + local file_sync_before_last=$(mktemp -u) diag "Start application BEFORE tracing is started" @@ -145,18 +156,21 @@ test_before_app() { enable_channel_per_pid $SESSION_NAME "channel0" enable_ust_lttng_event $SESSION_NAME $EVENT_NAME "channel0" - $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT & + $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT ${file_sync_after_first} ${file_sync_before_last} & ok $? "Start application to trace" - #FIXME: racy missing synchronization - start_lttng_tracing $SESSION_NAME + touch ${file_sync_before_last} + wait stop_lttng_tracing $SESSION_NAME destroy_lttng_session $SESSION_NAME + rm -f ${file_sync_after_first} + rm -f ${file_sync_before_last} + out=$(babeltrace $TRACE_PATH | grep $EVENT_NAME | wc -l) if [ $out -eq 0 ]; then fail "Trace validation" diff --git a/tests/regression/ust/java-jul/test_java_jul b/tests/regression/ust/java-jul/test_java_jul index d16880f27..d32d9ed45 100755 --- a/tests/regression/ust/java-jul/test_java_jul +++ b/tests/regression/ust/java-jul/test_java_jul @@ -38,6 +38,7 @@ function run_app local finest_tp=$1 local fire_second_tp=$2 + #FIXME: app should have synchro. java -cp $JAVA_CP -Djava.library.path="/usr/local/lib:/usr/lib" $TESTAPP_NAME $NR_ITER $NR_MSEC_WAIT $finest_tp $fire_second_tp >/dev/null 2>&1 } @@ -89,6 +90,9 @@ function enable_jul_filter_loglevel_only() function test_jul_before_start () { + local file_sync_after_first=$(mktemp -u) + local file_sync_before_last=$(mktemp -u) + diag "Test JUL application BEFORE tracing starts" create_lttng_session $SESSION_NAME $TRACE_PATH enable_jul_lttng_event $SESSION_NAME $EVENT_NAME @@ -96,16 +100,19 @@ function test_jul_before_start () # Run 5 times with a 1 second delay run_app_background - #FIXME: racy missing synchronization - start_lttng_tracing $SESSION_NAME + touch ${file_sync_before_last} + # Wait for the applications started in background wait stop_lttng_tracing $SESSION_NAME destroy_lttng_session $SESSION_NAME + rm -f ${file_sync_after_first} + rm -f ${file_sync_before_last} + # Validate test. Expecting all events. trace_match_only $EVENT_NAME $NR_ITER $TRACE_PATH if [ $? -ne 0 ]; then diff --git a/tests/regression/ust/java-log4j/test_java_log4j b/tests/regression/ust/java-log4j/test_java_log4j index 11845a0bb..a0b7cdc0f 100755 --- a/tests/regression/ust/java-log4j/test_java_log4j +++ b/tests/regression/ust/java-log4j/test_java_log4j @@ -39,6 +39,7 @@ function run_app local debug_tp=$1 local fire_second_tp=$2 + # FIXME: test app should have synchro. java -cp $JAVA_CP -Djava.library.path="/usr/local/lib:/usr/lib" $TESTAPP_NAME $NR_ITER $NR_MSEC_WAIT $debug_tp $fire_second_tp >/dev/null 2>&1 } @@ -90,6 +91,9 @@ function enable_log4j_filter_loglevel_only() function test_log4j_before_start () { + local file_sync_after_first=$(mktemp -u) + local file_sync_before_last=$(mktemp -u) + diag "Test LOG4J application BEFORE tracing starts" create_lttng_session $SESSION_NAME $TRACE_PATH enable_log4j_lttng_event $SESSION_NAME $EVENT_NAME @@ -97,16 +101,19 @@ function test_log4j_before_start () # Run 5 times with a 1 second delay run_app_background - #FIXME: racy missing synchronization - start_lttng_tracing $SESSION_NAME + touch ${file_sync_before_last} + # Wait for the applications started in background wait stop_lttng_tracing $SESSION_NAME destroy_lttng_session $SESSION_NAME + rm -f ${file_sync_after_first} + rm -f ${file_sync_before_last} + # Validate test. Expecting all events. trace_match_only $EVENT_NAME $NR_ITER $TRACE_PATH if [ $? -ne 0 ]; then diff --git a/tests/regression/ust/nprocesses/test_nprocesses b/tests/regression/ust/nprocesses/test_nprocesses index ca0f9d416..8eed95fca 100755 --- a/tests/regression/ust/nprocesses/test_nprocesses +++ b/tests/regression/ust/nprocesses/test_nprocesses @@ -46,15 +46,16 @@ start_lttng_sessiond # Start tests. Each is an infinite tracing loop. +file_sync_after_first=$(mktemp -u) +file_sync_before_last=$(mktemp -u) + diag "Starting $NUM_PROCESS test applications" for i in `seq 1 $NUM_PROCESS` do - $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT >/dev/null 2>&1 & + $TESTAPP_BIN $NR_ITER $NR_USEC_WAIT ${file_sync_after_first} ${file_sync_before_last} >/dev/null 2>&1 & APPS_PID="${APPS_PID} ${!}" done -#FIXME: racy missing synchronization - diag "Waiting for applications to be registered to sessiond" reg_app_count=0 @@ -72,13 +73,15 @@ create_lttng_session $SESSION_NAME $TRACE_PATH enable_ust_lttng_event $SESSION_NAME $EVENT_NAME start_lttng_tracing $SESSION_NAME +touch ${file_sync_before_last} + # We don't validate whether the applications have traced here, rather # just that they registered to sessiond (above). stop_lttng_tracing $SESSION_NAME destroy_lttng_session $SESSION_NAME -#FIXME/TODO: add validation after fixing racy synchroniaation +#TODO: add trace validation. rm -rf $TRACE_PATH @@ -90,4 +93,7 @@ done APPS_PID= pass "Stopped all spawned applications" +rm -f ${file_sync_after_first} +rm -f ${file_sync_before_last} + stop_lttng_sessiond diff --git a/tests/regression/ust/periodical-metadata-flush/test_periodical_metadata_flush b/tests/regression/ust/periodical-metadata-flush/test_periodical_metadata_flush index 53db813e1..7937fa27d 100755 --- a/tests/regression/ust/periodical-metadata-flush/test_periodical_metadata_flush +++ b/tests/regression/ust/periodical-metadata-flush/test_periodical_metadata_flush @@ -27,7 +27,7 @@ SESSION_NAME="periodical-flush" EVENT_NAME="tp:tptest" BIN_NAME="gen-nevents" NUM_TESTS=38 -APP_TMP_FILE="/tmp/lttng_test_ust.42.file" +APP_TMP_FILE=$(mktemp -u) APPS_PID= source $TESTDIR/utils/utils.sh diff --git a/tests/utils/testapp/gen-ust-events/gen-ust-events.c b/tests/utils/testapp/gen-ust-events/gen-ust-events.c index 3be0f0f11..11327d5f4 100644 --- a/tests/utils/testapp/gen-ust-events/gen-ust-events.c +++ b/tests/utils/testapp/gen-ust-events/gen-ust-events.c @@ -15,6 +15,7 @@ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA */ +#define _GNU_SOURCE #define _LGPL_SOURCE #include #include @@ -28,15 +29,21 @@ #include #include #include +#include +#include +#include #define TRACEPOINT_DEFINE #include "tp.h" void create_file(const char *path) { + static bool file_created = false; int ret; - assert(path); + if (!path || file_created) { + return; + } ret = creat(path, S_IRWXU); if (ret < 0) { @@ -45,6 +52,30 @@ void create_file(const char *path) } (void) close(ret); + file_created = true; +} + +static +void wait_on_file(const char *path) +{ + if (!path) { + return; + } + for (;;) { + int ret; + struct stat buf; + + ret = stat(path, &buf); + if (ret == -1 && errno == ENOENT) { + (void) poll(NULL, 0, 10); /* 10 ms delay */ + continue; /* retry */ + } + if (ret) { + perror("stat"); + exit(EXIT_FAILURE); + } + break; /* found */ + } } int main(int argc, char **argv) @@ -56,8 +87,8 @@ int main(int argc, char **argv) float flt = 2222.0; int nr_iter = 100; useconds_t nr_usec = 0; - char *tmp_file_path = NULL; - bool file_created = false; + char *after_first_event_file_path = NULL; + char *before_last_event_file_path = NULL; if (argc >= 2) { /* @@ -72,22 +103,30 @@ int main(int argc, char **argv) } if (argc >= 4) { - tmp_file_path = argv[3]; + after_first_event_file_path = argv[3]; + } + + if (argc >= 5) { + before_last_event_file_path = argv[4]; } for (i = 0; nr_iter < 0 || i < nr_iter; i++) { + if (nr_iter >= 0 && i == nr_iter - 1) { + /* + * Wait on synchronization before writing last + * event. + */ + wait_on_file(before_last_event_file_path); + } netint = htonl(i); - tracepoint(tp, tptest, i, netint, values, text, strlen(text), dbl, - flt); + tracepoint(tp, tptest, i, netint, values, text, + strlen(text), dbl, flt); /* - * First loop we create the file if asked to indicate that at least one - * tracepoint has been hit. + * First loop we create the file if asked to indicate + * that at least one tracepoint has been hit. */ - if (!file_created && tmp_file_path) { - create_file(tmp_file_path); - file_created = true; - } + create_file(after_first_event_file_path); usleep(nr_usec); } -- 2.34.1