cddl/contrib/dtracetoolkit/Examples/dtruss_example.txt

   1 The following demonstrates the dtruss command - a DTrace version of truss.
   2 This version is designed to be less intrusive and safer than running truss.
   3
   4 dtruss has many options. Here is the help for version 0.70,
   5
   6    USAGE: dtruss [-acdefholL] [-t syscall] { -p PID | -n name | command }
   7
   8              -p PID          # examine this PID
   9              -n name         # examine this process name
  10              -t syscall      # examine this syscall only
  11              -a              # print all details
  12              -c              # print syscall counts
  13              -d              # print relative times (us)
  14              -e              # print elapsed times (us)
  15              -f              # follow children
  16              -l              # force printing pid/lwpid
  17              -o              # print on cpu times
  18              -L              # don't print pid/lwpid
  19              -b bufsize      # dynamic variable buf size
  20       eg,
  21           dtruss df -h       # run and examine "df -h"
  22           dtruss -p 1871     # examine PID 1871
  23           dtruss -n tar      # examine all processes called "tar"
  24           dtruss -f test.sh  # run test.sh and follow children
  25
  26
  27
  28 For example, here we dtruss any process with the name "ksh" - the Korn shell,
  29
  30  # dtruss -n ksh
  31  PID/LWP   SYSCALL(args)                  = return
  32  27547/1:  llseek(0x3F, 0xE4E, 0x0)               = 3662 0
  33  27547/1:  read(0x3F, "\0", 0x400)                = 0 0
  34  27547/1:  llseek(0x3F, 0x0, 0x0)                 = 3662 0
  35  27547/1:  write(0x3F, "ls -l\n\0", 0x8)          = 8 0
  36  27547/1:  fdsync(0x3F, 0x10, 0xFEC1D444)                 = 0 0
  37  27547/1:  lwp_sigmask(0x3, 0x20000, 0x0)                 = 0xFFBFFEFF 0
  38  27547/1:  stat64("/usr/bin/ls\0", 0x8047A00, 0xFEC1D444)                 = 0 0
  39  27547/1:  lwp_sigmask(0x3, 0x0, 0x0)             = 0xFFBFFEFF 0
  40  [...]
  41
  42 The output for each system call does not yet evaluate as much as truss does.
  43
  44
  45
  46 In the following example, syscall elapsed and overhead times are measured.
  47 Elapsed times represent the time from syscall start to finish; overhead
  48 times measure the time spent on the CPU,
  49
  50  # dtruss -eon bash
  51  PID/LWP    ELAPSD    CPU SYSCALL(args)           = return
  52   3911/1:       41     26 write(0x2, "l\0", 0x1)          = 1 0
  53   3911/1:  1001579     43 read(0x0, "s\0", 0x1)           = 1 0
  54   3911/1:       38     26 write(0x2, "s\0", 0x1)          = 1 0
  55   3911/1:  1019129     43 read(0x0, " \001\0", 0x1)               = 1 0
  56   3911/1:       38     26 write(0x2, " \0", 0x1)          = 1 0
  57   3911/1:   998533     43 read(0x0, "-\0", 0x1)           = 1 0
  58   3911/1:       38     26 write(0x2, "-\001\0", 0x1)              = 1 0
  59   3911/1:  1094323     42 read(0x0, "l\0", 0x1)           = 1 0
  60   3911/1:       39     27 write(0x2, "l\001\0", 0x1)              = 1 0
  61   3911/1:  1210496     44 read(0x0, "\r\0", 0x1)          = 1 0
  62   3911/1:       40     28 write(0x2, "\n\001\0", 0x1)             = 1 0
  63   3911/1:        9      1 lwp_sigmask(0x3, 0x2, 0x0)              = 0xFFBFFEFF 0
  64   3911/1:       70     63 ioctl(0x0, 0x540F, 0x80F6D00)           = 0 0
  65
  66 A bash command was in another window, where the "ls -l" command was being
  67 typed. The keystrokes can be seen above, along with the long elapsed times
  68 (keystroke delays), and short overhead times (as the bash process blocks
  69 on the read and leaves the CPU).
  70
  71
  72
  73 Now dtruss is put to the test. Here we truss a test program that runs several
  74 hundred smaller programs, which in turn generate thousands of system calls.
  75
  76 First, as a "control" we run the program without a truss or dtruss running,
  77
  78  # time ./test
  79  real    0m38.508s
  80  user    0m5.299s
  81  sys     0m25.668s
  82
  83 Now we try truss,
  84
  85  # time truss ./test 2> /dev/null
  86  real    0m41.281s
  87  user    0m0.558s
  88  sys     0m1.351s
  89
  90 Now we try dtruss,
  91
  92  # time dtruss ./test 2> /dev/null
  93  real    0m46.226s
  94  user    0m6.771s
  95  sys     0m31.703s
  96
  97 In the above test, truss slowed the program from 38 seconds to 41. dtruss
  98 slowed the program from 38 seconds to 46, slightly slower that truss...
  99
 100 Now we try follow mode "-f". The test program does run several hundred
 101 smaller programs, so now there are plenty more system calls to track,
 102
 103  # time truss -f ./test 2> /dev/null
 104  real    2m28.317s
 105  user    0m0.893s
 106  sys     0m3.527s
 107
 108 Now we try dtruss,
 109
 110  # time dtruss -f ./test 2> /dev/null
 111  real    0m56.179s
 112  user    0m10.040s
 113  sys     0m38.185s
 114
 115 Wow, the difference is huge! truss slows the program from 38 to 148 seconds;
 116 but dtruss has only slowed the program from 38 to 56 seconds.
 117
 118
 119
 120