From 62d53818da5769723515aeacacfc6b447bfb196e Mon Sep 17 00:00:00 2001 From: David Goulet Date: Thu, 1 Sep 2011 16:48:08 -0400 Subject: [PATCH] Fix conflicts in merge Signed-off-by: David Goulet --- benchmark/benchmark.c | 104 +++++++++++++++++++++++++++++++++++++ benchmark/benchmark.h | 2 + benchmark/measures.h | 65 +++++++++++++++++++++++ benchmark/run-boot-time.sh | 2 +- benchmark/runall.sh | 6 +-- ltt-sessiond/main.c | 33 ++++++++++-- ltt-sessiond/shm.c | 12 +++++ 7 files changed, 217 insertions(+), 7 deletions(-) diff --git a/benchmark/benchmark.c b/benchmark/benchmark.c index eda40b215..7e12c9894 100644 --- a/benchmark/benchmark.c +++ b/benchmark/benchmark.c @@ -99,6 +99,110 @@ double bench_get_destroy_session(void) return get_bench_time(time_destroy_session_start, time_destroy_session_end); } +/* + * Complete UST notification process time break down in different actions. + */ +void bench_print_ust_notification(void) +{ + double res, total = 0; + + fprintf(fp, "--- UST notification time ---\n"); + + if (time_ust_notify_mmap_start == 0 || time_ust_notify_mmap_stop == 0) { + goto no_data; + } + + res = get_bench_time(time_ust_notify_mmap_start, + time_ust_notify_mmap_stop); + fprintf(fp, "mmap() call time\n"); + fprintf(fp, "Time: %.20f sec.\n", res); + + total += res; + + if (time_ust_notify_perms_start == 0 || time_ust_notify_perms_stop == 0) { + goto no_data; + } + + res = get_bench_time(time_ust_notify_perms_start, + time_ust_notify_perms_stop); + fprintf(fp, "Setting permissions (chown/chmod)\n"); + fprintf(fp, "Time: %.20f sec.\n", res); + + total += res; + + if (time_ust_notify_shm_start == 0 || time_ust_notify_shm_stop == 0) { + goto no_data; + } + + res = get_bench_time(time_ust_notify_shm_start, + time_ust_notify_shm_stop); + fprintf(fp, "shm_open/ftruncate/fchmod\n"); + fprintf(fp, "Time: %.20f sec.\n", res); + + total += res; + + fprintf(fp, "Global UST nonification time\n"); + fprintf(fp, "Time: %.20f sec.\n", total); + return; + +no_data: + fprintf(fp, "NO DATA\n"); + return; +} + +/* + * This time value is only coherent is an UST application registered. + */ +void bench_print_ust_register(void) +{ + double res, total = 0; + + fprintf(fp, "--- UST registration time ---\n"); + + if (time_ust_register_start == 0 || time_ust_register_stop == 0) { + goto no_data; + } + + res = get_bench_time(time_ust_register_start, time_ust_register_stop); + fprintf(fp, "UST registration received and send to dispatch time\n"); + fprintf(fp, "Time: %.20f sec.\n", res); + + total += res; + + if (time_ust_dispatch_register_start == 0 || + time_ust_dispatch_register_stop == 0) { + goto no_data; + } + + res = get_bench_time(time_ust_dispatch_register_start, + time_ust_dispatch_register_stop); + fprintf(fp, "Dispatch UST registration request time\n"); + fprintf(fp, "Time: %.20f sec.\n", res); + + total += res; + + if (time_ust_manage_register_start == 0 || + time_ust_manage_register_stop == 0) { + goto no_data; + } + + res = get_bench_time(time_ust_manage_register_start, + time_ust_manage_register_stop); + fprintf(fp, "Manage UST registration time\n"); + fprintf(fp, "Time: %.20f sec.\n", res); + + total += res; + + fprintf(fp, "Global time of an UST application registration\n"); + fprintf(fp, "Time: %.20f sec.\n", total); + return; + +no_data: + fprintf(fp, "NO DATA\n"); + return; +} + + /* * Log results of the sessiond boot process. * diff --git a/benchmark/benchmark.h b/benchmark/benchmark.h index c02822e80..2a23fd97e 100644 --- a/benchmark/benchmark.h +++ b/benchmark/benchmark.h @@ -32,6 +32,8 @@ extern FILE *fp; void bench_init(void); void bench_close(void); void bench_print_boot_process(void); +void bench_print_ust_register(void); +void bench_print_ust_notification(void); double bench_get_create_session(void); double bench_get_destroy_session(void); diff --git a/benchmark/measures.h b/benchmark/measures.h index f67f1c49b..25acd7705 100644 --- a/benchmark/measures.h +++ b/benchmark/measures.h @@ -35,6 +35,10 @@ cycles_t time_sessiond_th_kern_poll; cycles_t time_sessiond_th_apps_start; cycles_t time_sessiond_th_apps_poll; +/* Session daemon thread registration apps time */ +cycles_t time_sessiond_th_reg_start; +cycles_t time_sessiond_th_reg_poll; + /* Session daemon thread manage client time */ cycles_t time_sessiond_th_cli_start; cycles_t time_sessiond_th_cli_poll; @@ -47,4 +51,65 @@ cycles_t time_create_session_end; cycles_t time_destroy_session_start; cycles_t time_destroy_session_end; +/* + * UST registration time + * + * Start time is taken *after* the poll() has detected activity on the apps + * socket and right *before* the accept(). There is a malloc() after that + * accept and then we recv() the request from the client. We need to measure + * the complete process. + */ +cycles_t time_ust_register_start; +/* + * The stop time is measured right after the futex() wake up. + */ +cycles_t time_ust_register_stop; + +/* + * UST dispatch registration request time + * + * Start time taken *after* the dequeue which is a blocking call. + */ +cycles_t time_ust_dispatch_register_start; +/* + * Stop time taken *before* the futex() wait so at this point, the registration + * was sent to the manage apps thread. + */ +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; + +/* + * UST notification time (using the shm/futex scheme). Those times were break + * down in seperate time for each big action step. + * + * Start time taken *before* we create/get the SHM mmap. + */ +cycles_t time_ust_notify_apps_start; +/* + * Stop time taken after waiting all processes (futex_wait_update()). + */ +cycles_t time_ust_notify_apps_stop; +/* mmap() call */ +cycles_t time_ust_notify_mmap_start; +cycles_t time_ust_notify_mmap_stop; +/* Permissions time (chmod/chown) */ +cycles_t time_ust_notify_perms_start; +cycles_t time_ust_notify_perms_stop; +/* Fork process */ +cycles_t time_ust_notify_fork_start; +cycles_t time_ust_notify_fork_stop; +/* shm_open call */ +cycles_t time_ust_notify_shm_start; +cycles_t time_ust_notify_shm_stop; + #endif /* _MEASURES_H */ diff --git a/benchmark/run-boot-time.sh b/benchmark/run-boot-time.sh index dabb707b9..ba57d168d 100755 --- a/benchmark/run-boot-time.sh +++ b/benchmark/run-boot-time.sh @@ -23,7 +23,7 @@ BASEDIR=`dirname $0` echo "Session daemon boot process benchmark" -$BASEDIR/../ltt-sessiond/$SESSIOND_BIN --daemonize --quiet +`BENCH_BOOT_PROCESS=1 $BASEDIR/../ltt-sessiond/$SESSIOND_BIN --daemonize --quiet` if [ $? -ne 0 ]; then echo -e '\e[1;31mFAILED\e[0m' exit 1 diff --git a/benchmark/runall.sh b/benchmark/runall.sh index eaf4980b8..d77694482 100755 --- a/benchmark/runall.sh +++ b/benchmark/runall.sh @@ -19,7 +19,7 @@ #### ADD TESTS HERE #### -test_suite=( "run-boot-time.sh" "run-sessions.sh" ) +test_suite=( "run-boot-time.sh" "run-sessions.sh" "run-ust-register.sh" ) #### END TESTS HERE #### @@ -27,7 +27,7 @@ RESULTS_PATH="/tmp/lttng-bench-results.txt" BASEDIR=`dirname $0` if [ -e $RESULTS_PATH ]; then - mv -v $RESULTS_PATH $RESULTS_PATH.`date +%s` + mv -v $RESULTS_PATH "$RESULTS_PATH.`date +%s`.txt" fi echo "" @@ -44,6 +44,6 @@ do echo "" done -mv -v $RESULTS_PATH results-`date +%d%m%Y.%H%M%S`.txt +mv -v $RESULTS_PATH "results-`date +%d%m%Y.%H%M%S`.txt" exit 0 diff --git a/ltt-sessiond/main.c b/ltt-sessiond/main.c index 1bb2c8c1a..2bc64f0af 100644 --- a/ltt-sessiond/main.c +++ b/ltt-sessiond/main.c @@ -303,7 +303,17 @@ static void cleanup(void) /* OUTPUT BENCHMARK RESULTS */ bench_init(); - bench_print_boot_process(); + if (getenv("BENCH_UST_NOTIFY")) { + bench_print_ust_notification(); + } + + if (getenv("BENCH_UST_REGISTER")) { + bench_print_ust_register(); + } + + if (getenv("BENCH_BOOT_PROCESS")) { + bench_print_boot_process(); + } bench_close(); /* END BENCHMARK */ @@ -465,6 +475,8 @@ static int notify_ust_apps(int active) DBG("Notifying applications of session daemon state: %d", active); + tracepoint(ust_notify_apps_start); + /* See shm.c for this call implying mmap, shm and futex calls */ wait_shm_mmap = shm_ust_get_mmap(wait_shm_path, is_root); if (wait_shm_mmap == NULL) { @@ -474,6 +486,8 @@ static int notify_ust_apps(int active) /* Wake waiting process */ futex_wait_update((int32_t *) wait_shm_mmap, active); + tracepoint(ust_notify_apps_stop); + /* Apps notified successfully */ return 0; @@ -970,6 +984,8 @@ static void *thread_manage_apps(void *data) ERR("Apps command pipe poll error"); goto error; case POLLIN: + tracepoint(ust_manage_register_start); + /* Empty pipe */ ret = read(apps_cmd_pipe[0], &ust_cmd, sizeof(ust_cmd)); if (ret < 0 || ret < sizeof(ust_cmd)) { @@ -992,6 +1008,8 @@ static void *thread_manage_apps(void *data) */ unregister_traceable_app(ust_cmd.sock); } + + tracepoint(ust_manage_register_stop); break; } } @@ -1052,6 +1070,8 @@ static void *thread_dispatch_ust_registration(void *data) break; } + tracepoint(ust_dispatch_register_start); + ust_cmd = caa_container_of(node, struct ust_command, node); DBG("Dispatching UST registration pid:%d ppid:%d uid:%d" @@ -1082,6 +1102,8 @@ static void *thread_dispatch_ust_registration(void *data) free(ust_cmd); } while (node != NULL); + tracepoint(ust_dispatch_register_stop); + /* Futex wait on queue. Blocking call on futex() */ futex_nto1_wait(&ust_cmd_queue.futex); } @@ -1104,7 +1126,7 @@ static void *thread_registration_apps(void *data) */ struct ust_command *ust_cmd = NULL; - tracepoint(sessiond_th_apps_start); + tracepoint(sessiond_th_reg_start); DBG("[thread] Manage application registration started"); @@ -1131,7 +1153,7 @@ static void *thread_registration_apps(void *data) while (1) { DBG("Accepting application registration"); - tracepoint(sessiond_th_apps_poll); + tracepoint(sessiond_th_reg_poll); /* Inifinite blocking call, waiting for transmission */ ret = poll(pollfd, 2, -1); @@ -1148,6 +1170,9 @@ static void *thread_registration_apps(void *data) goto error; } + /* Registration starts here. Recording cycles */ + tracepoint(ust_register_start); + sock = lttcomm_accept_unix_sock(apps_sock); if (sock < 0) { goto error; @@ -1196,6 +1221,8 @@ static void *thread_registration_apps(void *data) * Implicit memory barrier with the exchange in cds_wfq_enqueue. */ futex_nto1_wake(&ust_cmd_queue.futex); + + tracepoint(ust_register_stop); } error: diff --git a/ltt-sessiond/shm.c b/ltt-sessiond/shm.c index 7dac1659f..1ccaec5d8 100644 --- a/ltt-sessiond/shm.c +++ b/ltt-sessiond/shm.c @@ -28,6 +28,8 @@ #include +#include "benchmark.h" +#include "measures.h" #include "shm.h" /* @@ -43,6 +45,8 @@ static int get_wait_shm(char *shm_path, size_t mmap_size, int global) int wait_shm_fd, ret; mode_t mode; + tracepoint(ust_notify_perms_start); + /* Default permissions */ mode = S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP; @@ -88,6 +92,9 @@ static int get_wait_shm(char *shm_path, size_t mmap_size, int global) */ umask(~mode); + tracepoint(ust_notify_perms_stop); + + tracepoint(ust_notify_shm_start); /* * Try creating shm (or get rw access). We don't do an exclusive open, * because we allow other processes to create+ftruncate it concurrently. @@ -110,6 +117,8 @@ static int get_wait_shm(char *shm_path, size_t mmap_size, int global) exit(EXIT_FAILURE); } + tracepoint(ust_notify_shm_stop); + DBG("Got the wait shm fd %d", wait_shm_fd); return wait_shm_fd; @@ -139,9 +148,12 @@ char *shm_ust_get_mmap(char *shm_path, int global) goto error; } + tracepoint(ust_notify_mmap_start); + wait_shm_mmap = mmap(NULL, mmap_size, PROT_WRITE | PROT_READ, MAP_SHARED, wait_shm_fd, 0); + tracepoint(ust_notify_mmap_stop); /* close shm fd immediately after taking the mmap reference */ ret = close(wait_shm_fd); if (ret) { -- 2.34.1