Skip to content
Permalink
Browse files

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>
  • Loading branch information...
Mark Hills authored and ldv-alt committed May 28, 2014
1 parent ac5133d commit e53bf23f1c33076090b51184b82af4dd98d0c51c
Showing with 20 additions and 3 deletions.
  1. +3 −0 NEWS
  2. +2 −2 count.c
  3. +1 −0 defs.h
  4. +4 −0 strace.1
  5. +10 −1 strace.c
3 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)
==============================================

@@ -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
1 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;
@@ -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
@@ -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;

0 comments on commit e53bf23

Please sign in to comment.
You can’t perform that action at this time.