From: David Goulet Date: Tue, 6 Sep 2011 14:52:03 +0000 (-0400) Subject: More fine grained time for ust register/notify X-Git-Url: http://git.lttng.org./?a=commitdiff_plain;h=85c434ee82d47b46f3857540e983523b7178061b;p=lttng-tools.git More fine grained time for ust register/notify Also, fix the benchmark script not to hang or use useless command to wait for the session daemon. Signed-off-by: David Goulet --- diff --git a/benchmark/benchmark.c b/benchmark/benchmark.c index 7e12c9894..8fbe8ad78 100644 --- a/benchmark/benchmark.c +++ b/benchmark/benchmark.c @@ -181,14 +181,25 @@ void bench_print_ust_register(void) total += res; - if (time_ust_manage_register_start == 0 || - time_ust_manage_register_stop == 0) { - goto no_data; - } + fprintf(fp, "--> Manage registration breakdown\n"); + + res = get_bench_time(time_ust_register_read_start, + time_ust_register_read_stop); + fprintf(fp, "read() from pipe time\n"); + fprintf(fp, "Time: %.20f sec.\n", res); - res = get_bench_time(time_ust_manage_register_start, - time_ust_manage_register_stop); - fprintf(fp, "Manage UST registration time\n"); + total += res; + + res = get_bench_time(time_ust_register_add_start, + time_ust_register_add_stop); + fprintf(fp, "register_traceable_app time\n"); + fprintf(fp, "Time: %.20f sec.\n", res); + + total += res; + + res = get_bench_time(time_ust_register_done_start, + time_ust_register_done_stop); + fprintf(fp, "send register done command time\n"); fprintf(fp, "Time: %.20f sec.\n", res); total += res; @@ -217,31 +228,45 @@ void bench_print_boot_process(void) res = get_bench_time(time_sessiond_boot_start, time_sessiond_boot_end); - fprintf(fp, "Boot time inside main() from start to first pthread_join (blocking state)\n"); + fprintf(fp, "Inside main() from start to first pthread_join" + "(blocking state)\n"); + fprintf(fp, "Time: %.20f sec.\n", res); + + global_boot_time += res; + + res = get_bench_time(time_sessiond_th_kern_start, + time_sessiond_th_kern_poll); + + fprintf(fp, "Kernel thread from start to poll() (ready state)\n"); fprintf(fp, "Time: %.20f sec.\n", res); global_boot_time += res; - res = get_bench_time(time_sessiond_th_kern_start, time_sessiond_th_kern_poll); + res = get_bench_time(time_sessiond_th_apps_start, + time_sessiond_th_apps_poll); - fprintf(fp, "Boot time of the kernel thread from start to poll() (ready state)\n"); + fprintf(fp, "Application thread from start to poll() (ready state)\n"); fprintf(fp, "Time: %.20f sec.\n", res); global_boot_time += res; - res = get_bench_time(time_sessiond_th_apps_start, time_sessiond_th_apps_poll); + res = get_bench_time(time_sessiond_th_cli_start, + time_sessiond_th_cli_poll); - fprintf(fp, "Boot time of the application thread from start to poll() (ready state)\n"); + fprintf(fp, "Client thread from start to poll() (ready state)\n"); fprintf(fp, "Time: %.20f sec.\n", res); global_boot_time += res; - res = get_bench_time(time_sessiond_th_cli_start, time_sessiond_th_cli_poll); + res = get_bench_time(time_sessiond_th_dispatch_start, + time_sessiond_th_dispatch_block); - fprintf(fp, "Boot time of the client thread from start to poll() (ready state)\n"); + fprintf(fp, "Dispatch registration thread from start to poll()" + "(ready state)\n"); fprintf(fp, "Time: %.20f sec.\n", res); global_boot_time += res; - fprintf(fp, "Global Boot Time of ltt-sessiond: %0.20f sec.\n", global_boot_time); + fprintf(fp, "Global Boot Time\n"); + fprintf(fp, "Time: %0.20f sec.\n", global_boot_time); } diff --git a/benchmark/hello b/benchmark/hello index 9f39805ed..adbc00f14 100755 Binary files a/benchmark/hello and b/benchmark/hello differ diff --git a/benchmark/measures.h b/benchmark/measures.h index 25acd7705..91809e1ac 100644 --- a/benchmark/measures.h +++ b/benchmark/measures.h @@ -39,6 +39,10 @@ cycles_t time_sessiond_th_apps_poll; cycles_t time_sessiond_th_reg_start; cycles_t time_sessiond_th_reg_poll; +/* Session daemon thread registration apps time */ +cycles_t time_sessiond_th_dispatch_start; +cycles_t time_sessiond_th_dispatch_block; + /* Session daemon thread manage client time */ cycles_t time_sessiond_th_cli_start; cycles_t time_sessiond_th_cli_poll; @@ -79,14 +83,16 @@ cycles_t time_ust_dispatch_register_stop; /* * UST managing registration time - * - * Start *before* the thread reads the pipe containing the registration data. - */ -cycles_t time_ust_manage_register_start; -/* - * Stop time taken *after* the register command is sent to the application. */ -cycles_t time_ust_manage_register_stop; +/* read() from pipe */ +cycles_t time_ust_register_read_start; +cycles_t time_ust_register_read_stop; +/* register_traceable_app() time */ +cycles_t time_ust_register_add_start; +cycles_t time_ust_register_add_stop; +/* send register done command */ +cycles_t time_ust_register_done_start; +cycles_t time_ust_register_done_stop; /* * UST notification time (using the shm/futex scheme). Those times were break diff --git a/benchmark/run-boot-time.sh b/benchmark/run-boot-time.sh index c17a4fd26..bbf0edca0 100755 --- a/benchmark/run-boot-time.sh +++ b/benchmark/run-boot-time.sh @@ -21,29 +21,31 @@ SESSIOND_BIN="ltt-sessiond" RESULTS_PATH="/tmp/lttng-bench-results.txt" BASEDIR=`dirname $0` -echo "Session daemon boot process benchmark" +echo "Starting session daemon" -`BENCH_BOOT_PROCESS=1 $BASEDIR/../ltt-sessiond/$SESSIOND_BIN --daemonize --quiet` -if [ $? -ne 0 ]; then +BENCH_BOOT_PROCESS=1 $BASEDIR/../ltt-sessiond/$SESSIOND_BIN -v >/dev/null 2>&1 & + +PID_SESSIOND=$! +if [ -z $PID_SESSIOND ]; then echo -e '\e[1;31mFAILED\e[0m' exit 1 else echo -e "\e[1;32mOK\e[0m" + echo "PID session daemon: $PID_SESSIOND" fi -PID_SESSIOND=`pidof lt-$SESSIOND_BIN` - # Wait for the benchmark to run echo -n "Waiting." sleep 1 echo -n "." sleep 1 -echo -n "." +echo "." sleep 1 kill $PID_SESSIOND -# Trick to wait for a PID which is not a child -tail --pid=$PID_SESSIOND --quiet -F $RESULTS_PATH > /dev/null 2>&1 +wait $PID_SESSIOND + +echo "Benchmarks done in $RESULTS_PATH" exit 0 diff --git a/benchmark/run-ust-notify.sh b/benchmark/run-ust-notify.sh index be1544ed5..0759398d7 100755 --- a/benchmark/run-ust-notify.sh +++ b/benchmark/run-ust-notify.sh @@ -23,19 +23,19 @@ BASEDIR=`dirname $0` echo "Session daemon boot" -`BENCH_UST_NOTIFY=1 $BASEDIR/../ltt-sessiond/$SESSIOND_BIN --daemonize --quiet` -if [ $? -ne 0 ]; then +BENCH_UST_NOTIFY=1 $BASEDIR/../ltt-sessiond/$SESSIOND_BIN -v >/dev/null 2>&1 & + +PID_SESSIOND=$! +if [ -z $PID_SESSIOND ]; then echo -e '\e[1;31mFAILED\e[0m' exit 1 else echo -e "\e[1;32mOK\e[0m" + echo "PID session daemon: $PID_SESSIOND" fi -PID_SESSIOND=`pidof lt-$SESSIOND_BIN` - kill $PID_SESSIOND -# Trick to wait for a PID which is not a child -tail --pid=$PID_SESSIOND --quiet -F $RESULTS_PATH > /dev/null 2>&1 +wait $PID_SESSIOND exit 0 diff --git a/benchmark/run-ust-register.sh b/benchmark/run-ust-register.sh index 61c76f4db..0640cfd72 100755 --- a/benchmark/run-ust-register.sh +++ b/benchmark/run-ust-register.sh @@ -22,17 +22,17 @@ RESULTS_PATH="/tmp/lttng-bench-results.txt" BASEDIR=`dirname $0` echo "Session daemon boot" +BENCH_UST_REGISTER=1 $BASEDIR/../ltt-sessiond/$SESSIOND_BIN -v >/dev/null 2>&1 & -`BENCH_UST_REGISTER=1 $BASEDIR/../ltt-sessiond/$SESSIOND_BIN --daemonize --quiet` -if [ $? -ne 0 ]; then +PID_SESSIOND=$! +if [ -z $PID_SESSIOND ]; then echo -e '\e[1;31mFAILED\e[0m' exit 1 else echo -e "\e[1;32mOK\e[0m" + echo "PID session daemon: $PID_SESSIOND" fi -PID_SESSIOND=`pidof lt-$SESSIOND_BIN` - # Wait for sessiond to settle sleep 2 @@ -41,7 +41,6 @@ UST_AUTOPROBE=1 UST_TRACE=1 ./$BASEDIR/hello kill $PID_SESSIOND -# Trick to wait for a PID which is not a child -tail --pid=$PID_SESSIOND --quiet -F $RESULTS_PATH > /dev/null 2>&1 +wait $PID_SESSIOND exit 0 diff --git a/ltt-sessiond/main.c b/ltt-sessiond/main.c index 2bc64f0af..306988354 100644 --- a/ltt-sessiond/main.c +++ b/ltt-sessiond/main.c @@ -937,6 +937,8 @@ static void *thread_manage_apps(void *data) struct pollfd *pollfd = NULL; struct ust_command ust_cmd; + tracepoint(sessiond_th_apps_start); + DBG("[thread] Manage application started"); ust_cmd.sock = -1; @@ -967,6 +969,8 @@ static void *thread_manage_apps(void *data) DBG("Apps thread polling on %d fds", nb_fd); + tracepoint(sessiond_th_apps_poll); + /* Inifinite blocking call, waiting for transmission */ ret = poll(pollfd, nb_fd, -1); if (ret < 0) { @@ -984,7 +988,7 @@ static void *thread_manage_apps(void *data) ERR("Apps command pipe poll error"); goto error; case POLLIN: - tracepoint(ust_manage_register_start); + tracepoint(ust_register_read_start); /* Empty pipe */ ret = read(apps_cmd_pipe[0], &ust_cmd, sizeof(ust_cmd)); @@ -993,13 +997,18 @@ static void *thread_manage_apps(void *data) goto error; } + tracepoint(ust_register_read_stop); + + tracepoint(ust_register_add_start); /* Register applicaton to the session daemon */ ret = register_traceable_app(&ust_cmd.reg_msg, ust_cmd.sock); if (ret < 0) { /* Only critical ENOMEM error can be returned here */ goto error; } + tracepoint(ust_register_add_stop); + tracepoint(ust_register_done_start); ret = ustctl_register_done(ust_cmd.sock); if (ret < 0) { /* @@ -1009,7 +1018,7 @@ static void *thread_manage_apps(void *data) unregister_traceable_app(ust_cmd.sock); } - tracepoint(ust_manage_register_stop); + tracepoint(ust_register_done_stop); break; } } @@ -1055,6 +1064,8 @@ static void *thread_dispatch_ust_registration(void *data) struct cds_wfq_node *node; struct ust_command *ust_cmd = NULL; + tracepoint(sessiond_th_dispatch_start); + DBG("[thread] Dispatch UST command started"); while (!dispatch_thread_exit) { @@ -1062,6 +1073,8 @@ static void *thread_dispatch_ust_registration(void *data) futex_nto1_prepare(&ust_cmd_queue.futex); do { + tracepoint(sessiond_th_dispatch_block); + /* Dequeue command for registration */ node = cds_wfq_dequeue_blocking(&ust_cmd_queue.queue); if (node == NULL) {