cddl/contrib/dtracetoolkit/Proc/pfilestat

   1 #!/usr/bin/sh
   2 #
   3 # pfilestat
   4 #
   5 # This prints I/O statistics for each file descriptor within a process.
   6 # In particular, the time break down during read() and write() events is
   7 # measured.
   8 #
   9 # $Id: pfilestat 4 2007-08-01 11:01:38Z brendan $
  10 #
  11 # USAGE:        pfilestat [-r|-w] pid
  12 #
  13 # FIELDS:
  14 #               STATE      microstate: running, sleeping, waitcpu, read, write
  15 #               FDUM       File Descriptor ID
  16 #               Time       Percentage of wallclock time in each STATE
  17 #               File       Name of file, if known
  18 #
  19 # COPYRIGHT: Copyright (c) 2006 Richard McDougall.
  20 #
  21 # CDDL HEADER START
  22 #
  23 #  The contents of this file are subject to the terms of the
  24 #  Common Development and Distribution License, Version 1.0 only
  25 #  (the "License").  You may not use this file except in compliance
  26 #  with the License.
  27 #
  28 #  You can obtain a copy of the license at Docs/cddl1.txt
  29 #  or http://www.opensolaris.org/os/licensing.
  30 #  See the License for the specific language governing permissions
  31 #  and limitations under the License.
  32 #
  33 # CDDL HEADER END
  34 #
  35 # ToDo:
  36 #       Trace readv() and writev().
  37 #
  38 # 20-Feb-2006   Richard McDougall       created this.
  39 # 24-Feb-2006   Brendan Gregg           tweaked code.
  40 # 20-Mar-2006      "      "             tweaked code.
  41 # 20-Mar-2006      "      "             last update.
  42
  43
  44 ##############################
  45 # --- Process Arguments ---
  46 #
  47
  48 ### Default variables
  49 opt_read=0; opt_write=0
  50
  51 ### Process options
  52 while getopts hrw name
  53 do
  54         case $name in
  55         r)      opt_read=1 ;;
  56         w)      opt_write=1 ;;
  57         h|?)    cat <<-END >&2
  58                 USAGE: pfilestat [-r|-w] pid
  59                               -r           # reads only
  60                               -w           # writes only
  61                   eg,
  62                        pfilestat pid       # default, r+w counts
  63                        pfilestat -r pid    # read count only
  64                 END
  65                 exit 1
  66         esac
  67 done
  68 shift `expr $OPTIND - 1`
  69
  70 PID=$1
  71 clearstr=`clear`
  72
  73 if [ -z "$PID" ]
  74 then
  75         echo "Must supply pid"
  76         exit 1
  77 fi
  78
  79 ### Option logic
  80 if [ $opt_read -eq 0 -a $opt_write -eq 0 ]; then
  81         opt_read=1; opt_write=1
  82 fi
  83
  84
  85 #################################
  86 # --- Main Program, DTrace ---
  87 #
  88 /usr/sbin/dtrace -n '
  89  #pragma D option quiet
  90
  91  inline string CLEAR   = "'$clearstr'";
  92  inline int OPT_read   = '$opt_read';
  93  inline int OPT_write  = '$opt_write';
  94  inline int PID        = '$PID';
  95
  96  unsigned long long totaltime;
  97  unsigned long long totalbytes;
  98
  99  enum runstate {
 100         READ,
 101         WRITE,
 102         OTHER
 103  };
 104
 105  /* print header */
 106  dtrace:::BEGIN
 107  {
 108         printf("Tracing ");
 109         OPT_read && OPT_write ? printf("reads and writes") : 1;
 110         OPT_read && ! OPT_write ? printf("reads") : 1;
 111         ! OPT_read && OPT_write ? printf("writes") : 1;
 112         printf("...");
 113         totaltime = 0;
 114         totalbytes = 0;
 115         last = timestamp;
 116         stamp = timestamp;
 117  }
 118
 119  /* sample reads */
 120  syscall::read:entry,
 121  syscall::pread*:entry
 122  /pid == PID && OPT_read/
 123  {
 124         runstate = READ;
 125         @logical["running", (uint64_t)0, ""] = sum(timestamp - last);
 126         totaltime += timestamp - last;
 127         last = timestamp;
 128
 129         self->fd = arg0 + 1;
 130  }
 131
 132  fbt::fop_read:entry,
 133  fbt::fop_write:entry
 134  /self->fd/
 135  {
 136         self->path = args[0]->v_path == 0 ? "<none>" :
 137             cleanpath(args[0]->v_path);
 138  }
 139
 140  syscall::read:return,
 141  syscall::pread*:return
 142  /pid == PID && OPT_read/
 143  {
 144         runstate = OTHER;
 145         this->bytes = (int)arg0 > 0 ? (int)arg0 : 0;
 146         @logical["read", self->fd - 1, self->path] = sum(timestamp - last);
 147         @bytes["read", self->fd - 1, self->path] = sum(this->bytes);
 148         totalbytes += this->bytes;
 149         totaltime += timestamp - last;
 150         last = timestamp;
 151         self->path = 0;
 152         self->fd = 0;
 153  }
 154
 155
 156  /* sample writes */
 157  syscall::write:entry,
 158  syscall::pwrite*:entry
 159  /pid == PID && OPT_write/
 160  {
 161         runstate = WRITE;
 162         @logical["running", (uint64_t)0, ""] = sum(timestamp - last);
 163         totaltime += timestamp - last;
 164         last = timestamp;
 165
 166         self->fd = (int)arg0 + 1;
 167  }
 168
 169  syscall::write:return,
 170  syscall::pwrite*:return
 171  /pid == PID && OPT_write/
 172  {
 173         runstate = OTHER;
 174         this->bytes = (int)arg0 > 0 ? (int)arg0 : 0;
 175         @logical["write", self->fd - 1, self->path] = sum(timestamp - last);
 176         @bytes["write", self->fd - 1, self->path] = sum(this->bytes);
 177         totalbytes += this->bytes;
 178         totaltime += timestamp - last;
 179         last = timestamp;
 180         self->path = 0;
 181         self->fd = 0;
 182  }
 183
 184  sched:::on-cpu
 185  /pid == PID/
 186  {
 187         @logical["waitcpu", (uint64_t)0, ""] = sum(timestamp - last);
 188         totaltime += timestamp - last;
 189         last = timestamp;
 190  }
 191
 192
 193  sched:::off-cpu
 194  /pid == PID/
 195  {
 196         @logical["running", (uint64_t)0, ""] = sum(timestamp - last);
 197         totaltime += timestamp - last;
 198         last = timestamp;
 199  }
 200
 201  sched:::sleep
 202  /pid == PID/
 203  {
 204         @logical["running", (uint64_t)0, ""] = sum(timestamp - last);
 205         totaltime += timestamp - last;
 206         last = timestamp;
 207  }
 208
 209  sched:::wakeup
 210  /args[1]->pr_pid == PID && runstate == OTHER/
 211  {
 212         @logical["sleep", (uint64_t)0, ""] = sum(timestamp - last);
 213         totaltime += timestamp - last;
 214         last = timestamp;
 215  }
 216
 217  sched:::wakeup
 218  /args[1]->pr_pid == PID && runstate == READ/
 219  {
 220         @logical["sleep-r", (uint64_t)0, ""] = sum(timestamp - last);
 221         totaltime += timestamp - last;
 222         last = timestamp;
 223  }
 224
 225  sched:::wakeup
 226  /args[1]->pr_pid == PID && runstate == WRITE/
 227  {
 228         @logical["sleep-w", (uint64_t)0, ""] = sum(timestamp - last);
 229         totaltime += timestamp - last;
 230         last = timestamp;
 231  }
 232
 233  sched:::enqueue
 234  /args[1]->pr_pid == PID/
 235  {
 236         @logical["waitcpu", (uint64_t)0, ""] = sum(timestamp - last);
 237         totaltime += timestamp - last;
 238         last = timestamp;
 239  }
 240
 241  sched:::dequeue
 242  /args[1]->pr_pid == PID/
 243  {
 244         @logical["waitcpu", (uint64_t)0, ""] = sum(timestamp - last);
 245         totaltime += timestamp - last;
 246         last = timestamp;
 247  }
 248
 249  /* print report */
 250  profile:::tick-5s
 251  {
 252         printf("%s", CLEAR);
 253         normalize(@logical, totaltime / 100);
 254         trunc(@logical, 10);
 255         printf("%10s %7s %9s %-44s\n", "STATE", "FDNUM", "Time", "Filename");
 256         printa("%10s %7d %@8d%% %-44.44s\n", @logical);
 257         trunc(@logical);
 258
 259         delta = timestamp - stamp;
 260         stamp = timestamp;
 261         normalize(@bytes, (1024 * delta) / 1000000000);
 262         trunc(@bytes, 10);
 263         printf("\n%10s %7s %9s %-44s\n", "STATE", "FDNUM", "KB/s",
 264             "Filename");
 265         printa("%10s %7d %@9d %-44.44s\n", @bytes);
 266         trunc(@bytes);
 267
 268         printf("\nTotal event time (ms): %d   Total Mbytes/sec: %d\n",
 269             totaltime / 1000000,
 270             (totalbytes * 1000000000) / (delta * 1048576));
 271
 272         totaltime = 0;
 273         totalbytes = 0;
 274         last = timestamp;
 275  }
 276
 277  dtrace:::END
 278  {
 279         trunc(@logical);
 280         trunc(@bytes);
 281  }
 282 '