Optionally produce stats on syscall latency

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@framestore.com>

diff --git a/NEWS b/NEWS
index eed78c298f1c11ddcf895b41f1974d0b864b19be..895649cc22accc0d5da9d77298fe7e3e0e73b2ba 100644 (file)
--- 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 b0372a11ee7473d123d315b8aead089d463dc8f0..e41994d3715a9728c7cf1070da9b85d6caed2925 100644 (file)
--- 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;
 };
@@ -102,7 +102,7 @@ count_syscall(struct tcb *tcp, const struct timeval *syscall_exiting_tv)
        }
        if (tv_cmp(tv, &shortest) < 0)
                shortest = *tv;
-       tv_add(&cc->time, &cc->time, tv);
+       tv_add(&cc->time, &cc->time, count_wallclock ? &wtv : tv);
 }
 
 static int

diff --git a/defs.h b/defs.h
index 002271ade27164d96b0453f80d3e1c8bc5ca332d..34a887483e497c9cd72507423682005fb1c19bb3 100644 (file)
--- 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 6ca4bdaa018747477044399f7be5450d2cd295ef..4d26be52bc6fda7d256857d0d8aac4f4c2435100 100644 (file)
--- 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 8a49340f76ddf4065aeb1925e8e54e385e2bb906..35ee7bed5629b12ee95d3be5b490de89fcc72f60 100644 (file)
--- 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;