From owner-svn-src-all@FreeBSD.ORG Sat Aug 21 13:15:56 2010 Return-Path: Delivered-To: svn-src-all@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id C0021106564A; Sat, 21 Aug 2010 13:15:56 +0000 (UTC) (envelope-from rpaulo@FreeBSD.org) Received: from svn.freebsd.org (svn.freebsd.org [IPv6:2001:4f8:fff6::2c]) by mx1.freebsd.org (Postfix) with ESMTP id B00F08FC17; Sat, 21 Aug 2010 13:15:56 +0000 (UTC) Received: from svn.freebsd.org (localhost [127.0.0.1]) by svn.freebsd.org (8.14.3/8.14.3) with ESMTP id o7LDFu2T070061; Sat, 21 Aug 2010 13:15:56 GMT (envelope-from rpaulo@svn.freebsd.org) Received: (from rpaulo@localhost) by svn.freebsd.org (8.14.3/8.14.3/Submit) id o7LDFuJ8070059; Sat, 21 Aug 2010 13:15:56 GMT (envelope-from rpaulo@svn.freebsd.org) Message-Id: <201008211315.o7LDFuJ8070059@svn.freebsd.org> From: Rui Paulo Date: Sat, 21 Aug 2010 13:15:56 +0000 (UTC) To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-vendor@freebsd.org X-SVN-Group: vendor MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Cc: Subject: svn commit: r211557 - vendor/dtracetoolkit/dist X-BeenThere: svn-src-all@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: "SVN commit messages for the entire src tree \(except for " user" and " projects" \)" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 21 Aug 2010 13:15:56 -0000 Author: rpaulo Date: Sat Aug 21 13:15:56 2010 New Revision: 211557 URL: http://svn.freebsd.org/changeset/base/211557 Log: Import dtruss from Brendan Gregg's DTraceToolkit. Sponsored by: The FreeBSD Foundation Added: vendor/dtracetoolkit/dist/ vendor/dtracetoolkit/dist/dtruss (contents, props changed) Added: vendor/dtracetoolkit/dist/dtruss ============================================================================== --- /dev/null 00:00:00 1970 (empty, because file is newly added) +++ vendor/dtracetoolkit/dist/dtruss Sat Aug 21 13:15:56 2010 (r211557) @@ -0,0 +1,467 @@ +#!/usr/bin/sh +# +# dtruss - print process system call time details. +# Written using DTrace (Solaris 10 3/05). +# +# $Id: dtruss 9 2007-08-07 10:21:07Z brendan $ +# +# USAGE: dtruss [-acdeflhoLs] [-t syscall] { -p PID | -n name | command } +# +# -p PID # examine this PID +# -n name # examine this process name +# -t syscall # examine this syscall only +# -a # print all details +# -c # print system call counts +# -d # print relative timestamps (us) +# -e # print elapsed times (us) +# -f # follow children as they are forked +# -l # force printing of pid/lwpid per line +# -o # print on cpu times (us) +# -s # print stack backtraces +# -L # don't print pid/lwpid per line +# -b bufsize # dynamic variable buf size (default is "4m") +# eg, +# dtruss df -h # run and examine the "df -h" command +# dtruss -p 1871 # examine PID 1871 +# dtruss -n tar # examine all processes called "tar" +# dtruss -f test.sh # run test.sh and follow children +# +# See the man page dtruss(1M) for further details. +# +# SEE ALSO: procsystime # DTraceToolkit +# dapptrace # DTraceToolkit +# truss +# +# COPYRIGHT: Copyright (c) 2005, 2006, 2007 Brendan Gregg. +# +# CDDL HEADER START +# +# The contents of this file are subject to the terms of the +# Common Development and Distribution License, Version 1.0 only +# (the "License"). You may not use this file except in compliance +# with the License. +# +# You can obtain a copy of the license at Docs/cddl1.txt +# or http://www.opensolaris.org/os/licensing. +# See the License for the specific language governing permissions +# and limitations under the License. +# +# CDDL HEADER END +# +# TODO: Track signals, more output formatting. +# +# 29-Apr-2005 Brendan Gregg Created this. +# 09-May-2005 " " Fixed evaltime (thanks Adam L.) +# 16-May-2005 " " Added -t syscall tracing. +# 17-Jun-2005 " " Added -s stack backtraces. +# 17-Jun-2005 " " Last update. +# 29-Jun-2007 " " Used progenyof() (thanks Aaron Gutman). +# 06-Aug-2007 " " Various updates. +# + + +############################## +# --- Process Arguments --- +# + +### Default variables +opt_pid=0; opt_name=0; pid=0; pname="."; opt_elapsed=0; opt_cpu=0 +opt_counts=0; opt_relative=0; opt_printid=0; opt_follow=0; opt_command=0 +command=""; opt_buf=0; buf="4m"; opt_trace=0; trace="."; opt_stack=0 + +### Process options +while getopts ab:cdefhln:op:st:L name +do + case $name in + b) opt_buf=1; buf=$OPTARG ;; + p) opt_pid=1; pid=$OPTARG ;; + n) opt_name=1; pname=$OPTARG ;; + t) opt_trace=1; trace=$OPTARG ;; + a) opt_counts=1; opt_relative=1; opt_elapsed=1; opt_follow=1 + opt_printid=1; opt_cpu=1 ;; + c) opt_counts=1 ;; + d) opt_relative=1 ;; + e) opt_elapsed=1 ;; + f) opt_follow=1 ;; + l) opt_printid=1 ;; + o) opt_cpu=1 ;; + L) opt_printid=-1 ;; + s) opt_stack=-1 ;; + h|?) cat <<-END >&2 + USAGE: dtruss [-acdefholLs] [-t syscall] { -p PID | -n name | command } + + -p PID # examine this PID + -n name # examine this process name + -t syscall # examine this syscall only + -a # print all details + -c # print syscall counts + -d # print relative times (us) + -e # print elapsed times (us) + -f # follow children (-p or cmd only) + -l # force printing pid/lwpid + -o # print on cpu times + -s # print stack backtraces + -L # don't print pid/lwpid + -b bufsize # dynamic variable buf size + eg, + dtruss df -h # run and examine "df -h" + dtruss -p 1871 # examine PID 1871 + dtruss -n tar # examine all processes called "tar" + dtruss -f test.sh # run test.sh and follow children + END + exit 1 + esac +done +shift `expr $OPTIND - 1` + +### Option logic +if [ $opt_pid -eq 0 -a $opt_name -eq 0 ]; then + opt_command=1 + if [ "$*" = "" ]; then + $0 -h + exit + fi + command="$*" # yes, I meant $*! +fi +if [ $opt_follow -eq 1 -o $opt_name -eq 1 ]; then + if [ $opt_printid -ne -1 ]; then + opt_printid=1 + else + opt_printid=0 + fi +fi +if [ $opt_follow -eq 1 -a $opt_name -eq 1 ]; then + echo "ERROR: -f option cannot be used with -n (use -p or cmd instead)." + exit 1 +fi + +### Option translation +if [ "$trace" = "exec" ]; then trace="exece"; fi +if [ "$trace" = "time" ]; then trace="gtime"; fi +if [ "$trace" = "exit" ]; then trace="rexit"; fi + + +################################# +# --- Main Program, DTrace --- +# + +### Define D Script +dtrace=' +#pragma D option quiet +#pragma D option switchrate=10 + +/* + * Command line arguments + */ +inline int OPT_command = '$opt_command'; +inline int OPT_follow = '$opt_follow'; +inline int OPT_printid = '$opt_printid'; +inline int OPT_relative = '$opt_relative'; +inline int OPT_elapsed = '$opt_elapsed'; +inline int OPT_cpu = '$opt_cpu'; +inline int OPT_counts = '$opt_counts'; +inline int OPT_pid = '$opt_pid'; +inline int OPT_name = '$opt_name'; +inline int OPT_trace = '$opt_trace'; +inline int OPT_stack = '$opt_stack'; +inline string NAME = "'$pname'"; +inline string TRACE = "'$trace'"; + +dtrace:::BEGIN +{ + /* print header */ + OPT_printid ? printf("%-9s ", "PID/LWP") : 1; + OPT_relative ? printf("%8s ", "RELATIVE") : 1; + OPT_elapsed ? printf("%7s ", "ELAPSD") : 1; + OPT_cpu ? printf("%6s ", "CPU") : 1; + printf("SYSCALL(args) \t\t = return\n"); +} + +/* + * Save syscall entry info + */ +syscall:::entry +/((OPT_command || OPT_pid) && pid == $target) || + (OPT_name && execname == NAME) || + (OPT_follow && progenyof($target))/ +{ + /* set start details */ + self->start = timestamp; + self->vstart = vtimestamp; + self->arg0 = arg0; + self->arg1 = arg1; + self->arg2 = arg2; + + /* count occurances */ + OPT_counts == 1 ? @Counts[probefunc] = count() : 1; +} + +/* + * Follow children + */ +syscall::fork*:return +/(OPT_follow && progenyof($target)) && (!OPT_trace || (TRACE == probefunc))/ +{ + /* print output */ + self->code = errno == 0 ? "" : "Err#"; + OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; + OPT_relative ? printf("%8d: ", vtimestamp/1000) : 1; + OPT_elapsed ? printf("%7d: ", 0) : 1; + OPT_cpu ? printf("%6d ", 0) : 1; + printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, + self->arg0, self->arg1, self->arg2, (int)arg0, self->code, + (int)errno); +} + +/* + * Check for syscall tracing + */ +syscall:::entry +/OPT_trace && probefunc != TRACE/ +{ + /* drop info */ + self->start = 0; + self->vstart = 0; + self->arg0 = 0; + self->arg1 = 0; + self->arg2 = 0; +} + +/* + * Print return data + */ + +/* + * The following code is written in an intentionally repetative way. + * The first versions had no code redundancies, but performed badly during + * benchmarking. The priority here is speed, not cleverness. I know there + * are many obvious shortcuts to this code, I have tried them. This style has + * shown in benchmarks to be the fastest (fewest probes fired, fewest actions). + */ + +/* print 3 args, return as hex */ +syscall::lwp_sigmask:return +/self->start/ +{ + /* calculate elapsed time */ + this->elapsed = timestamp - self->start; + self->start = 0; + this->cpu = vtimestamp - self->vstart; + self->vstart = 0; + self->code = errno == 0 ? "" : "Err#"; + + /* print optional fields */ + OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; + OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; + OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; + OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; + + /* print main data */ + printf("%s(0x%X, 0x%X, 0x%X)\t\t = 0x%X %s%d\n", probefunc, + (int)self->arg0, self->arg1, self->arg2, (int)arg0, + self->code, (int)errno); + OPT_stack ? ustack() : 1; + OPT_stack ? trace("\n") : 1; + self->arg0 = 0; + self->arg1 = 0; + self->arg2 = 0; +} + +/* print 3 args, arg0 as a string */ +syscall::stat*:return, +syscall::lstat*:return, +syscall::open*:return, +syscall::resolvepath:return +/self->start/ +{ + /* calculate elapsed time */ + this->elapsed = timestamp - self->start; + self->start = 0; + this->cpu = vtimestamp - self->vstart; + self->vstart = 0; + self->code = errno == 0 ? "" : "Err#"; + + /* print optional fields */ + OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; + OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; + OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; + OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; + + /* print main data */ + printf("%s(\"%S\", 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, + copyinstr(self->arg0), self->arg1, self->arg2, (int)arg0, + self->code, (int)errno); + OPT_stack ? ustack() : 1; + OPT_stack ? trace("\n") : 1; + self->arg0 = 0; + self->arg1 = 0; + self->arg2 = 0; +} + +/* print 3 args, arg1 as a string */ +syscall::write:return, +syscall::pwrite:return, +syscall::*read*:return +/self->start/ +{ + /* calculate elapsed time */ + this->elapsed = timestamp - self->start; + self->start = 0; + this->cpu = vtimestamp - self->vstart; + self->vstart = 0; + self->code = errno == 0 ? "" : "Err#"; + + /* print optional fields */ + OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; + OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; + OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; + OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; + + /* print main data */ + printf("%s(0x%X, \"%S\", 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0, + stringof(copyin(self->arg1, self->arg2)), self->arg2, (int)arg0, + self->code, (int)errno); + OPT_stack ? ustack() : 1; + OPT_stack ? trace("\n") : 1; + self->arg0 = 0; + self->arg1 = 0; + self->arg2 = 0; +} + +/* print 0 arg output */ +syscall::gtime:return, +syscall::*fork*:return +/self->start/ +{ + /* calculate elapsed time */ + this->elapsed = timestamp - self->start; + self->start = 0; + this->cpu = vtimestamp - self->vstart; + self->vstart = 0; + self->code = errno == 0 ? "" : "Err#"; + + /* print optional fields */ + OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; + OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; + OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; + OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; + + /* print main data */ + printf("%s()\t\t = %d %s%d\n", probefunc, + (int)arg0, self->code, (int)errno); + OPT_stack ? ustack() : 1; + OPT_stack ? trace("\n") : 1; + self->arg0 = 0; + self->arg1 = 0; + self->arg2 = 0; +} + +/* print 1 arg output */ +syscall::brk:return, +syscall::times:return, +syscall::stime:return, +syscall::close:return +/self->start/ +{ + /* calculate elapsed time */ + this->elapsed = timestamp - self->start; + self->start = 0; + this->cpu = vtimestamp - self->vstart; + self->vstart = 0; + self->code = errno == 0 ? "" : "Err#"; + + /* print optional fields */ + OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; + OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; + OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; + OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; + + /* print main data */ + printf("%s(0x%X)\t\t = %d %s%d\n", probefunc, self->arg0, + (int)arg0, self->code, (int)errno); + OPT_stack ? ustack() : 1; + OPT_stack ? trace("\n") : 1; + self->arg0 = 0; + self->arg1 = 0; + self->arg2 = 0; +} + +/* print 2 arg output */ +syscall::utime:return, +syscall::munmap:return +/self->start/ +{ + /* calculate elapsed time */ + this->elapsed = timestamp - self->start; + self->start = 0; + this->cpu = vtimestamp - self->vstart; + self->vstart = 0; + self->code = errno == 0 ? "" : "Err#"; + + /* print optional fields */ + OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; + OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; + OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; + OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; + + /* print main data */ + printf("%s(0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0, + self->arg1, (int)arg0, self->code, (int)errno); + OPT_stack ? ustack() : 1; + OPT_stack ? trace("\n") : 1; + self->arg0 = 0; + self->arg1 = 0; + self->arg2 = 0; +} + +/* print 3 arg output - default */ +syscall:::return +/self->start/ +{ + /* calculate elapsed time */ + this->elapsed = timestamp - self->start; + self->start = 0; + this->cpu = vtimestamp - self->vstart; + self->vstart = 0; + self->code = errno == 0 ? "" : "Err#"; + + /* print optional fields */ + OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; + OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; + OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; + OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; + + /* print main data */ + printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0, + self->arg1, self->arg2, (int)arg0, self->code, (int)errno); + OPT_stack ? ustack() : 1; + OPT_stack ? trace("\n") : 1; + self->arg0 = 0; + self->arg1 = 0; + self->arg2 = 0; +} + +/* program exited */ +proc:::exit +/(OPT_command || OPT_pid) && pid == $target/ +{ + exit(0); +} + +/* print counts */ +dtrace:::END +{ + OPT_counts == 1 ? printf("\n%-32s %16s\n", "CALL", "COUNT") : 1; + OPT_counts == 1 ? printa("%-32s %@16d\n", @Counts) : 1; +} +' + +### Run DTrace +if [ $opt_command -eq 1 ]; then + /usr/sbin/dtrace -x dynvarsize=$buf -x evaltime=exec -n "$dtrace" \ + -c "$command" >&2 +elif [ $opt_pid -eq 1 ]; then + /usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" -p "$pid" >&2 +else + /usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" >&2 +fi