1N/A# dtruss - print process system call time details. 1N/A# Written using DTrace (Solaris 10 3/05). 1N/A# $Id: dtruss 9 2007-08-07 10:21:07Z brendan $ 1N/A# USAGE: dtruss [-acdeflhoLs] [-t syscall] { -p PID | -n name | command } 1N/A# -p PID # examine this PID 1N/A# -n name # examine this process name 1N/A# -t syscall # examine this syscall only 1N/A# -a # print all details 1N/A# -c # print system call counts 1N/A# -d # print relative timestamps (us) 1N/A# -e # print elapsed times (us) 1N/A# -f # follow children as they are forked 1N/A# -o # print on cpu times (us) 1N/A# -s # print stack backtraces 1N/A# -b bufsize # dynamic variable buf size (default is "4m") 1N/A# dtruss df -h # run and examine the "df -h" command 1N/A# dtruss -p 1871 # examine PID 1871 1N/A# dtruss -n tar # examine all processes called "tar" 1N/A# See the man page dtruss(1M) for further details. 1N/A# SEE ALSO: procsystime # DTraceToolkit 1N/A# dapptrace # DTraceToolkit 1N/A# COPYRIGHT: Copyright (c) 2005, 2006, 2007 Brendan Gregg. 1N/A# The contents of this file are subject to the terms of the 1N/A# Common Development and Distribution License, Version 1.0 only 1N/A# (the "License"). You may not use this file except in compliance 1N/A# See the License for the specific language governing permissions 1N/A# and limitations under the License. 1N/A# TODO: Track signals, more output formatting. 1N/A# 29-Apr-2005 Brendan Gregg Created this. 1N/A# 09-May-2005 " " Fixed evaltime (thanks Adam L.) 1N/A# 16-May-2005 " " Added -t syscall tracing. 1N/A# 17-Jun-2005 " " Added -s stack backtraces. 1N/A# 17-Jun-2005 " " Last update. 1N/A# 29-Jun-2007 " " Used progenyof() (thanks Aaron Gutman). 1N/A# 06-Aug-2007 " " Various updates. 1N/A############################## 1N/A# --- Process Arguments --- 1N/A### Default variables 1N/A USAGE: dtruss [-acdefholLs] [-t syscall] { -p PID | -n name | command } 1N/A -p PID # examine this PID 1N/A -n name # examine this process name 1N/A -t syscall # examine this syscall only 1N/A -a # print all details 1N/A -c # print syscall counts 1N/A -d # print relative times (us) 1N/A -e # print elapsed times (us) 1N/A -f # follow children (-p or cmd only) 1N/A -l # force printing pid/lwpid 1N/A -o # print on cpu times 1N/A -s # print stack backtraces 1N/A -L # don't print pid/lwpid 1N/A -b bufsize # dynamic variable buf size 1N/A dtruss df -h # run and examine "df -h" 1N/A dtruss -p 1871 # examine PID 1871 1N/A dtruss -n tar # examine all processes called "tar" 1N/A dtruss -f test.sh # run test.sh and follow children 1N/Ashift `expr $OPTIND - 1` 1N/Aif [ $opt_pid -eq 0 -a $opt_name -eq 0 ]; then 1N/A if [ "$*" = "" ]; then 1N/A command="$*" # yes, I meant $*! 1N/Aif [ $opt_follow -eq 1 -o $opt_name -eq 1 ]; then 1N/A if [ $opt_printid -ne -1 ]; then 1N/Aif [ $opt_follow -eq 1 -a $opt_name -eq 1 ]; then 1N/A echo "ERROR: -f option cannot be used with -n (use -p or cmd instead)." 1N/A### Option translation 1N/Aif [ "$trace" = "exec" ]; then trace="exece"; fi 1N/Aif [ "$trace" = "fork" ]; then trace="forksys"; fi 1N/Aif [ "$trace" = "time" ]; then trace="gtime"; fi 1N/Aif [ "$trace" = "exit" ]; then trace="rexit"; fi 1N/A################################# 1N/A# --- Main Program, DTrace --- 1N/A#pragma D option quiet 1N/A#pragma D option switchrate=10 1N/A * Command line arguments 1N/Ainline int OPT_command = '$opt_command'; 1N/Ainline int OPT_follow = '$opt_follow'; 1N/Ainline int OPT_printid = '$opt_printid'; 1N/Ainline int OPT_relative = '$opt_relative'; 1N/Ainline int OPT_elapsed = '$opt_elapsed'; 1N/Ainline int OPT_cpu = '$opt_cpu'; 1N/Ainline int OPT_counts = '$opt_counts'; 1N/Ainline int OPT_pid = '$opt_pid'; 1N/Ainline int OPT_name = '$opt_name'; 1N/Ainline int OPT_trace = '$opt_trace'; 1N/Ainline int OPT_stack = '$opt_stack'; 1N/Ainline string NAME = "'$pname'"; 1N/Ainline string TRACE = "'$trace'"; 1N/A OPT_printid ? printf("%-9s ", "PID/LWP") : 1; 1N/A OPT_relative ? printf("%8s ", "RELATIVE") : 1; 1N/A OPT_elapsed ? printf("%7s ", "ELAPSD") : 1; 1N/A OPT_cpu ? printf("%6s ", "CPU") : 1; 1N/A printf("SYSCALL(args) \t\t = return\n"); 1N/A * Save syscall entry info 1N/A/((OPT_command || OPT_pid) && pid == $target) || 1N/A (OPT_name && execname == NAME) || 1N/A (OPT_follow && progenyof($target))/ 1N/A /* set start details */ 1N/A self->start = timestamp; 1N/A self->vstart = vtimestamp; 1N/A /* count occurances */ 1N/A OPT_counts == 1 ? @Counts[probefunc] = count() : 1; 1N/A * (vfork() is only executed by a process running in an S10-branded zone.) 1N/Asyscall::forksys:return, 1N/Asyscall::vfork:return 1N/A/(OPT_follow && progenyof($target)) && (!OPT_trace || (TRACE == probefunc))/ 1N/A self->code = errno == 0 ? "" : "Err#"; 1N/A OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; 1N/A OPT_relative ? printf("%8d: ", vtimestamp/1000) : 1; 1N/A OPT_elapsed ? printf("%7d: ", 0) : 1; 1N/A OPT_cpu ? printf("%6d ", 0) : 1; 1N/A printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, 1N/A self->arg0, self->arg1, self->arg2, (int)arg0, self->code, 1N/A * Check for syscall tracing 1N/A/OPT_trace && probefunc != TRACE/ 1N/A * The following code is written in an intentionally repetative way. 1N/A * The first versions had no code redundancies, but performed badly during 1N/A * benchmarking. The priority here is speed, not cleverness. I know there 1N/A * are many obvious shortcuts to this code, I have tried them. This style has 1N/A * shown in benchmarks to be the fastest (fewest probes fired, fewest actions). 1N/A/* print 3 args, return as hex */ 1N/Asyscall::lwp_sigmask:return 1N/A /* calculate elapsed time */ 1N/A this->elapsed = timestamp - self->start; 1N/A this->cpu = vtimestamp - self->vstart; 1N/A self->code = errno == 0 ? "" : "Err#"; 1N/A /* print optional fields */ 1N/A OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; 1N/A OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; 1N/A OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; 1N/A OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; 1N/A /* print main data */ 1N/A printf("%s(0x%X, 0x%X, 0x%X)\t\t = 0x%X %s%d\n", probefunc, 1N/A (int)self->arg0, self->arg1, self->arg2, (int)arg0, 1N/A self->code, (int)errno); 1N/A OPT_stack ? ustack() : 1; 1N/A OPT_stack ? trace("\n") : 1; 1N/A/* print 1 arg, arg0 as a string */ 1N/Asyscall::chdir:return, 1N/Asyscall::chroot:return 1N/A /* calculate elapsed time */ 1N/A this->elapsed = timestamp - self->start; 1N/A this->cpu = vtimestamp - self->vstart; 1N/A self->code = errno == 0 ? "" : "Err#"; 1N/A /* print optional fields */ 1N/A OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; 1N/A OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; 1N/A OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; 1N/A OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; 1N/A /* print main data */ 1N/A printf("%s(\"%S\")\t\t = %d %s%d\n", probefunc, 1N/A copyinstr(self->arg0), (int)arg0, 1N/A self->code, (int)errno); 1N/A OPT_stack ? ustack() : 1; 1N/A OPT_stack ? trace("\n") : 1; 1N/A/* print 2 args, arg0 as a string */ 1N/Asyscall::getcwd:return, 1N/Asyscall::pathconf:return, 1N/Asyscall::statvfs64:return, 1N/Asyscall::statvfs:return, 1N/Asyscall::umount2:return 1N/A /* calculate elapsed time */ 1N/A this->elapsed = timestamp - self->start; 1N/A this->cpu = vtimestamp - self->vstart; 1N/A self->code = errno == 0 ? "" : "Err#"; 1N/A /* print optional fields */ 1N/A OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; 1N/A OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; 1N/A OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; 1N/A OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; 1N/A /* print main data */ 1N/A printf("%s(\"%S\", 0x%X)\t\t = %d %s%d\n", probefunc, 1N/A copyinstr(self->arg0), self->arg1, (int)arg0, 1N/A self->code, (int)errno); 1N/A OPT_stack ? ustack() : 1; 1N/A OPT_stack ? trace("\n") : 1; 1N/A/* print *at() syscalls, 3 args, arg1 as a string if possible */ 1N/Asyscall::faccessat:return, 1N/Asyscall::fchmodat:return, 1N/Asyscall::fchownat:return, 1N/Asyscall::fstatat:return, 1N/Asyscall::fstatat64:return, 1N/Asyscall::linkat:return, 1N/Asyscall::mkdirat:return, 1N/Asyscall::mknodat:return, 1N/Asyscall::openat:return, 1N/Asyscall::openat64:return, 1N/Asyscall::readlinkat:return, 1N/Asyscall::renameat:return, 1N/Asyscall::unlinkat:return, 1N/Asyscall::utimensat:return 1N/A/self->start && self->arg1 != 0/ 1N/A /* calculate elapsed time */ 1N/A this->elapsed = timestamp - self->start; 1N/A this->cpu = vtimestamp - self->vstart; 1N/A self->code = errno == 0 ? "" : "Err#"; 1N/A /* print optional fields */ 1N/A OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; 1N/A OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; 1N/A OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; 1N/A OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; 1N/A /* print main data */ 1N/A printf("%s(0x%X, \"%S\", 0x%X)\t\t = %d %s%d\n", probefunc, 1N/A (uint_t)self->arg0, copyinstr(self->arg1), self->arg2, (int)arg0, 1N/A self->code, (int)errno); 1N/A OPT_stack ? ustack() : 1; 1N/A OPT_stack ? trace("\n") : 1; 1N/A/* print 3 args, arg0 as a string */ 1N/Asyscall::mount:return, 1N/Asyscall::resolvepath:return, 1N/Asyscall::statfs:return, 1N/Asyscall::symlinkat:return, 1N/Asyscall::uucopystr:return 1N/A /* calculate elapsed time */ 1N/A this->elapsed = timestamp - self->start; 1N/A this->cpu = vtimestamp - self->vstart; 1N/A self->code = errno == 0 ? "" : "Err#"; 1N/A /* print optional fields */ 1N/A OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; 1N/A OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; 1N/A OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; 1N/A OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; 1N/A /* print main data */ 1N/A printf("%s(\"%S\", 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, 1N/A copyinstr(self->arg0), self->arg1, self->arg2, (int)arg0, 1N/A self->code, (int)errno); 1N/A OPT_stack ? ustack() : 1; 1N/A OPT_stack ? trace("\n") : 1; 1N/A/* print 3 args, arg1 as a string bounded by return value (size) */ 1N/Asyscall::read:return, 1N/Asyscall::pread:return, 1N/Asyscall::pread64:return, 1N/Asyscall::write:return, 1N/Asyscall::pwrite:return, 1N/Asyscall::pwrite64:return 1N/A/self->start && arg0 > 0/ 1N/A /* calculate elapsed time */ 1N/A this->elapsed = timestamp - self->start; 1N/A this->cpu = vtimestamp - self->vstart; 1N/A self->code = errno == 0 ? "" : "Err#"; 1N/A /* print optional fields */ 1N/A OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; 1N/A OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; 1N/A OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; 1N/A OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; 1N/A /* print main data */ 1N/A this->size = arg0 > 32? 32 : arg0; 1N/A printf("%s(0x%X, \"%S\", 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0, 1N/A stringof(copyin(self->arg1, this->size)), self->arg2, (int)arg0, 1N/A self->code, (int)errno); 1N/A OPT_stack ? ustack() : 1; 1N/A OPT_stack ? trace("\n") : 1; 1N/A/* print 0 arg output (there are lots more 0-arg syscalls) */ 1N/Asyscall::gtime:return 1N/A /* calculate elapsed time */ 1N/A this->elapsed = timestamp - self->start; 1N/A this->cpu = vtimestamp - self->vstart; 1N/A self->code = errno == 0 ? "" : "Err#"; 1N/A /* print optional fields */ 1N/A OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; 1N/A OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; 1N/A OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; 1N/A OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; 1N/A /* print main data */ 1N/A printf("%s()\t\t = %d %s%d\n", probefunc, 1N/A (int)arg0, self->code, (int)errno); 1N/A OPT_stack ? ustack() : 1; 1N/A OPT_stack ? trace("\n") : 1; 1N/A/* print 1 arg output (there are lots more 1-arg syscalls) */ 1N/Asyscall::close:return, 1N/Asyscall::stime:return, 1N/Asyscall::times:return 1N/A /* calculate elapsed time */ 1N/A this->elapsed = timestamp - self->start; 1N/A this->cpu = vtimestamp - self->vstart; 1N/A self->code = errno == 0 ? "" : "Err#"; 1N/A /* print optional fields */ 1N/A OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; 1N/A OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; 1N/A OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; 1N/A OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; 1N/A /* print main data */ 1N/A printf("%s(0x%X)\t\t = %d %s%d\n", probefunc, self->arg0, 1N/A (int)arg0, self->code, (int)errno); 1N/A OPT_stack ? ustack() : 1; 1N/A OPT_stack ? trace("\n") : 1; 1N/A/* print 2 arg output (there are lots more 2-arg syscalls) */ 1N/Asyscall::munmap:return 1N/A /* calculate elapsed time */ 1N/A this->elapsed = timestamp - self->start; 1N/A this->cpu = vtimestamp - self->vstart; 1N/A self->code = errno == 0 ? "" : "Err#"; 1N/A /* print optional fields */ 1N/A OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; 1N/A OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; 1N/A OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; 1N/A OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; 1N/A /* print main data */ 1N/A printf("%s(0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0, 1N/A self->arg1, (int)arg0, self->code, (int)errno); 1N/A OPT_stack ? ustack() : 1; 1N/A OPT_stack ? trace("\n") : 1; 1N/A/* print 3 arg output - default */ 1N/A /* calculate elapsed time */ 1N/A this->elapsed = timestamp - self->start; 1N/A this->cpu = vtimestamp - self->vstart; 1N/A self->code = errno == 0 ? "" : "Err#"; 1N/A /* print optional fields */ 1N/A OPT_printid ? printf("%6d/%d: ", pid, tid) : 1; 1N/A OPT_relative ? printf("%8d ", vtimestamp/1000) : 1; 1N/A OPT_elapsed ? printf("%7d ", this->elapsed/1000) : 1; 1N/A OPT_cpu ? printf("%6d ", this->cpu/1000) : 1; 1N/A /* print main data */ 1N/A printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0, 1N/A self->arg1, self->arg2, (int)arg0, self->code, (int)errno); 1N/A OPT_stack ? ustack() : 1; 1N/A OPT_stack ? trace("\n") : 1; 1N/A/(OPT_command || OPT_pid) && pid == $target/ 1N/A OPT_counts == 1 ? printf("\n%-32s %16s\n", "CALL", "COUNT") : 1; 1N/A OPT_counts == 1 ? printa("%-32s %@16d\n", @Counts) : 1; 1N/Aif [ $opt_command -eq 1 ]; then 1N/A /usr/sbin/dtrace -x dynvarsize=$buf -x evaltime=exec -n "$dtrace" \ 1N/Aelif [ $opt_pid -eq 1 ]; then 1N/A /usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" -p "$pid" >&2 1N/A /usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" >&2