MFC 295930:

Add support for displaying thread IDs to truss(1).

- Consolidate duplicate code for printing the metadata at the start of
  each line into a shared function.
- Add an -H option which will log the thread ID of the relevant thread
  for each event.

While here, remove some extraneous calls to clock_gettime() in
print_syscall() and print_syscall_ret().  The caller of print_syscall_ret()
always updates the current thread's "after" time before it is called.

usr.bin/truss/extern.h

@@ -31,6 +31,7 @@
  * $FreeBSD$
  */
 
+extern int print_line_prefix(struct trussinfo *);
 extern void setup_and_wait(struct trussinfo *, char **);
 extern void start_tracing(struct trussinfo *, pid_t);
 extern void restore_proc(int);

usr.bin/truss/main.c

@@ -95,7 +95,7 @@ main(int ac, char **av)
 	trussinfo->curthread = NULL;
 	LIST_INIT(&trussinfo->proclist);
 	init_syscalls();
-	while ((c = getopt(ac, av, "p:o:facedDs:S")) != -1) {
+	while ((c = getopt(ac, av, "p:o:facedDs:SH")) != -1) {
 		switch (c) {
 		case 'p':	/* specified pid */
 			pid = atoi(optarg);
@@ -131,6 +131,9 @@ main(int ac, char **av)
 		case 'S':	/* Don't trace signals */
 			trussinfo->flags |= NOSIGS;
 			break;
+		case 'H':
+			trussinfo->flags |= DISPLAYTIDS;
+			break;
 		default:
 			usage();
 		}

usr.bin/truss/setup.c

@@ -439,26 +439,46 @@ exit_syscall(struct trussinfo *info, struct ptrace_lwpinfo *pl)
 	}
 }
 
+int
+print_line_prefix(struct trussinfo *info)
+{
+	struct timespec timediff;
+	struct threadinfo *t;
+	int len;
+
+	len = 0;
+	t = info->curthread;
+	if (info->flags & (FOLLOWFORKS | DISPLAYTIDS)) {
+		if (info->flags & FOLLOWFORKS)
+			len += fprintf(info->outfile, "%5d", t->proc->pid);
+		if ((info->flags & (FOLLOWFORKS | DISPLAYTIDS)) ==
+		    (FOLLOWFORKS | DISPLAYTIDS))
+			len += fprintf(info->outfile, " ");
+		if (info->flags & DISPLAYTIDS)
+			len += fprintf(info->outfile, "%6d", t->tid);
+		len += fprintf(info->outfile, ": ");
+	}
+	if (info->flags & ABSOLUTETIMESTAMPS) {
+		timespecsubt(&t->after, &info->start_time, &timediff);
+		len += fprintf(info->outfile, "%jd.%09ld ",
+		    (intmax_t)timediff.tv_sec, timediff.tv_nsec);
+	}
+	if (info->flags & RELATIVETIMESTAMPS) {
+		timespecsubt(&t->after, &t->before, &timediff);
+		len += fprintf(info->outfile, "%jd.%09ld ",
+		    (intmax_t)timediff.tv_sec, timediff.tv_nsec);
+	}
+	return (len);
+}
+
 static void
 report_exit(struct trussinfo *info, siginfo_t *si)
 {
-	struct timespec timediff;
+	struct threadinfo *t;
 
-	if (info->flags & FOLLOWFORKS)
-		fprintf(info->outfile, "%5d: ", si->si_pid);
-	clock_gettime(CLOCK_REALTIME, &info->curthread->after);
-	if (info->flags & ABSOLUTETIMESTAMPS) {
-		timespecsubt(&info->curthread->after, &info->start_time,
-		    &timediff);
-		fprintf(info->outfile, "%jd.%09ld ", (intmax_t)timediff.tv_sec,
-		    timediff.tv_nsec);
-	}
-	if (info->flags & RELATIVETIMESTAMPS) {
-		timespecsubt(&info->curthread->after, &info->curthread->before,
-		    &timediff);
-		fprintf(info->outfile, "%jd.%09ld ", (intmax_t)timediff.tv_sec,
-		    timediff.tv_nsec);
-	}
+	t = info->curthread;
+	clock_gettime(CLOCK_REALTIME, &t->after);
+	print_line_prefix(info);
 	if (si->si_code == CLD_EXITED)
 		fprintf(info->outfile, "process exit, rval = %u\n",
 		    si->si_status);
@@ -469,48 +489,26 @@ report_exit(struct trussinfo *info, siginfo_t *si)
 }
 
 static void
