diff options
-rw-r--r-- | .gitignore | 1 | ||||
-rw-r--r-- | ChangeLog.txt | 10 | ||||
-rw-r--r-- | Makefile.in | 24 | ||||
-rwxr-xr-x | configure | 28 | ||||
-rw-r--r-- | enums/debug_type.in | 2 | ||||
-rwxr-xr-x | makewrappers | 5 | ||||
-rw-r--r-- | ports/common/pseudo_wrappers.c | 32 | ||||
-rw-r--r-- | ports/darwin/pseudo_wrappers.c | 3 | ||||
-rw-r--r-- | ports/linux/guts/__fxstatat64.c | 2 | ||||
-rw-r--r-- | ports/linux/xattr/pseudo_wrappers.c | 4 | ||||
-rw-r--r-- | pseudo.1 | 8 | ||||
-rw-r--r-- | pseudo.h | 10 | ||||
-rw-r--r-- | pseudo_client.c | 257 | ||||
-rw-r--r-- | pseudo_profile.c | 64 | ||||
-rw-r--r-- | pseudo_server.c | 1 | ||||
-rw-r--r-- | pseudo_util.c | 3 | ||||
-rw-r--r-- | pseudo_wrappers.c | 16 | ||||
-rw-r--r-- | templates/wrapfuncs.c | 5 |
18 files changed, 408 insertions, 67 deletions
@@ -6,6 +6,7 @@ pseudo_wrapper_table.c pseudo pseudodb pseudolog +pseudo_profile pseudo_tables.c pseudo_tables.h port_wrappers.c diff --git a/ChangeLog.txt b/ChangeLog.txt index 7f51dbd..ff27760 100644 --- a/ChangeLog.txt +++ b/ChangeLog.txt @@ -1,3 +1,13 @@ +2015-08-17: + * (seebs) profiling improvements + +2015-08-14: + * (seebs) profiling cleanup, add profiler to gitignore + * Start using 1.7.0 version for internal work. + +2015-08-13: + * (seebs) client profiling stuff (first pass) + 2015-07-17: * (seebs) allow actually making fifos without randomly closing fd 0 * 1.6.7 diff --git a/Makefile.in b/Makefile.in index 7379648..1c8bd6a 100644 --- a/Makefile.in +++ b/Makefile.in @@ -26,12 +26,19 @@ SQLITE_LIB=@SQLITE_LIB@ SQLITE_MEMORY=@SQLITE_MEMORY@ FORCE_ASYNC=@FORCE_ASYNC@ XATTR=@XATTR@ +ifeq (true,@PROFILING@) + PROFILING=-DPSEUDO_PROFILING + PSEUDO_PROFILE=$(BIN)/pseudo_profile +else + PROFILING= + PSEUDO_PROFILE= +endif PASSWD_FALLBACK=@PASSWD_FALLBACK@ BITS=@BITS@ ARCH_FLAGS=@ARCH_FLAGS@ MARK64=@MARK64@ RPATH=@RPATH@ -VERSION=1.6.7 +VERSION=1.7.0 LIB=@LIB@ BIN=bin @@ -41,7 +48,7 @@ LOCALSTATEDIR=$(PREFIX)/$(LOCALSTATE) CFLAGS_BASE=-pipe -std=gnu99 -Wall -W -Wextra CFLAGS_CODE=-fPIC -D_LARGEFILE64_SOURCE -D_ATFILE_SOURCE $(ARCH_FLAGS) -CFLAGS_DEFS=-DPSEUDO_PREFIX='"$(PREFIX)"' -DPSEUDO_SUFFIX='"$(SUFFIX)"' -DPSEUDO_BINDIR='"$(BIN)"' -DPSEUDO_LIBDIR='"$(LIB)"' -DPSEUDO_LOCALSTATEDIR='"$(LOCALSTATE)"' -DPSEUDO_VERSION='"$(VERSION)"' $(SQLITE_MEMORY) $(FORCE_ASYNC) -DPSEUDO_PASSWD_FALLBACK='$(PASSWD_FALLBACK)' +CFLAGS_DEFS=-DPSEUDO_PREFIX='"$(PREFIX)"' -DPSEUDO_SUFFIX='"$(SUFFIX)"' -DPSEUDO_BINDIR='"$(BIN)"' -DPSEUDO_LIBDIR='"$(LIB)"' -DPSEUDO_LOCALSTATEDIR='"$(LOCALSTATE)"' -DPSEUDO_VERSION='"$(VERSION)"' $(SQLITE_MEMORY) $(FORCE_ASYNC) -DPSEUDO_PASSWD_FALLBACK='$(PASSWD_FALLBACK)' $(PROFILING) CFLAGS_DEBUG=-O2 -g @DEFAULT_SQLITE@CFLAGS_SQL=-L$(SQLITE)/$(SQLITE_LIB) -I$(SQLITE)/include $(RPATH) CFLAGS_PSEUDO=$(CFLAGS_BASE) $(CFLAGS_CODE) $(CFLAGS_DEFS) \ @@ -69,7 +76,7 @@ LIBPSEUDO=$(LIB)/libpseudo.so TEMPLATES=templates/guts templates/wrapfuncs.c templates/wrapfuncs.h templates/wrapper_table TABLES=table_templates/pseudo_tables.c table_templates/pseudo_tables.h -all: $(LIBPSEUDO) $(PSEUDO) $(PSEUDODB) $(PSEUDOLOG) +all: $(LIBPSEUDO) $(PSEUDO) $(PSEUDODB) $(PSEUDOLOG) $(PSEUDO_PROFILE) test: all $(BIN) $(LIB) $(LOCALSTATE) @./run_tests.sh -v @@ -79,9 +86,9 @@ install-lib: $(LIBPSEUDO) cp $(LIBPSEUDO) $(DESTDIR)$(LIBDIR) $(if $(SUFFIX),cp $(LIBPSEUDO) $(DESTDIR)$(LIBDIR)/libpseudo$(SUFFIX).so,:) -install-bin: $(PSEUDO) $(PSEUDODB) $(PSEUDOLOG) +install-bin: $(PSEUDO) $(PSEUDODB) $(PSEUDOLOG) $(PSEUDO_PROFILE) mkdir -p $(DESTDIR)$(BINDIR) - cp $(PSEUDO) $(PSEUDODB) $(PSEUDOLOG) $(DESTDIR)$(BINDIR) + cp $(PSEUDO) $(PSEUDODB) $(PSEUDOLOG) $(PSEUDO_PROFILE) $(DESTDIR)$(BINDIR) install-data: mkdir -p $(DESTDIR)$(LOCALSTATEDIR) @@ -155,6 +162,12 @@ offsets32: offsets64: $(CC) -m64 -o offsets64 offsets.c +$(PSEUDO_PROFILE): $(BIN) pseudo_profile + cp pseudo_profile $(BIN) + +pseudo_profile: Makefile pseudo_profile.c tables wrappers + $(CC) $(CFLAGS) $(CFLAGS_PSEUDO) -o pseudo_profile pseudo_profile.c + clean: rm -f *.o *.so $(PSEUDO) $(PSEUDODB) $(PSEUDOLOG) \ pseudo_wrapfuncs.h pseudo_wrapfuncs.c \ @@ -162,6 +175,7 @@ clean: pseudo_tables.c pseudo_tables.h \ pseudo_ports.h port_wrappers.c \ offsets32 offsets64 \ + pseudo_profile \ port_deps.mk func_deps.mk touch port_deps.mk func_deps.mk @@ -28,6 +28,7 @@ opt_rpath= opt_memory= opt_async= opt_xattr= +opt_profile=false opt_passwd_fallback='""' compile_x86_32=-m32 @@ -41,6 +42,7 @@ usage() echo >&2 " [--suffix=...]" echo >&2 " [--enable-memory-db]" echo >&2 " [--enable-xattr]" + echo >&2 " [--enable-profiling]" echo >&2 " [--enable-force-async]" echo >&2 " [--with-sqlite=...]" echo >&2 " [--with-sqlite-lib=...]" @@ -105,6 +107,12 @@ do --enable-force-async=yes | --enable-force-async) opt_async=true ;; + --enable-profiling=no) + opt_profiling=false + ;; + --enable-profiling=yes | --enable-profiling) + opt_profiling=true + ;; --enable-xattr=no) opt_xattr=false ;; @@ -243,13 +251,26 @@ else FORCE_ASYNC="" fi +if getfattr --help >/dev/null 2>&1; then + xattr_runs=true +else + xattr_runs=false +fi + + if [ -z "$opt_xattr" ]; then - if getfattr --help >/dev/null 2>&1; then + if $xattr_runs; then opt_xattr=true - echo "getfattr runs, enabling extended attribute support" + echo "getfattr runs, enabling extended attribute support" else opt_xattr=false - echo "getfattr fails, disabling extended attribute support" + echo "getfattr fails, disabling extended attribute support" + fi +fi + +if $opt_xattr; then + if ! $xattr_runs; then + echo >&2 "WARNING: getfattr doesn't work, but xattr-related features requestd." fi fi @@ -287,6 +308,7 @@ touch func_deps.mk sed -e ' s,@PREFIX@,'"$opt_prefix"',g s,@XATTR@,'"$opt_xattr"',g + s,@PROFILING@,'"$opt_profiling"',g s,@LIBDIR@,'"$opt_libdir"',g s,@LIB@,'"$opt_lib"',g s,@SUFFIX@,'"$opt_suffix"',g diff --git a/enums/debug_type.in b/enums/debug_type.in index f4de3ab..950333a 100644 --- a/enums/debug_type.in +++ b/enums/debug_type.in @@ -15,6 +15,8 @@ pid, 'P', "show process IDs" client, 'c', "client side startup/shutdown" server, 'v', "server side startup/shutdown" db, 'd', "database interactions" +xattrdb, 'D', "xattr database" +profile, 'R', "profiling" syscall, 'y', "system calls" env, 'e', "environment manipulation" chroot, 'r', "chroot functionality" diff --git a/makewrappers b/makewrappers index 46aeb44..efe6180 100755 --- a/makewrappers +++ b/makewrappers @@ -306,8 +306,10 @@ class Function: if self.async_skip: return """/* This function is not called if pseudo is configured --enable-force-async */ #ifdef PSEUDO_FORCE_ASYNC - if (!pseudo_allow_fsync) + if (!pseudo_allow_fsync) { + PROFILE_DONE; return %s; + } #endif """ % self.async_skip else: @@ -579,6 +581,7 @@ def main(argv): for path in glob.glob('templates/*'): try: + print "Considering template: " + path source = TemplateFile(path) if source.name.endswith('.c') or source.name.endswith('.h'): source.emit('copyright') diff --git a/ports/common/pseudo_wrappers.c b/ports/common/pseudo_wrappers.c index 3652ad4..81be635 100644 --- a/ports/common/pseudo_wrappers.c +++ b/ports/common/pseudo_wrappers.c @@ -67,9 +67,12 @@ execl(const char *file, const char *arg, ...) { int rc = -1; + PROFILE_START; + if (!pseudo_check_wrappers()) { /* rc was initialized to the "failure" value */ pseudo_enosys("execl"); + PROFILE_DONE; return rc; } @@ -78,6 +81,7 @@ execl(const char *file, const char *arg, ...) { va_end(ap); if (!argv) { errno = ENOMEM; + PROFILE_DONE; return -1; } @@ -86,6 +90,7 @@ execl(const char *file, const char *arg, ...) { if (pseudo_getlock()) { errno = EBUSY; sigprocmask(SIG_SETMASK, &saved, NULL); + PROFILE_DONE; return -1; } @@ -101,6 +106,7 @@ execl(const char *file, const char *arg, ...) { pseudo_debug(PDBGF_WRAPPER, "completed: execl\n"); errno = save_errno; free(argv); + PROFILE_DONE; return rc; } @@ -111,10 +117,12 @@ execlp(const char *file, const char *arg, ...) { char **argv; int rc = -1; + PROFILE_START; if (!pseudo_check_wrappers()) { /* rc was initialized to the "failure" value */ pseudo_enosys("execlp"); + PROFILE_DONE; return rc; } @@ -123,6 +131,7 @@ execlp(const char *file, const char *arg, ...) { va_end(ap); if (!argv) { errno = ENOMEM; + PROFILE_DONE; return -1; } @@ -131,6 +140,7 @@ execlp(const char *file, const char *arg, ...) { if (pseudo_getlock()) { errno = EBUSY; sigprocmask(SIG_SETMASK, &saved, NULL); + PROFILE_DONE; return -1; } @@ -146,6 +156,7 @@ execlp(const char *file, const char *arg, ...) { pseudo_debug(PDBGF_WRAPPER, "completed: execlp\n"); errno = save_errno; free(argv); + PROFILE_DONE; return rc; } @@ -157,10 +168,12 @@ execle(const char *file, const char *arg, ...) { char **envp; int rc = -1; + PROFILE_START; if (!pseudo_check_wrappers()) { /* rc was initialized to the "failure" value */ pseudo_enosys("execle"); + PROFILE_DONE; return rc; } @@ -169,6 +182,7 @@ execle(const char *file, const char *arg, ...) { va_end(ap); if (!argv) { errno = ENOMEM; + PROFILE_DONE; return -1; } @@ -177,6 +191,7 @@ execle(const char *file, const char *arg, ...) { if (pseudo_getlock()) { errno = EBUSY; sigprocmask(SIG_SETMASK, &saved, NULL); + PROFILE_DONE; return -1; } @@ -192,6 +207,7 @@ execle(const char *file, const char *arg, ...) { pseudo_debug(PDBGF_WRAPPER, "completed: execle\n"); errno = save_errno; free(argv); + PROFILE_DONE; return rc; } @@ -201,9 +217,12 @@ execv(const char *file, char *const *argv) { int rc = -1; + PROFILE_START; + if (!pseudo_check_wrappers() || !real_execv) { /* rc was initialized to the "failure" value */ pseudo_enosys("execv"); + PROFILE_DONE; return rc; } @@ -212,6 +231,7 @@ execv(const char *file, char *const *argv) { if (pseudo_getlock()) { errno = EBUSY; sigprocmask(SIG_SETMASK, &saved, NULL); + PROFILE_DONE; return -1; } @@ -226,6 +246,7 @@ execv(const char *file, char *const *argv) { sigprocmask(SIG_SETMASK, &saved, NULL); pseudo_debug(PDBGF_WRAPPER, "completed: execv\n"); errno = save_errno; + PROFILE_DONE; return rc; } @@ -234,10 +255,12 @@ execve(const char *file, char *const *argv, char *const *envp) { sigset_t saved; int rc = -1; + PROFILE_START; if (!pseudo_check_wrappers() || !real_execve) { /* rc was initialized to the "failure" value */ pseudo_enosys("execve"); + PROFILE_DONE; return rc; } @@ -246,6 +269,7 @@ execve(const char *file, char *const *argv, char *const *envp) { if (pseudo_getlock()) { errno = EBUSY; sigprocmask(SIG_SETMASK, &saved, NULL); + PROFILE_DONE; return -1; } @@ -260,6 +284,7 @@ execve(const char *file, char *const *argv, char *const *envp) { sigprocmask(SIG_SETMASK, &saved, NULL); pseudo_debug(PDBGF_WRAPPER, "completed: execve\n"); errno = save_errno; + PROFILE_DONE; return rc; } @@ -268,10 +293,12 @@ execvp(const char *file, char *const *argv) { sigset_t saved; int rc = -1; + PROFILE_START; if (!pseudo_check_wrappers() || !real_execvp) { /* rc was initialized to the "failure" value */ pseudo_enosys("execvp"); + PROFILE_DONE; return rc; } @@ -280,6 +307,7 @@ execvp(const char *file, char *const *argv) { if (pseudo_getlock()) { errno = EBUSY; sigprocmask(SIG_SETMASK, &saved, NULL); + PROFILE_DONE; return -1; } @@ -294,9 +322,13 @@ execvp(const char *file, char *const *argv) { sigprocmask(SIG_SETMASK, &saved, NULL); pseudo_debug(PDBGF_WRAPPER, "completed: execvp\n"); errno = save_errno; + PROFILE_DONE; return rc; } +/* no profiling in fork because it wouldn't work anyway + * half the time + */ int fork(void) { sigset_t saved; diff --git a/ports/darwin/pseudo_wrappers.c b/ports/darwin/pseudo_wrappers.c index 8a0222f..e33533e 100644 --- a/ports/darwin/pseudo_wrappers.c +++ b/ports/darwin/pseudo_wrappers.c @@ -130,7 +130,8 @@ posix_permissions(const acl_header *header, int entries, int *extra, int *mode) if (rc == -1) { \ return rc; \ } - + +/* Note: no profiling implementation yet. */ static ssize_t shared_getxattr(const char *path, int fd, const char *name, void *value, size_t size, u_int32_t position, int options) { RC_AND_BUF diff --git a/ports/linux/guts/__fxstatat64.c b/ports/linux/guts/__fxstatat64.c index b989e7b..62fc3f1 100644 --- a/ports/linux/guts/__fxstatat64.c +++ b/ports/linux/guts/__fxstatat64.c @@ -47,7 +47,7 @@ * don't need to check for a symlink on this end */ msg = pseudo_client_op(OP_STAT, 0, -1, dirfd, path, buf); - if (msg) { + if (msg && msg->result == RESULT_SUCCEED) { pseudo_stat_msg(buf, msg); } diff --git a/ports/linux/xattr/pseudo_wrappers.c b/ports/linux/xattr/pseudo_wrappers.c index e2f4388..46bc053 100644 --- a/ports/linux/xattr/pseudo_wrappers.c +++ b/ports/linux/xattr/pseudo_wrappers.c @@ -166,6 +166,10 @@ static int shared_setxattr(const char *path, int fd, const char *name, const voi } } } + if (!strcmp(name, "user.pseudo_data")) { + pseudo_debug(PDBGF_XATTR | PDBGF_XATTRDB, "user.pseudo_data xattribute does not get to go in database.\n"); + return -1; + } switch (flags) { case XATTR_CREATE: @@ -583,6 +583,14 @@ This variable is automatically set by the .I pseudo program when it is used as a launcher. .TP 8 +.B PSEUDO_PROFILE_PATH +If +.I pseudo +was configured with profiling enabled, specifies a path in which to +write client profiling information for use with the +.I pseudo_profile +utility (not built by default). +.TP 8 .B PSEUDO_TAG If this variable is set in a client's environment, its value is communicated to the server at the beginning of each client session, @@ -152,4 +152,14 @@ round_up(size_t n, size_t block) { return block * (((n + block / 4) / block) + 1); } +#ifdef PSEUDO_PROFILING +typedef struct { + int processes; + long long total_ops; + long long messages; + struct timeval op_time; + struct timeval ipc_time; + struct timeval wrapper_time; +} pseudo_profile_t; +#endif #include "pseudo_ports.h" diff --git a/pseudo_client.c b/pseudo_client.c index 965be6f..c4dd43d 100644 --- a/pseudo_client.c +++ b/pseudo_client.c @@ -77,8 +77,12 @@ static char **fd_paths = NULL; static int nfds = 0; static const char **passwd_paths = NULL; static int npasswd_paths = 0; -static int messages = 0; -static struct timeval message_time = { .tv_sec = 0 }; +#ifdef PSEUDO_PROFILING +int pseudo_profile_fd = -1; +static int profile_interval = 1; +static pseudo_profile_t profile_data; +struct timeval *pseudo_wrapper_time = &profile_data.wrapper_time; +#endif static int pseudo_inited = 0; static int sent_messages = 0; @@ -186,6 +190,123 @@ build_passwd_paths(void) return; } +#ifdef PSEUDO_PROFILING +static int pseudo_profile_pid = -2; + +static void +pseudo_profile_start(void) { + /* We use -1 as a starting value, and -2 as a value + * indicating not to try to open it. + */ + int existing_data = 0; + int pid = getpid(); + if (pseudo_profile_pid > 0 && pseudo_profile_pid != pid) { + /* looks like there's been a fork. We intentionally + * abandon any existing stats, since the parent might + * want to write them, and we want to combine with + * any previous stats for this pid. + */ + close(pseudo_profile_fd); + pseudo_profile_fd = -1; + } + if (pseudo_profile_fd == -1) { + int fd = -2; + char *profile_path = pseudo_get_value("PSEUDO_PROFILE_PATH"); + pseudo_profile_pid = pid; + if (profile_path) { + fd = open(profile_path, O_RDWR | O_CREAT, 0600); + if (fd >= 0) { + fd = pseudo_fd(fd, MOVE_FD); + } + if (fd < 0) { + fd = -2; + } else { + if (pid > 0) { + pseudo_profile_t data; + off_t rc; + + rc = lseek(fd, pid * sizeof(data), SEEK_SET); + if (rc == (off_t) (pid * sizeof(data))) { + rc = read(fd, &profile_data, sizeof(profile_data)); + /* cumulative with other values in same file */ + if (rc == sizeof(profile_data)) { + pseudo_debug(PDBGF_PROFILE, "pid %d found existing profiling data.\n", pid); + existing_data = 1; + ++profile_data.processes; + } else { + pseudo_debug(PDBGF_PROFILE, "read failed for pid %d: %d, %d\n", pid, (int) rc, errno); + } + profile_interval = 1; + } + } + } + } + pseudo_profile_fd = fd; + } else { + pseudo_debug(PDBGF_PROFILE, "_start called with existing fd? (pid %d)", (int) pseudo_profile_pid); + existing_data = 1; + ++profile_data.processes; + profile_data.total_ops = 0; + profile_data.messages = 0; + profile_data.wrapper_time = (struct timeval) { .tv_sec = 0 }; + profile_data.op_time = (struct timeval) { .tv_sec = 0 }; + profile_data.ipc_time = (struct timeval) { .tv_sec = 0 }; + } + if (!existing_data) { + pseudo_debug(PDBGF_PROFILE, "pid %d found no existing profiling data.\n", pid); + profile_data = (pseudo_profile_t) { + .processes = 1, + .total_ops = 0, + .messages = 0, + .wrapper_time = (struct timeval) { .tv_sec = 0 }, + .op_time = (struct timeval) { .tv_sec = 0 }, + .ipc_time = (struct timeval) { .tv_sec = 0 }, + }; + } +} + +static inline void +fix_tv(struct timeval *tv) { + if (tv->tv_usec > 1000000) { + tv->tv_sec += tv->tv_usec / 1000000; + tv->tv_usec %= 1000000; + } else if (tv->tv_usec < 0) { + /* C99 and later guarantee truncate-towards-zero. + * We want -1 through -1000000 usec to produce + * -1 seconds, etcetera. Note that sec is + * negative, so yes, we want to add to tv_sec and + * subtract from tv_usec. + */ + int sec = (tv->tv_usec - 999999) / 1000000; + tv->tv_sec += sec; + tv->tv_usec -= 1000000 * sec; + } +} + +static int profile_reported = 0; +static void +pseudo_profile_report(void) { + if (pseudo_profile_fd < 0) { + return; + } + fix_tv(&profile_data.wrapper_time); + fix_tv(&profile_data.op_time); + fix_tv(&profile_data.ipc_time); + if (pseudo_profile_pid >= 0) { + int rc1, rc2; + rc1 = lseek(pseudo_profile_fd, pseudo_profile_pid * sizeof(profile_data), SEEK_SET); + rc2 = write(pseudo_profile_fd, &profile_data, sizeof(profile_data)); + if (!profile_reported) { + pseudo_debug(PDBGF_PROFILE, "pid %d (%s) saving profiling info: %d, %d.\n", + pseudo_profile_pid, + program_invocation_name ? program_invocation_name : "unknown", + rc1, rc2); + profile_reported = 1; + } + } +} +#endif + void pseudo_init_client(void) { char *env; @@ -196,6 +317,12 @@ pseudo_init_client(void) { close(connect_fd); connect_fd = -1; } +#ifdef PSEUDO_PROFILING + if (pseudo_profile_fd > -1) { + close(pseudo_profile_fd); + } + pseudo_profile_fd = -1; +#endif /* in child processes, PSEUDO_DISABLED may have become set to * some truthy value, in which case we'd disable pseudo, @@ -268,7 +395,7 @@ pseudo_init_client(void) { env = getenv("PSEUDO_UNLOAD"); if (env) { pseudo_set_value("PSEUDO_UNLOAD", env); - pseudo_disabled=1; + pseudo_disabled = 1; } /* Setup global items needed for pseudo to function... */ @@ -403,8 +530,12 @@ pseudo_init_client(void) { pseudo_inited = 1; } - if (!pseudo_disabled) + if (!pseudo_disabled) { pseudo_client_getcwd(); +#ifdef PSEUDO_PROFILING + pseudo_profile_start(); +#endif + } pseudo_magic(); } @@ -1152,14 +1283,32 @@ pseudo_client_op(pseudo_op_t op, int access, int fd, int dirfd, const char *path static size_t alloced_len = 0; int strip_slash; +#ifdef PSEUDO_PROFILING + struct timeval tv1_op, tv2_op; + + gettimeofday(&tv1_op, NULL); + ++profile_data.total_ops; +#endif /* disable wrappers */ pseudo_antimagic(); + /* note: I am not entirely sure this should happen even if no + * messages have actually been sent. */ if (!sent_messages) { sent_messages = 1; atexit(void_client_ping); } + /* if path isn't available, try to find one? */ + if (!path && fd >= 0 && fd <= nfds) { + path = fd_path(fd); + if (!path) { + pathlen = 0; + } else { + pathlen = strlen(path) + 1; + } + } + if (op == OP_RENAME) { va_list ap; if (!path) { @@ -1208,16 +1357,6 @@ pseudo_client_op(pseudo_op_t op, int access, int fd, int dirfd, const char *path op == OP_GET_XATTR ? "get" : "remove", path_extra_1); } - /* if path isn't available, try to find one? */ - if (!path && fd >= 0 && fd <= nfds) { - path = fd_path(fd); - if (!path) { - pathlen = 0; - } else { - pathlen = strlen(path) + 1; - } - } - if (path) { if (pathlen == (size_t) -1) { pathlen = strlen(path) + 1; @@ -1288,30 +1427,34 @@ pseudo_client_op(pseudo_op_t op, int access, int fd, int dirfd, const char *path } } - pseudo_debug(PDBGF_OP, "%s%s", pseudo_op_name(op), - (dirfd != -1 && dirfd != AT_FDCWD && op != OP_DUP) ? "at" : ""); - if (path_extra_1) { - pseudo_debug(PDBGF_OP, " %s ->", path_extra_1); - } - if (path) { - pseudo_debug(PDBGF_OP, " %s", path); - } - /* for OP_RENAME in renameat, "fd" is also used for the - * second dirfd. - */ - if (fd != -1 && op != OP_RENAME) { - pseudo_debug(PDBGF_OP, " [fd %d]", fd); - } - if (buf) { - pseudo_debug(PDBGF_OP, " (+buf)"); + if (buf) pseudo_msg_stat(&msg, buf); - if (buf && fd != -1) { - pseudo_debug(PDBGF_OP, " [dev/ino: %d/%llu]", - (int) buf->st_dev, (unsigned long long) buf->st_ino); + + if (pseudo_util_debug_flags & PDBGF_OP) { + pseudo_debug(PDBGF_OP, "%s%s", pseudo_op_name(op), + (dirfd != -1 && dirfd != AT_FDCWD && op != OP_DUP) ? "at" : ""); + if (path_extra_1) { + pseudo_debug(PDBGF_OP, " %s ->", path_extra_1); + } + if (path) { + pseudo_debug(PDBGF_OP, " %s", path); + } + /* for OP_RENAME in renameat, "fd" is also used for the + * second dirfd. + */ + if (fd != -1 && op != OP_RENAME) { + pseudo_debug(PDBGF_OP, " [fd %d]", fd); + } + if (buf) { + pseudo_debug(PDBGF_OP, " (+buf)"); + if (fd != -1) { + pseudo_debug(PDBGF_OP, " [dev/ino: %d/%llu]", + (int) buf->st_dev, (unsigned long long) buf->st_ino); + } + pseudo_debug(PDBGF_OP, " (0%o)", (int) buf->st_mode); } - pseudo_debug(PDBGF_OP, " (0%o)", (int) buf->st_mode); + pseudo_debug(PDBGF_OP, ": "); } - pseudo_debug(PDBGF_OP, ": "); msg.type = PSEUDO_MSG_OP; msg.op = op; msg.fd = fd; @@ -1413,28 +1556,27 @@ pseudo_client_op(pseudo_op_t op, int access, int fd, int dirfd, const char *path break; } if (do_request) { - struct timeval tv1, tv2; +#ifdef PSEUDO_PROFILING + struct timeval tv1_ipc, tv2_ipc; +#endif if (!pseudo_op_wait(msg.op)) msg.type = PSEUDO_MSG_FASTOP; pseudo_debug(PDBGF_CLIENT | PDBGF_VERBOSE, "sending request [ino %llu]\n", (unsigned long long) msg.ino); - gettimeofday(&tv1, NULL); +#ifdef PSEUDO_PROFILING + gettimeofday(&tv1_ipc, NULL); +#endif if (pseudo_local_only) { /* disable server */ result = NULL; } else { result = pseudo_client_request(&msg, pathlen, path); } - gettimeofday(&tv2, NULL); - ++messages; - message_time.tv_sec += (tv2.tv_sec - tv1.tv_sec); - message_time.tv_usec += (tv2.tv_usec - tv1.tv_usec); - if (message_time.tv_usec < 0) { - message_time.tv_usec += 1000000; - --message_time.tv_sec; - } else while (message_time.tv_usec > 1000000) { - message_time.tv_usec -= 1000000; - ++message_time.tv_sec; - } +#ifdef PSEUDO_PROFILING + gettimeofday(&tv2_ipc, NULL); + ++profile_data.messages; + profile_data.ipc_time.tv_sec += (tv2_ipc.tv_sec - tv1_ipc.tv_sec); + profile_data.ipc_time.tv_usec += (tv2_ipc.tv_usec - tv1_ipc.tv_usec); +#endif if (result) { pseudo_debug(PDBGF_OP, "(%d) %s", getpid(), pseudo_res_name(result->result)); if (op == OP_STAT || op == OP_FSTAT) { @@ -1450,20 +1592,25 @@ pseudo_client_op(pseudo_op_t op, int access, int fd, int dirfd, const char *path (int) result->uid, (int) result->gid); } - } else { + } else if (msg.type != PSEUDO_MSG_FASTOP) { pseudo_debug(PDBGF_OP, "(%d) no answer", getpid()); } - } else { + } else if (!result) { pseudo_debug(PDBGF_OP, "(%d) (no request)", getpid()); } pseudo_debug(PDBGF_OP, "\n"); - if (do_request && (messages % 1000 == 0)) { - pseudo_debug(PDBGF_CLIENT | PDBGF_VERBOSE | PDBGF_BENCHMARK, "%d messages handled in %.4f seconds\n", - messages, - (double) message_time.tv_sec + - (double) message_time.tv_usec / 1000000.0); +#ifdef PSEUDO_PROFILING + gettimeofday(&tv2_op, NULL); + profile_data.op_time.tv_sec += (tv2_op.tv_sec - tv1_op.tv_sec); + profile_data.op_time.tv_usec += (tv2_op.tv_usec - tv1_op.tv_usec); + if (profile_data.total_ops % profile_interval == 0) { + pseudo_profile_report(); + if (profile_interval < 100) { + profile_interval = profile_interval * 10; + } } +#endif /* reenable wrappers */ pseudo_magic(); diff --git a/pseudo_profile.c b/pseudo_profile.c new file mode 100644 index 0000000..c4af803 --- /dev/null +++ b/pseudo_profile.c @@ -0,0 +1,64 @@ +#define _GNU_SOURCE + +#include <errno.h> +#include <stdio.h> +#include <stdlib.h> +#include <unistd.h> +#include <sys/stat.h> + +#include "pseudo.h" + +int +main(int argc, char **argv) { + int fd; + pseudo_profile_t totals = { .total_ops = 0 }, item; + int count = 0; + + if (argc < 2) { + fprintf(stderr, "usage: pseudo_profile <profiling_data>\n"); + exit(1); + } + + fd = open(argv[1], O_RDONLY); + if (fd < 0) { + fprintf(stderr, "Can't open '%s': %s.\n", + argv[1], strerror(errno)); + exit(1); + } + while (read(fd, &item, sizeof(item)) == sizeof(item)) { + if (item.total_ops > 0) { + ++count; + totals.processes += item.processes; + totals.total_ops += item.total_ops; + totals.messages += item.messages; + totals.op_time.tv_sec += item.op_time.tv_sec; + totals.op_time.tv_usec += item.op_time.tv_usec; + if (totals.op_time.tv_usec >= 1000000) { + ++totals.op_time.tv_sec; + totals.op_time.tv_usec -= 1000000; + } + totals.ipc_time.tv_sec += item.ipc_time.tv_sec; + totals.ipc_time.tv_usec += item.ipc_time.tv_usec; + if (totals.ipc_time.tv_usec >= 1000000) { + ++totals.ipc_time.tv_sec; + totals.ipc_time.tv_usec -= 1000000; + } + totals.wrapper_time.tv_sec += item.wrapper_time.tv_sec; + totals.wrapper_time.tv_usec += item.wrapper_time.tv_usec; + if (totals.wrapper_time.tv_usec >= 1000000) { + ++totals.wrapper_time.tv_sec; + totals.wrapper_time.tv_usec -= 1000000; + } + } + } + printf("Found data for %d PIDs, %d processes.\n", + count, totals.processes); + printf("%lld messages for %lld ops.\n", totals.messages, totals.total_ops); + double otime = totals.op_time.tv_sec + (totals.op_time.tv_usec / 1000000.0); + double itime = totals.ipc_time.tv_sec + (totals.ipc_time.tv_usec / 1000000.0); + double wtime = totals.wrapper_time.tv_sec + (totals.wrapper_time.tv_usec / 1000000.0); + printf("%.4f msec wrapper time, %.4f msec op time, %.4f msec IPC time.\n", + wtime * 1000, otime * 1000, itime * 1000); + + return 0; +} diff --git a/pseudo_server.c b/pseudo_server.c index a7600af..1fdadcb 100644 --- a/pseudo_server.c +++ b/pseudo_server.c @@ -1,6 +1,5 @@ /* * pseudo_server.c, pseudo's server-side logic and message handling - * * Copyright (c) 2008-2010, 2013 Wind River Systems, Inc. * diff --git a/pseudo_util.c b/pseudo_util.c index 7f21164..ccbda60 100644 --- a/pseudo_util.c +++ b/pseudo_util.c @@ -66,6 +66,9 @@ static struct pseudo_variables pseudo_env[] = { { "PSEUDO_DISABLED", 15, NULL }, { "PSEUDO_UNLOAD", 13, NULL }, { "PSEUDO_ALLOW_FSYNC", 18, NULL }, +#ifdef PSEUDO_PROFILING + { "PSEUDO_PROFILE_PATH", 19, NULL }, +#endif { NULL, 0, NULL } /* Magic terminator */ }; diff --git a/pseudo_wrappers.c b/pseudo_wrappers.c index 4a40fed..b2e3810 100644 --- a/pseudo_wrappers.c +++ b/pseudo_wrappers.c @@ -31,6 +31,7 @@ #include <unistd.h> #include <fcntl.h> #include <sys/stat.h> +#include <sys/time.h> #include <sys/wait.h> #include <dlfcn.h> @@ -70,6 +71,21 @@ static void _libpseudo_init(void) __attribute__ ((constructor)); static int _libpseudo_initted = 0; +#ifdef PSEUDO_PROFILING +extern struct timeval *pseudo_wrapper_time; +/* profiling shared postamble */ +#define PROFILE_START \ + struct timeval tv1, tv2; \ + do { gettimeofday(&tv1, NULL); } while(0) +#define PROFILE_DONE do { \ + gettimeofday(&tv2, NULL); \ + pseudo_wrapper_time->tv_sec += tv2.tv_sec - tv1.tv_sec; \ + pseudo_wrapper_time->tv_usec += tv2.tv_usec - tv1.tv_usec; } while(0) +#else +#define PROFILE_START do {} while(0) +#define PROFILE_DONE do {} while(0) +#endif + static void _libpseudo_init(void) { pseudo_getlock(); diff --git a/templates/wrapfuncs.c b/templates/wrapfuncs.c index faac1b7..5a436e9 100644 --- a/templates/wrapfuncs.c +++ b/templates/wrapfuncs.c @@ -22,12 +22,14 @@ ${name}(${decl_args}) { sigset_t saved; ${variadic_decl} ${rc_decl} + PROFILE_START; ${maybe_async_skip} if (!pseudo_check_wrappers() || !real_$name) { /* rc was initialized to the "failure" value */ pseudo_enosys("${name}"); + PROFILE_DONE; ${rc_return} } @@ -36,6 +38,7 @@ ${maybe_async_skip} if (pseudo_disabled) { ${rc_assign} (*real_${name})(${call_args}); ${variadic_end} + PROFILE_DONE; ${rc_return} } @@ -46,6 +49,7 @@ ${maybe_async_skip} errno = EBUSY; sigprocmask(SIG_SETMASK, &saved, NULL); pseudo_debug(PDBGF_WRAPPER, "${name} failed to get lock, giving EBUSY.\n"); + PROFILE_DONE; ${def_return} } @@ -74,6 +78,7 @@ ${maybe_async_skip} #endif pseudo_debug(PDBGF_WRAPPER, "wrapper completed: ${name} (errno: %d)\n", save_errno); errno = save_errno; + PROFILE_DONE; ${rc_return} } |