[PATCH RFC] Summary of syscall latency

[Mark Hills]

Time spent in system time is not useful where a syscall depends on some 
non-CPU resource, eg. typically open() or stat() to a network drive.

This patch adds a -w flag to produce a summary of the time difference 
between beginning and end of the system call (ie. latency)

This functionality has been useful to profile slow processes that are not 
CPU-bound.

An older commit 8050cdc mentions this:

> It might be useful to have a mode where we show wall clock time spent in 
> syscalls, not CPU time. It might also be more accurate.

I'm not sure how reasonably useful the crude profile of CPU "system time" 
is. Is it better to replace the existing functionality with 
wallclock/latency time, or does this justify the introduction of a new 
flag, as below?

Thanks

-- 
Mark


---
 count.c  |    4 ++--
 defs.h   |    1 +
 strace.1 |    4 ++++
 strace.c |   11 ++++++++++-
 4 files changed, 17 insertions(+), 3 deletions(-)

diff --git a/count.c b/count.c
index 8395466..cbb92a4 100644
--- a/count.c
+++ b/count.c
@@ -37,7 +37,7 @@
 
 /* Per-syscall stats structure */
 struct call_counts {
-	/* system time spent in syscall (not wall clock time) */
+	/* time may be total latency or system time */
 	struct timeval time;
 	int calls, errors;
 };
@@ -72,7 +72,7 @@ count_syscall(struct tcb *tcp, struct timeval *tv)
 	tv_sub(tv, tv, &tcp->etime);
 
 	/* Spent more wall clock time than spent system time? (usually yes) */
-	if (tv_cmp(tv, &tcp->dtime) > 0) {
+	if (!count_wallclock && tv_cmp(tv, &tcp->dtime) > 0) {
 		static struct timeval one_tick = { -1, 0 };
 
 		if (one_tick.tv_sec == -1) {
diff --git a/defs.h b/defs.h
index 074c8f0..2fce8b3 100644
--- a/defs.h
+++ b/defs.h
@@ -548,6 +548,7 @@ extern cflag_t cflag;
 extern bool debug_flag;
 extern bool Tflag;
 extern bool iflag;
+extern bool count_wallclock;
 extern unsigned int qflag;
 extern bool not_failing_only;
 extern bool show_fd_path;
diff --git a/strace.1 b/strace.1
index 6ca4bda..4d26be5 100644
--- a/strace.1
+++ b/strace.1
@@ -290,6 +290,10 @@ of seconds since the epoch.
 Show the time spent in system calls. This records the time
 difference between the beginning and the end of each system call.
 .TP
+.B \-w
+Summarise the time difference between the beginning and end of
+each system call. The default is to summarise the system time.
+.TP
 .B \-v
 Print unabbreviated versions of environment, stat, termios, etc.
 calls.  These structures are very common in calls and so the default
diff --git a/strace.c b/strace.c
index 8a49340..35ee7be 100644
--- a/strace.c
+++ b/strace.c
@@ -78,6 +78,7 @@ bool need_fork_exec_workarounds = 0;
 bool debug_flag = 0;
 bool Tflag = 0;
 bool iflag = 0;
+bool count_wallclock = 0;
 unsigned int qflag = 0;
 /* Which WSTOPSIG(status) value marks syscall traps? */
 static unsigned int syscall_trap_sig = SIGTRAP;
@@ -200,6 +201,7 @@ usage: strace [-CdffhiqrtttTvVxxy] [-I n] [-e expr]...\n\
               -p pid... / [-D] [-E var=val]... [-u username] PROG [ARGS]\n\
 -c -- count time, calls, and errors for each syscall and report summary\n\
 -C -- like -c but also print regular output\n\
+-w -- summarise syscall latency (default is system time)\n\
 -d -- enable debug output to stderr\n\
 -D -- run tracer process as a detached grandchild, not as parent\n\
 -f -- follow forks, -ff -- with output into separate files\n\
@@ -1650,7 +1652,7 @@ init(int argc, char *argv[])
 #endif
 	qualify("signal=all");
 	while ((c = getopt(argc, argv,
-		"+b:cCdfFhiqrtTvVxyz"
+		"+b:cCdfFhiqrtTvVwxyz"
 		"D"
 		"a:e:o:O:p:s:S:u:E:P:I:")) != EOF) {
 		switch (c) {
@@ -1702,6 +1704,9 @@ init(int argc, char *argv[])
 		case 'T':
 			Tflag = 1;
 			break;
+		case 'w':
+			count_wallclock = 1;
+			break;
 		case 'x':
 			xflag++;
 			break;
@@ -1791,6 +1796,10 @@ init(int argc, char *argv[])
 		error_msg_and_die("(-c or -C) and -ff are mutually exclusive");
 	}
 
+	if (count_wallclock && !cflag) {
+		error_msg_and_die("-w must be given with (-c or -C)");
+	}
+
 	/* See if they want to run as another user. */
 	if (username != NULL) {
 		struct passwd *pent;
-- 
1.7.1