-report_new_child(struct trussinfo *info, pid_t pid)
+report_new_child(struct trussinfo *info)
 {
-	struct timespec timediff;
+	struct threadinfo *t;
 
-	clock_gettime(CLOCK_REALTIME, &info->curthread->after);
-	assert(info->flags & FOLLOWFORKS);
-	fprintf(info->outfile, "%5d: ", pid);
-	if (info->flags & ABSOLUTETIMESTAMPS) {
-		timespecsubt(&info->curthread->after, &info->start_time,
-		    &timediff);
-		fprintf(info->outfile, "%jd.%09ld ", (intmax_t)timediff.tv_sec,
-		    timediff.tv_nsec);
-	}
-	if (info->flags & RELATIVETIMESTAMPS) {
-		timediff.tv_sec = 0;
-		timediff.tv_nsec = 0;
-		fprintf(info->outfile, "%jd.%09ld ", (intmax_t)timediff.tv_sec,
-		    timediff.tv_nsec);
-	}
+	t = info->curthread;
+	clock_gettime(CLOCK_REALTIME, &t->after);
+	t->before = t->after;
+	print_line_prefix(info);
 	fprintf(info->outfile, "<new process>\n");
 }
 
 static void
 report_signal(struct trussinfo *info, siginfo_t *si)
 {
-	struct timespec timediff;
+	struct threadinfo *t;
 	char *signame;
 
-	if (info->flags & FOLLOWFORKS)
-		fprintf(info->outfile, "%5d: ", si->si_pid);
-	if (info->flags & ABSOLUTETIMESTAMPS) {
-		timespecsubt(&info->curthread->after, &info->start_time,
-		    &timediff);
-		fprintf(info->outfile, "%jd.%09ld ", (intmax_t)timediff.tv_sec,
-		    timediff.tv_nsec);
-	}
-	if (info->flags & RELATIVETIMESTAMPS) {
-		timespecsubt(&info->curthread->after, &info->curthread->before,
-		    &timediff);
-		fprintf(info->outfile, "%jd.%09ld ", (intmax_t)timediff.tv_sec,
-		    timediff.tv_nsec);
-	}
+	t = info->curthread;
+	clock_gettime(CLOCK_REALTIME, &t->after);
+	print_line_prefix(info);
 	signame = strsig(si->si_status);
 	fprintf(info->outfile, "SIGNAL %u (%s)\n", si->si_status,
 	    signame == NULL ? "?" : signame);
@@ -572,7 +570,7 @@ eventloop(struct trussinfo *info)
 				pending_signal = 0;
 			} else if (pl.pl_flags & PL_FLAG_CHILD) {
 				if ((info->flags & COUNTONLY) == 0)
-					report_new_child(info, si.si_pid);
+					report_new_child(info);
 				pending_signal = 0;
 			} else {
 				if ((info->flags & NOSIGS) == 0)

usr.bin/truss/syscalls.c

@@ -1625,38 +1625,18 @@ print_arg(struct syscall_args *sc, unsigned long *args, long *retval,
 void
 print_syscall(struct trussinfo *trussinfo)
 {
-	struct timespec timediff;
 	struct threadinfo *t;
 	const char *name;
 	char **s_args;
 	int i, len, nargs;
 
-	len = 0;
 	t = trussinfo->curthread;
-	if (trussinfo->flags & FOLLOWFORKS)
-		len += fprintf(trussinfo->outfile, "%5d: ",
-		    t->proc->pid);
 
 	name = t->cs.name;
 	nargs = t->cs.nargs;
 	s_args = t->cs.s_args;
-	if (name != NULL && (strcmp(name, "execve") == 0 ||
-	    strcmp(name, "exit") == 0)) {
-		clock_gettime(CLOCK_REALTIME, &t->after);
-	}
-
-	if (trussinfo->flags & ABSOLUTETIMESTAMPS) {
-		timespecsubt(&t->after, &trussinfo->start_time, &timediff);
-		len += fprintf(trussinfo->outfile, "%jd.%09ld ",
-		    (intmax_t)timediff.tv_sec, timediff.tv_nsec);
-	}
-
-	if (trussinfo->flags & RELATIVETIMESTAMPS) {
-		timespecsubt(&t->after, &t->before, &timediff);
-		len += fprintf(trussinfo->outfile, "%jd.%09ld ",
-		    (intmax_t)timediff.tv_sec, timediff.tv_nsec);
-	}
 
+	len = print_line_prefix(trussinfo);
 	len += fprintf(trussinfo->outfile, "%s(", name);
 
 	for (i = 0; i < nargs; i++) {
@@ -1683,7 +1663,6 @@ print_syscall_ret(struct trussinfo *trussinfo, int errorp, long *retval)
 	t = trussinfo->curthread;
 	sc = t->cs.sc;
 	if (trussinfo->flags & COUNTONLY) {
-		clock_gettime(CLOCK_REALTIME, &t->after);
 		timespecsubt(&t->after, &t->before, &timediff);
 		timespecadd(&sc->time, &timediff, &sc->time);
 		sc->ncalls++;

usr.bin/truss/truss.1

@@ -1,6 +1,6 @@
 .\" $FreeBSD$
 .\"
-.Dd October 9, 2015
+.Dd February 23, 2016
 .Dt TRUSS 1
 .Os
 .Sh NAME
@@ -8,12 +8,12 @@
 .Nd trace system calls
 .Sh SYNOPSIS
 .Nm
-.Op Fl facedDS
+.Op Fl facedDHS
 .Op Fl o Ar file
 .Op Fl s Ar strsize
 .Fl p Ar pid
 .Nm
-.Op Fl facedDS
+.Op Fl facedDHS
 .Op Fl o Ar file
 .Op Fl s Ar strsize
 .Ar command Op Ar args
@@ -32,6 +32,10 @@ Trace descendants of the original traced process created by
 .Xr fork 2 ,
 .Xr vfork 2 ,
 etc.
+To distinguish events between processes,
+the process ID
+.Pq PID
+of the process is included in the output of each event.
 .It Fl a
 Show the argument strings that are passed in each
 .Xr execve 2
@@ -52,6 +56,8 @@ since the trace was started.
 .It Fl D
 Include timestamps in the output showing the time elapsed
 since the last recorded event.
+.It Fl H
+Include the thread ID of in the output of each event.
 .It Fl S
 Do not display information about signals received by the process.
 (Normally,

usr.bin/truss/truss.h

@@ -35,6 +35,7 @@
 #define	EXECVEARGS		0x00000010
 #define	EXECVEENVS		0x00000020
 #define	COUNTONLY		0x00000040
+#define	DISPLAYTIDS		0x00000080
 
 struct procinfo;
 struct trussinfo;