[PATCH] Optionally produce stats on 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 new flag (-w) 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.

Signed-off-by: Mark Hills <mark.hills at framestore.com>
---
 NEWS     |    3 +++
 count.c  |    4 ++--
 defs.h   |    1 +
 strace.1 |    4 ++++
 strace.c |   11 ++++++++++-
 5 files changed, 20 insertions(+), 3 deletions(-)

diff --git a/NEWS b/NEWS
index eed78c2..895649c 100644
--- a/NEWS
+++ b/NEWS
@@ -1,6 +1,9 @@
 Noteworthy changes in release ?.? (????-??-??)
 ==============================================
 
+* Improvements
+  * Added -w option to produce stats on syscall latency
+
 Noteworthy changes in release 4.8 (2013-06-03)
 ==============================================
 
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 4e06a92..a6ea5a0 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