From owner-svn-src-head@freebsd.org Tue Feb 23 19:56:31 2016 Return-Path: Delivered-To: svn-src-head@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 1A9CFAB29A7; Tue, 23 Feb 2016 19:56:31 +0000 (UTC) (envelope-from jhb@FreeBSD.org) Received: from repo.freebsd.org (repo.freebsd.org [IPv6:2610:1c1:1:6068::e6a:0]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id EA29CB67; Tue, 23 Feb 2016 19:56:30 +0000 (UTC) (envelope-from jhb@FreeBSD.org) Received: from repo.freebsd.org ([127.0.1.37]) by repo.freebsd.org (8.15.2/8.15.2) with ESMTP id u1NJuT04014241; Tue, 23 Feb 2016 19:56:29 GMT (envelope-from jhb@FreeBSD.org) Received: (from jhb@localhost) by repo.freebsd.org (8.15.2/8.15.2/Submit) id u1NJuTQ2014235; Tue, 23 Feb 2016 19:56:29 GMT (envelope-from jhb@FreeBSD.org) Message-Id: <201602231956.u1NJuTQ2014235@repo.freebsd.org> X-Authentication-Warning: repo.freebsd.org: jhb set sender to jhb@FreeBSD.org using -f From: John Baldwin Date: Tue, 23 Feb 2016 19:56:29 +0000 (UTC) To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: svn commit: r295930 - head/usr.bin/truss X-SVN-Group: head MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-BeenThere: svn-src-head@freebsd.org X-Mailman-Version: 2.1.20 Precedence: list List-Id: SVN commit messages for the src tree for head/-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 23 Feb 2016 19:56:31 -0000 Author: jhb Date: Tue Feb 23 19:56:29 2016 New Revision: 295930 URL: https://svnweb.freebsd.org/changeset/base/295930 Log: 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. Reviewed by: kib MFC after: 1 month Differential Revision: https://reviews.freebsd.org/D5363 Modified: head/usr.bin/truss/extern.h head/usr.bin/truss/main.c head/usr.bin/truss/setup.c head/usr.bin/truss/syscalls.c head/usr.bin/truss/truss.1 head/usr.bin/truss/truss.h Modified: head/usr.bin/truss/extern.h ============================================================================== --- head/usr.bin/truss/extern.h Tue Feb 23 18:50:34 2016 (r295929) +++ head/usr.bin/truss/extern.h Tue Feb 23 19:56:29 2016 (r295930) @@ -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); Modified: head/usr.bin/truss/main.c ============================================================================== --- head/usr.bin/truss/main.c Tue Feb 23 18:50:34 2016 (r295929) +++ head/usr.bin/truss/main.c Tue Feb 23 19:56:29 2016 (r295930) @@ -96,7 +96,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); @@ -132,6 +132,9 @@ main(int ac, char **av) case 'S': /* Don't trace signals */ trussinfo->flags |= NOSIGS; break; + case 'H': + trussinfo->flags |= DISPLAYTIDS; + break; default: usage(); } Modified: head/usr.bin/truss/setup.c ============================================================================== --- head/usr.bin/truss/setup.c Tue Feb 23 18:50:34 2016 (r295929) +++ head/usr.bin/truss/setup.c Tue Feb 23 19:56:29 2016 (r295930) @@ -439,26 +439,46 @@ exit_syscall(struct trussinfo *info, str } } -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, sigi } 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) Modified: head/usr.bin/truss/syscalls.c ============================================================================== --- head/usr.bin/truss/syscalls.c Tue Feb 23 18:50:34 2016 (r295929) +++ head/usr.bin/truss/syscalls.c Tue Feb 23 19:56:29 2016 (r295930) @@ -2005,38 +2005,18 @@ print_arg(struct syscall_args *sc, unsig 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++) { @@ -2063,7 +2043,6 @@ print_syscall_ret(struct trussinfo *trus 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++; Modified: head/usr.bin/truss/truss.1 ============================================================================== --- head/usr.bin/truss/truss.1 Tue Feb 23 18:50:34 2016 (r295929) +++ head/usr.bin/truss/truss.1 Tue Feb 23 19:56:29 2016 (r295930) @@ -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 .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, Modified: head/usr.bin/truss/truss.h ============================================================================== --- head/usr.bin/truss/truss.h Tue Feb 23 18:50:34 2016 (r295929) +++ head/usr.bin/truss/truss.h Tue Feb 23 19:56:29 2016 (r295930) @@ -35,6 +35,7 @@ #define EXECVEARGS 0x00000010 #define EXECVEENVS 0x00000020 #define COUNTONLY 0x00000040 +#define DISPLAYTIDS 0x00000080 struct procinfo; struct trussinfo;