From 7c4db354e0d04c7adcb1a39ee270e0dfae194d9d Mon Sep 17 00:00:00 2001 From: jhb Date: Thu, 21 Apr 2016 18:44:53 +0000 Subject: [PATCH] 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. git-svn-id: svn://svn.freebsd.org/base/stable/10@298427 ccf9f872-aa2e-dd11-9fc8-001c23d0bc1f --- usr.bin/truss/extern.h | 1 + usr.bin/truss/main.c | 5 ++- usr.bin/truss/setup.c | 90 ++++++++++++++++++++-------------------- usr.bin/truss/syscalls.c | 23 +--------- usr.bin/truss/truss.1 | 12 ++++-- usr.bin/truss/truss.h | 1 + 6 files changed, 60 insertions(+), 72 deletions(-) diff --git a/usr.bin/truss/extern.h b/usr.bin/truss/extern.h index 708d055cf..5ce3d3be8 100644 --- a/usr.bin/truss/extern.h +++ b/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); diff --git a/usr.bin/truss/main.c b/usr.bin/truss/main.c index 5eec9538f..75469cee0 100644 --- a/usr.bin/truss/main.c +++ b/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(); } diff --git a/usr.bin/truss/setup.c b/usr.bin/truss/setup.c index c001e9d08..9487c9ea9 100644 --- a/usr.bin/truss/setup.c +++ b/usr.bin/truss/setup.c @@ -439,26 +439,46 @@ exit_syscall(struct trussinfo *info, struct ptrace_lwpinfo *pl) } } -static void -report_exit(struct trussinfo *info, siginfo_t *si) +int +print_line_prefix(struct trussinfo *info) { struct timespec timediff; + struct threadinfo *t; + int len; - if (info->flags & FOLLOWFORKS) - fprintf(info->outfile, "%5d: ", si->si_pid); - clock_gettime(CLOCK_REALTIME, &info->curthread->after); + 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(&info->curthread->after, &info->start_time, - &timediff); - fprintf(info->outfile, "%jd.%09ld ", (intmax_t)timediff.tv_sec, - timediff.tv_nsec); + 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(&info->curthread->after, &info->curthread->before, - &timediff); - fprintf(info->outfile, "%jd.%09ld ", (intmax_t)timediff.tv_sec, - timediff.tv_nsec); + 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 threadinfo *t; + + 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, "\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) diff --git a/usr.bin/truss/syscalls.c b/usr.bin/truss/syscalls.c index 024ad1979..985a074cb 100644 --- a/usr.bin/truss/syscalls.c +++ b/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++; diff --git a/usr.bin/truss/truss.1 b/usr.bin/truss/truss.1 index b5a1cfefb..f5acb7122 100644 --- a/usr.bin/truss/truss.1 +++ b/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, diff --git a/usr.bin/truss/truss.h b/usr.bin/truss/truss.h index 5a57de700..4ba80a004 100644 --- a/usr.bin/truss/truss.h +++ b/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; -- 2.45.0