aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorPeter Seebach <peter.seebach@windriver.com>2015-08-13 17:10:02 -0500
committerPeter Seebach <peter.seebach@windriver.com>2015-08-20 17:17:09 -0500
commit4377856c427d40d4d518263ff0b6effa00fd3636 (patch)
treed59095adf952060da6f6969fa792b3cf3f074c65
parentdc631e69f8d189332c86a7dcae5b9f0badd52fd0 (diff)
downloadpseudo-4377856c427d40d4d518263ff0b6effa00fd3636.tar.gz
pseudo-4377856c427d40d4d518263ff0b6effa00fd3636.tar.bz2
pseudo-4377856c427d40d4d518263ff0b6effa00fd3636.zip
Initial profiling implementation.
A partially-implemented profiler for client time, which basically just inserts (optional) gettimeofday calls in various places and stashes data in a flat file containing one data block per pid. Signed-off-by: Peter Seebach <peter.seebach@windriver.com>
-rw-r--r--.gitignore1
-rw-r--r--ChangeLog.txt10
-rw-r--r--Makefile.in24
-rwxr-xr-xconfigure28
-rw-r--r--enums/debug_type.in2
-rwxr-xr-xmakewrappers5
-rw-r--r--ports/common/pseudo_wrappers.c32
-rw-r--r--ports/darwin/pseudo_wrappers.c3
-rw-r--r--ports/linux/guts/__fxstatat64.c2
-rw-r--r--ports/linux/xattr/pseudo_wrappers.c4
-rw-r--r--pseudo.18
-rw-r--r--pseudo.h10
-rw-r--r--pseudo_client.c257
-rw-r--r--pseudo_profile.c64
-rw-r--r--pseudo_server.c1
-rw-r--r--pseudo_util.c3
-rw-r--r--pseudo_wrappers.c16
-rw-r--r--templates/wrapfuncs.c5
18 files changed, 408 insertions, 67 deletions
diff --git a/.gitignore b/.gitignore
index 5f038ed..e6e11d9 100644
--- a/.gitignore
+++ b/.gitignore
@@ -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
diff --git a/configure b/configure
index 23ffe43..9472701 100755
--- a/configure
+++ b/configure
@@ -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:
diff --git a/pseudo.1 b/pseudo.1
index 6906345..13f6bbe 100644
--- a/pseudo.1
+++ b/pseudo.1
@@ -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,
diff --git a/pseudo.h b/pseudo.h
index 05813c1..81db201 100644
--- a/pseudo.h
+++ b/pseudo.h
@@ -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}
}