cddl/contrib/dtracetoolkit/dtruss

   1 #!/bin/sh
   2 #
   3 # dtruss - print process system call time details.
   4 #          Written using DTrace (Solaris 10 3/05).
   5 #
   6 # $Id: dtruss 9 2007-08-07 10:21:07Z brendan $
   7 #
   8 # USAGE: dtruss [-acdeflhoLs] [-t syscall] { -p PID | -n name | command }
   9 #
  10 #               -p PID          # examine this PID
  11 #               -n name         # examine this process name
  12 #               -t syscall      # examine this syscall only
  13 #               -a              # print all details
  14 #               -c              # print system call counts
  15 #               -d              # print relative timestamps (us)
  16 #               -e              # print elapsed times (us)
  17 #               -f              # follow children as they are forked
  18 #               -l              # force printing of pid/lwpid per line
  19 #               -o              # print on cpu times (us)
  20 #               -s              # print stack backtraces
  21 #               -L              # don't print pid/lwpid per line
  22 #               -b bufsize      # dynamic variable buf size (default is "4m")
  23 #  eg,
  24 #               dtruss df -h    # run and examine the "df -h" command
  25 #               dtruss -p 1871  # examine PID 1871
  26 #               dtruss -n tar   # examine all processes called "tar"
  27 #               dtruss -f test.sh       # run test.sh and follow children
  28 #
  29 # See the man page dtruss(1M) for further details.
  30 #
  31 # SEE ALSO: procsystime    # DTraceToolkit
  32 #           dapptrace      # DTraceToolkit
  33 #           truss
  34 #
  35 # COPYRIGHT: Copyright (c) 2005, 2006, 2007 Brendan Gregg.
  36 #
  37 # CDDL HEADER START
  38 #
  39 #  The contents of this file are subject to the terms of the
  40 #  Common Development and Distribution License, Version 1.0 only
  41 #  (the "License").  You may not use this file except in compliance
  42 #  with the License.
  43 #
  44 #  You can obtain a copy of the license at Docs/cddl1.txt
  45 #  or http://www.opensolaris.org/os/licensing.
  46 #  See the License for the specific language governing permissions
  47 #  and limitations under the License.
  48 #
  49 # CDDL HEADER END
  50 #
  51 # TODO: Track signals, more output formatting.
  52 #
  53 # 29-Apr-2005   Brendan Gregg   Created this.
  54 # 09-May-2005      "      "     Fixed evaltime (thanks Adam L.)
  55 # 16-May-2005      "      "     Added -t syscall tracing.
  56 # 17-Jun-2005      "      "     Added -s stack backtraces.
  57 # 17-Jun-2005      "      "     Last update.
  58 # 29-Jun-2007      "      "     Used progenyof() (thanks Aaron Gutman).
  59 # 06-Aug-2007      "      "     Various updates.
  60 #
  61
  62
  63 ##############################
  64 # --- Process Arguments ---
  65 #
  66
  67 ### Default variables
  68 opt_pid=0; opt_name=0; pid=0; pname="."; opt_elapsed=0; opt_cpu=0
  69 opt_counts=0; opt_relative=0; opt_printid=0; opt_follow=0; opt_command=0
  70 command=""; opt_buf=0; buf="4m"; opt_trace=0; trace="."; opt_stack=0
  71
  72 ### Process options
  73 while getopts ab:cdefhln:op:st:L name
  74 do
  75         case $name in
  76         b)      opt_buf=1; buf=$OPTARG ;;
  77         p)      opt_pid=1; pid=$OPTARG ;;
  78         n)      opt_name=1; pname=$OPTARG ;;
  79         t)      opt_trace=1; trace=$OPTARG ;;
  80         a)      opt_counts=1; opt_relative=1; opt_elapsed=1; opt_follow=1
  81                 opt_printid=1; opt_cpu=1 ;;
  82         c)      opt_counts=1 ;;
  83         d)      opt_relative=1 ;;
  84         e)      opt_elapsed=1 ;;
  85         f)      opt_follow=1 ;;
  86         l)      opt_printid=1 ;;
  87         o)      opt_cpu=1 ;;
  88         L)      opt_printid=-1 ;;
  89         s)      opt_stack=-1 ;;
  90         h|?)    cat <<-END >&2
  91                 USAGE: dtruss [-acdefholLs] [-t syscall] { -p PID | -n name | command }
  92
  93                           -p PID          # examine this PID
  94                           -n name         # examine this process name
  95                           -t syscall      # examine this syscall only
  96                           -a              # print all details
  97                           -c              # print syscall counts
  98                           -d              # print relative times (us)
  99                           -e              # print elapsed times (us)
 100                           -f              # follow children (-p or cmd only)
 101                           -l              # force printing pid/lwpid
 102                           -o              # print on cpu times
 103                           -s              # print stack backtraces
 104                           -L              # don't print pid/lwpid
 105                           -b bufsize      # dynamic variable buf size
 106                    eg,
 107                        dtruss df -h       # run and examine "df -h"
 108                        dtruss -p 1871     # examine PID 1871
 109                        dtruss -n tar      # examine all processes called "tar"
 110                        dtruss -f test.sh  # run test.sh and follow children
 111                 END
 112                 exit 1
 113         esac
 114 done
 115 shift `expr $OPTIND - 1`
 116
 117 ### Option logic
 118 if [ $opt_pid -eq 0 -a $opt_name -eq 0 ]; then
 119         opt_command=1
 120         if [ "$*" = "" ]; then
 121                 $0 -h
 122                 exit
 123         fi
 124         command="$*"    # yes, I meant $*!
 125 fi
 126 if [ $opt_follow -eq 1 -o $opt_name -eq 1 ]; then
 127         if [ $opt_printid -ne -1 ]; then
 128                 opt_printid=1
 129         else
 130                 opt_printid=0
 131         fi
 132 fi
 133 if [ $opt_follow -eq 1 -a $opt_name -eq 1 ]; then
 134         echo "ERROR: -f option cannot be used with -n (use -p or cmd instead)."
 135         exit 1
 136 fi
 137
 138 ### Option translation
 139 if [ "$trace" = "exec" ]; then trace="exece"; fi
 140 if [ "$trace" = "time" ]; then trace="gtime"; fi
 141 if [ "$trace" = "exit" ]; then trace="rexit"; fi
 142
 143
 144 #################################
 145 # --- Main Program, DTrace ---
 146 #
 147
 148 ### Define D Script
 149 dtrace='
 150 #pragma D option quiet
 151 #pragma D option switchrate=10
 152
 153 /*
 154  * Command line arguments
 155  */
 156 inline int OPT_command   = '$opt_command';
 157 inline int OPT_follow    = '$opt_follow';
 158 inline int OPT_printid   = '$opt_printid';
 159 inline int OPT_relative  = '$opt_relative';
 160 inline int OPT_elapsed   = '$opt_elapsed';
 161 inline int OPT_cpu       = '$opt_cpu';
 162 inline int OPT_counts    = '$opt_counts';
 163 inline int OPT_pid       = '$opt_pid';
 164 inline int OPT_name      = '$opt_name';
 165 inline int OPT_trace     = '$opt_trace';
 166 inline int OPT_stack     = '$opt_stack';
 167 inline string NAME       = "'$pname'";
 168 inline string TRACE      = "'$trace'";
 169
 170 dtrace:::BEGIN
 171 {
 172         /* print header */
 173         OPT_printid  ? printf("%-9s  ", "PID/LWP") : 1;
 174         OPT_relative ? printf("%8s ", "RELATIVE") : 1;
 175         OPT_elapsed  ? printf("%7s ", "ELAPSD") : 1;
 176         OPT_cpu      ? printf("%6s ", "CPU") : 1;
 177         printf("SYSCALL(args) \t\t = return\n");
 178 }
 179
 180 /*
 181  * Save syscall entry info
 182  */
 183 syscall:::entry
 184 /((OPT_command || OPT_pid) && pid == $target) ||
 185  (OPT_name && execname == NAME) ||
 186  (OPT_follow && progenyof($target))/
 187 {
 188         /* set start details */
 189         self->start = timestamp;
 190         self->vstart = vtimestamp;
 191         self->arg0 = arg0;
 192         self->arg1 = arg1;
 193         self->arg2 = arg2;
 194
 195         /* count occurances */
 196         OPT_counts == 1 ? @Counts[probefunc] = count() : 1;
 197 }
 198
 199 /*
 200  * Follow children
 201  */
 202 syscall::fork*:return
 203 /(OPT_follow && progenyof($target)) && (!OPT_trace || (TRACE == probefunc))/
 204 {
 205         /* print output */
 206         self->code = errno == 0 ? "" : "Err#";
 207         OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
 208         OPT_relative ? printf("%8d:  ", vtimestamp/1000) : 1;
 209         OPT_elapsed  ? printf("%7d:  ", 0) : 1;
 210         OPT_cpu      ? printf("%6d ", 0) : 1;
 211         printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc,
 212             self->arg0, self->arg1, self->arg2, (int)arg0, self->code,
 213             (int)errno);
 214 }
 215
 216 /*
 217  * Check for syscall tracing
 218  */
 219 syscall:::entry
 220 /OPT_trace && probefunc != TRACE/
 221 {
 222         /* drop info */
 223         self->start = 0;
 224         self->vstart = 0;
 225         self->arg0 = 0;
 226         self->arg1 = 0;
 227         self->arg2 = 0;
 228 }
 229
 230 /*
 231  * Print return data
 232  */
 233
 234 /*
 235  * The following code is written in an intentionally repetative way.
 236  * The first versions had no code redundancies, but performed badly during
 237  * benchmarking. The priority here is speed, not cleverness. I know there
 238  * are many obvious shortcuts to this code, I have tried them. This style has
 239  * shown in benchmarks to be the fastest (fewest probes fired, fewest actions).
 240  */
 241
 242 /* print 3 args, return as hex */
 243 syscall::sigprocmask:return
 244 /self->start/
 245 {
 246         /* calculate elapsed time */
 247         this->elapsed = timestamp - self->start;
 248         self->start = 0;
 249         this->cpu = vtimestamp - self->vstart;
 250         self->vstart = 0;
 251         self->code = errno == 0 ? "" : "Err#";
 252
 253         /* print optional fields */
 254         OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
 255         OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
 256         OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
 257         OPT_cpu ? printf("%6d ", this->cpu/1000) : 1;
 258
 259         /* print main data */
 260         printf("%s(0x%X, 0x%X, 0x%X)\t\t = 0x%X %s%d\n", probefunc,
 261             (int)self->arg0, self->arg1, self->arg2, (int)arg0,
 262             self->code, (int)errno);
 263         OPT_stack ? ustack()    : 1;
 264         OPT_stack ? trace("\n") : 1;
 265         self->arg0 = 0;
 266         self->arg1 = 0;
 267         self->arg2 = 0;
 268 }
 269
 270 /* print 3 args, arg0 as a string */
 271 syscall::access*:return,
 272 syscall::stat*:return,
 273 syscall::lstat*:return,
 274 syscall::readlink*:return,
 275 syscall::open*:return
 276 /self->start/
 277 {
 278         /* calculate elapsed time */
 279         this->elapsed = timestamp - self->start;
 280         self->start = 0;
 281         this->cpu = vtimestamp - self->vstart;
 282         self->vstart = 0;
 283         self->code = errno == 0 ? "" : "Err#";
 284
 285         /* print optional fields */
 286         OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
 287         OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
 288         OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
 289         OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 290
 291         /* print main data */
 292         printf("%s(\"%S\", 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc,
 293             copyinstr(self->arg0), self->arg1, self->arg2, (int)arg0,
 294             self->code, (int)errno);
 295         OPT_stack ? ustack()    : 1;
 296         OPT_stack ? trace("\n") : 1;
 297         self->arg0 = 0;
 298         self->arg1 = 0;
 299         self->arg2 = 0;
 300 }
 301
 302 /* print 3 args, arg1 as a string */
 303 syscall::write:return,
 304 syscall::pwrite:return,
 305 syscall::*read*:return
 306 /self->start/
 307 {
 308         /* calculate elapsed time */
 309         this->elapsed = timestamp - self->start;
 310         self->start = 0;
 311         this->cpu = vtimestamp - self->vstart;
 312         self->vstart = 0;
 313         self->code = errno == 0 ? "" : "Err#";
 314
 315         /* print optional fields */
 316         OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
 317         OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
 318         OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
 319         OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 320
 321         /* print main data */
 322         printf("%s(0x%X, \"%S\", 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
 323             stringof(copyin(self->arg1, self->arg2)), self->arg2, (int)arg0,
 324             self->code, (int)errno);
 325         OPT_stack ? ustack()    : 1;
 326         OPT_stack ? trace("\n") : 1;
 327         self->arg0 = 0;
 328         self->arg1 = 0;
 329         self->arg2 = 0;
 330 }
 331
 332 /* print 0 arg output */
 333 syscall::*fork*:return
 334 /self->start/
 335 {
 336         /* calculate elapsed time */
 337         this->elapsed = timestamp - self->start;
 338         self->start = 0;
 339         this->cpu = vtimestamp - self->vstart;
 340         self->vstart = 0;
 341         self->code = errno == 0 ? "" : "Err#";
 342
 343         /* print optional fields */
 344         OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
 345         OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
 346         OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
 347         OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 348
 349         /* print main data */
 350         printf("%s()\t\t = %d %s%d\n", probefunc,
 351             (int)arg0, self->code, (int)errno);
 352         OPT_stack ? ustack()    : 1;
 353         OPT_stack ? trace("\n") : 1;
 354         self->arg0 = 0;
 355         self->arg1 = 0;
 356         self->arg2 = 0;
 357 }
 358
 359 /* print 1 arg output */
 360 syscall::close:return
 361 /self->start/
 362 {
 363         /* calculate elapsed time */
 364         this->elapsed = timestamp - self->start;
 365         self->start = 0;
 366         this->cpu = vtimestamp - self->vstart;
 367         self->vstart = 0;
 368         self->code = errno == 0 ? "" : "Err#";
 369
 370         /* print optional fields */
 371         OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
 372         OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
 373         OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
 374         OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 375
 376         /* print main data */
 377         printf("%s(0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
 378             (int)arg0, self->code, (int)errno);
 379         OPT_stack ? ustack()    : 1;
 380         OPT_stack ? trace("\n") : 1;
 381         self->arg0 = 0;
 382         self->arg1 = 0;
 383         self->arg2 = 0;
 384 }
 385
 386 /* print 2 arg output */
 387 syscall::utimes:return,
 388 syscall::munmap:return
 389 /self->start/
 390 {
 391         /* calculate elapsed time */
 392         this->elapsed = timestamp - self->start;
 393         self->start = 0;
 394         this->cpu = vtimestamp - self->vstart;
 395         self->vstart = 0;
 396         self->code = errno == 0 ? "" : "Err#";
 397
 398         /* print optional fields */
 399         OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
 400         OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
 401         OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
 402         OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 403
 404         /* print main data */
 405         printf("%s(0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
 406             self->arg1, (int)arg0, self->code, (int)errno);
 407         OPT_stack ? ustack()    : 1;
 408         OPT_stack ? trace("\n") : 1;
 409         self->arg0 = 0;
 410         self->arg1 = 0;
 411         self->arg2 = 0;
 412 }
 413
 414 /* print 3 arg output - default */
 415 syscall:::return
 416 /self->start/
 417 {
 418         /* calculate elapsed time */
 419         this->elapsed = timestamp - self->start;
 420         self->start = 0;
 421         this->cpu = vtimestamp - self->vstart;
 422         self->vstart = 0;
 423         self->code = errno == 0 ? "" : "Err#";
 424
 425         /* print optional fields */
 426         OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
 427         OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
 428         OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
 429         OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 430
 431         /* print main data */
 432         printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
 433             self->arg1, self->arg2, (int)arg0, self->code, (int)errno);
 434         OPT_stack ? ustack()    : 1;
 435         OPT_stack ? trace("\n") : 1;
 436         self->arg0 = 0;
 437         self->arg1 = 0;
 438         self->arg2 = 0;
 439 }
 440
 441 /* program exited */
 442 proc:::exit
 443 /(OPT_command || OPT_pid) && pid == $target/
 444 {
 445         exit(0);
 446 }
 447
 448 /* print counts */
 449 dtrace:::END
 450 {
 451         OPT_counts == 1 ? printf("\n%-32s %16s\n", "CALL", "COUNT") : 1;
 452         OPT_counts == 1 ? printa("%-32s %@16d\n", @Counts) : 1;
 453 }
 454 '
 455
 456 ### Run DTrace
 457 if [ $opt_command -eq 1 ]; then
 458         /usr/sbin/dtrace -x dynvarsize=$buf -x evaltime=exec -n "$dtrace" \
 459             -c "$command" >&2
 460 elif [ $opt_pid -eq 1 ]; then
 461         /usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" -p "$pid" >&2
 462 else
 463         /usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" >&2
 464 fi