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 <david.goulet@polymtl.ca>

diff --git a/benchmark/benchmark.c b/benchmark/benchmark.c
index 7e12c98946a9df40b2241c067cc58795e15e14a7..8fbe8ad78416bcfdd2843ef6b986fa486e9ab096 100644 (file)
--- 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 9f39805edb838a8c7f41a1b68069811e8e09aaac..adbc00f1415eeea8c864f339c18fa200ab4742e6 100755 (executable)
Binary files a/benchmark/hello and b/benchmark/hello differ

diff --git a/benchmark/measures.h b/benchmark/measures.h
index 25acd77059c6ac54e18ee64cd46dbe488c0c1573..91809e1ac40cd976f98520e1181c73facac363d9 100644 (file)
--- 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 c17a4fd26165c60556ff08ff210a9a61d8d8df5e..bbf0edca08a4f1ae6ec8ba3e16f69d3bb03e7845 100755 (executable)
--- 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 be1544ed551fb04e732d22e97551cd8ac9586e0d..0759398d7c20e67180f17c3507acbb52e78f1f5e 100755 (executable)
--- 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 61c76f4db130b2c47dd56d9cc7061ac85fb5d851..0640cfd722725d59e66d0e388964efb4d3428fe7 100755 (executable)
--- 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 2bc64f0af1351430b79bece562b6113a54c96209..30698835459708bed2f4345c2dd6b06c9030dd34 100644 (file)
--- 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) {