Home | History | Annotate | Line # | Download | only in dist
      1 #!/bin/sh
      2 #
      3 # iosnoop - A program to print disk I/O events as they happen, with useful
      4 #           details such as UID, PID, filename (if available), command, etc.
      5 #           Written using DTrace (Solaris 10 3/05, MacOS X 10.5).
      6 #
      7 # This is measuring events that have made it past system caches, such as
      8 # disk events for local file systems, and network events for remote
      9 # filesystems (such as NFS.)
     10 #
     11 # $Id: iosnoop,v 1.2 2018/10/01 13:28:07 sevan Exp $
     12 #
     13 # USAGE: 	iosnoop [-a|-A|-DeghiNostv] [-d device] [-f filename] 
     14 #			[-m mount_point] [-n name] [-p PID]
     15 #
     16 #		iosnoop		# default output
     17 #
     18 #		-a		# print all data (mostly)
     19 #		-A		# dump all data, space delimited
     20 #		-D		# print time delta, us (elapsed)
     21 #		-e		# print device name
     22 #		-g		# print command arguments
     23 #		-i		# print device instance
     24 #		-N		# print major and minor numbers
     25 #		-o		# print disk delta time, us 
     26 #		-s		# print start time, us
     27 #		-t 		# print completion time, us
     28 #		-v		# print completion time, string
     29 #		-d device	# instance name to snoop (eg, dad0)
     30 #		-f filename	# full pathname of file to snoop
     31 #		-m mount_point	# this FS only (will skip raw events)
     32 #		-n name		# this process name only
     33 #		-p PID		# this PID only
     34 #  eg,
     35 #		iosnoop -v	# human readable timestamps
     36 #		iosnoop -N	# print major and minor numbers
     37 #		iosnoop -m /	# snoop events on the root filesystem only
     38 # 	
     39 # FIELDS:
     40 #		UID		user ID
     41 #		PID		process ID
     42 #		PPID		parennt process ID
     43 #		COMM		command name for the process
     44 #		ARGS		argument listing for the process
     45 #		SIZE		size of operation, bytes
     46 #		BLOCK		disk block for the operation (location)
     47 #		STIME	 	timestamp for the disk request, us
     48 #		TIME		timestamp for the disk completion, us
     49 #		DELTA		elapsed time from request to completion, us
     50 #		DTIME		time for disk to complete request, us
     51 #		STRTIME		timestamp for the disk completion, string
     52 #		DEVICE  	device name
     53 #		INS     	device instance number
     54 #		D		direction, Read or Write
     55 #		MOUNT		mount point
     56 #		FILE		filename (basename) for io operation
     57 # 
     58 # NOTE:
     59 # - There are two different delta times reported. -D prints the
     60 #   elapsed time from the disk request (strategy) to the disk completion
     61 #   (iodone); -o prints the time for the disk to complete that event 
     62 #   since it's last event (time between iodones), or, the time to the 
     63 #   strategy if the disk had been idle. 
     64 # - When filtering on PID or process name, be aware that poor disk event
     65 #   times may be due to events that have been filtered away, for example
     66 #   another process that may be seeking the disk heads elsewhere.
     67 #
     68 # SEE ALSO: BigAdmin: DTrace, http://www.sun.com/bigadmin/content/dtrace
     69 #	    Solaris Dynamic Tracing Guide, http://docs.sun.com
     70 #	    DTrace Tools, http://www.brendangregg.com/dtrace.html
     71 #
     72 # COPYRIGHT: Copyright (c) 2009 Brendan Gregg.
     73 #
     74 # CDDL HEADER START
     75 #
     76 #  The contents of this file are subject to the terms of the
     77 #  Common Development and Distribution License, Version 1.0 only
     78 #  (the "License").  You may not use this file except in compliance
     79 #  with the License.
     80 #
     81 #  You can obtain a copy of the license at Docs/cddl1.txt
     82 #  or http://www.opensolaris.org/os/licensing.
     83 #  See the License for the specific language governing permissions
     84 #  and limitations under the License.
     85 #
     86 # CDDL HEADER END
     87 #
     88 # 12-Mar-2004	Brendan Gregg	Created this, build 51.
     89 # 23-May-2004	   "	  "	Fixed mntpt bug.
     90 # 10-Oct-2004	   "      "	Rewritten to use the io provider, build 63.
     91 # 04-Jan-2005	   "	  "	Wrapped in sh to provide options.
     92 # 08-May-2005	   "      "	Rewritten for perfromance.
     93 # 15-Jul-2005	   "      "	Improved DTIME calculation.
     94 # 25-Jul-2005	   "      "	Added -p, -n. Improved code.
     95 # 17-Sep-2005	   "      "	Increased switchrate.
     96 # 15-Sep-2009	   "      "	Removed genunix for both MacOS X and NFS.
     97 #
     98 
     99 
    100 ##############################
    101 # --- Process Arguments ---
    102 #
    103 
    104 ### default variables
    105 opt_dump=0; opt_device=0; opt_delta=0; opt_devname=0; opt_file=0; opt_args=0; 
    106 opt_mount=0; opt_start=0 opt_end=0; opt_endstr=0; opt_ins=0; opt_nums=0
    107 opt_dtime=0; filter=0; device=.; filename=.; mount=.; pname=.; pid=0
    108 opt_name=0; opt_pid=0
    109 
    110 ### process options
    111 while getopts aAd:Def:ghim:Nn:op:stv name
    112 do
    113 	case $name in
    114 	a)	opt_devname=1; opt_args=1; opt_endstr=1; opt_nums=1 ;;
    115 	A)	opt_dump=1 ;;
    116 	d)	opt_device=1; device=$OPTARG ;;
    117 	D)	opt_delta=1 ;;
    118 	e)	opt_devname=1 ;;
    119 	f)	opt_file=1; filename=$OPTARG ;;
    120 	g)	opt_args=1 ;;
    121 	i)	opt_ins=1 ;;
    122 	N)	opt_nums=1 ;;
    123 	n)	opt_name=1; pname=$OPTARG ;;
    124 	o)	opt_dtime=1 ;;
    125 	p)	opt_pid=1; pid=$OPTARG ;;
    126 	m)	opt_mount=1; mount=$OPTARG ;;
    127 	s)	opt_start=1 ;;
    128 	t)	opt_end=1 ;;
    129 	v)	opt_endstr=1 ;;
    130 	h|?)	cat <<-END >&2
    131 		USAGE: iosnoop [-a|-A|-DeghiNostv] [-d device] [-f filename]
    132 		               [-m mount_point] [-n name] [-p PID]
    133 		       iosnoop          # default output
    134 		                -a      # print all data (mostly)
    135 		                -A      # dump all data, space delimited
    136 		                -D      # print time delta, us (elapsed)
    137 		                -e      # print device name
    138 		                -g      # print command arguments
    139 		                -i      # print device instance
    140 		                -N      # print major and minor numbers
    141 		                -o      # print disk delta time, us
    142 		                -s      # print start time, us
    143 		                -t      # print completion time, us
    144 		                -v      # print completion time, string
    145 		                -d device       # instance name to snoop 
    146 		                -f filename     # snoop this file only
    147 		                -m mount_point  # this FS only 
    148 		                -n name         # this process name only 
    149 		                -p PID          # this PID only 
    150 		   eg,
    151 		        iosnoop -v      # human readable timestamps
    152 		        iosnoop -N      # print major and minor numbers
    153 		        iosnoop -m /    # snoop events on filesystem / only
    154 		END
    155 		exit 1
    156 	esac
    157 done
    158 
    159 ### option logic
    160 if [ $opt_dump -eq 1 ]; then
    161 	opt_delta=0; opt_devname=0; opt_args=2; opt_start=0; 
    162 	opt_end=0; opt_endstr=0; opt_nums=0; opt_ins=0; opt_dtime=0
    163 fi
    164 if [ $opt_device -eq 1 -o $opt_file -eq 1 -o $opt_mount -eq 1 -o \
    165     $opt_name -eq 1 -o $opt_pid -eq 1 ]; then
    166 	filter=1
    167 fi
    168 
    169 
    170 #################################
    171 # --- Main Program, DTrace ---
    172 #
    173 /usr/sbin/dtrace -n '
    174  /*
    175   * Command line arguments
    176   */
    177  inline int OPT_dump 	= '$opt_dump';
    178  inline int OPT_device 	= '$opt_device';
    179  inline int OPT_delta 	= '$opt_delta';
    180  inline int OPT_devname = '$opt_devname';
    181  inline int OPT_file 	= '$opt_file';
    182  inline int OPT_args 	= '$opt_args';
    183  inline int OPT_ins  	= '$opt_ins';
    184  inline int OPT_nums  	= '$opt_nums';
    185  inline int OPT_dtime 	= '$opt_dtime';
    186  inline int OPT_mount 	= '$opt_mount';
    187  inline int OPT_start 	= '$opt_start';
    188  inline int OPT_pid 	= '$opt_pid';
    189  inline int OPT_name 	= '$opt_name';
    190  inline int OPT_end 	= '$opt_end';
    191  inline int OPT_endstr 	= '$opt_endstr';
    192  inline int FILTER 	= '$filter';
    193  inline int PID 	= '$pid';
    194  inline string DEVICE 	= "'$device'";
    195  inline string FILENAME = "'$filename'";
    196  inline string MOUNT 	= "'$mount'";
    197  inline string NAME 	= "'$pname'";
    198  
    199  #pragma D option quiet
    200  #pragma D option switchrate=10hz
    201 
    202  /* boost the following if you get "dynamic variable drops" */
    203  #pragma D option dynvarsize=16m
    204 
    205  /*
    206   * Print header
    207   */
    208  dtrace:::BEGIN 
    209  {
    210 	last_event[""] = 0;
    211 
    212 	/* print optional headers */
    213  	OPT_start   ? printf("%-14s ","STIME(us)")   : 1;
    214  	OPT_end     ? printf("%-14s ","TIME(us)")    : 1;
    215  	OPT_endstr  ? printf("%-20s ","STRTIME") : 1;
    216  	OPT_devname ? printf("%-7s ","DEVICE")   : 1;
    217  	OPT_ins     ? printf("%-3s ","INS")      : 1;
    218  	OPT_nums    ? printf("%-3s %-3s ","MAJ","MIN") : 1;
    219  	OPT_delta   ? printf("%-10s ","DELTA(us)")   : 1;
    220  	OPT_dtime   ? printf("%-10s ","DTIME(us)")   : 1;
    221 
    222 	/* print main headers */
    223 	OPT_dump ? 
    224 	    printf("%s %s %s %s %s %s %s %s %s %s %s %s %s %s %s %s %s %s\n",
    225  	    "TIME", "STIME", "DELTA", "DEVICE", "INS", "MAJ", "MIN", "UID",
    226 	    "PID", "PPID", "D", "BLOCK", "SIZE", "MOUNT", "FILE", "PATH",
    227 	    "COMM","ARGS") :
    228  	    printf("%5s %5s %1s %8s %6s ", "UID", "PID", "D", "BLOCK", "SIZE");
    229 	OPT_args == 0 ? printf("%10s %s\n", "COMM", "PATHNAME") : 1;
    230  	OPT_args == 1 ? printf("%28s %s\n", "PATHNAME", "ARGS") : 1;
    231  }
    232 
    233  /*
    234   * Check event is being traced
    235   */
    236  io:::start
    237  { 
    238 	/* default is to trace unless filtering, */
    239 	self->ok = FILTER ? 0 : 1;
    240 
    241 	/* check each filter, */
    242 	(OPT_device == 1 && DEVICE == args[1]->dev_statname)? self->ok = 1 : 1;
    243 	(OPT_file == 1 && FILENAME == args[2]->fi_pathname) ? self->ok = 1 : 1;
    244 	(OPT_mount == 1 && MOUNT == args[2]->fi_mount) ? self->ok = 1 : 1;
    245 	(OPT_name == 1 && NAME == execname) ? self->ok = 1 : 1;
    246 	(OPT_pid == 1 && PID == pid) ? self->ok = 1 : 1;
    247  }
    248 
    249  /*
    250   * Reset last_event for disk idle -> start
    251   * this prevents idle time being counted as disk time.
    252   */
    253  io:::start
    254  /! pending[args[1]->dev_statname]/
    255  {
    256 	/* save last disk event */
    257 	last_event[args[1]->dev_statname] = timestamp;
    258  }
    259 
    260  /*
    261   * Store entry details
    262   */
    263  io:::start
    264  /self->ok/
    265  {
    266 	/* these are used as a unique disk event key, */
    267  	this->dev = args[0]->b_edev;
    268  	this->blk = args[0]->b_blkno;
    269 
    270 	/* save disk event details, */
    271  	start_uid[this->dev, this->blk] = uid;
    272  	start_pid[this->dev, this->blk] = pid;
    273  	start_ppid[this->dev, this->blk] = ppid;
    274  	start_args[this->dev, this->blk] = (char *)curpsinfo->pr_psargs;
    275  	start_comm[this->dev, this->blk] = execname;
    276  	start_time[this->dev, this->blk] = timestamp;
    277 
    278 	/* increase disk event pending count */
    279 	pending[args[1]->dev_statname]++;
    280 
    281 	self->ok = 0;
    282  }
    283 
    284  /*
    285   * Process and Print completion
    286   */
    287  io:::done
    288  /start_time[args[0]->b_edev, args[0]->b_blkno]/
    289  {
    290 	/* decrease disk event pending count */
    291 	pending[args[1]->dev_statname]--;
    292 
    293 	/*
    294 	 * Process details
    295 	 */
    296 
    297  	/* fetch entry values */
    298  	this->dev = args[0]->b_edev;
    299  	this->blk = args[0]->b_blkno;
    300  	this->suid = start_uid[this->dev, this->blk];
    301  	this->spid = start_pid[this->dev, this->blk];
    302  	this->sppid = start_ppid[this->dev, this->blk];
    303  	self->sargs = (int)start_args[this->dev, this->blk] == 0 ? 
    304  	    "" : start_args[this->dev, this->blk];
    305  	self->scomm = start_comm[this->dev, this->blk];
    306  	this->stime = start_time[this->dev, this->blk];
    307 	this->etime = timestamp; /* endtime */
    308 	this->delta = this->etime - this->stime;
    309 	this->dtime = last_event[args[1]->dev_statname] == 0 ? 0 :
    310 	    timestamp - last_event[args[1]->dev_statname];
    311 
    312  	/* memory cleanup */
    313  	start_uid[this->dev, this->blk]  = 0;
    314  	start_pid[this->dev, this->blk]  = 0;
    315  	start_ppid[this->dev, this->blk] = 0;
    316  	start_args[this->dev, this->blk] = 0;
    317  	start_time[this->dev, this->blk] = 0;
    318  	start_comm[this->dev, this->blk] = 0;
    319  	start_rw[this->dev, this->blk]   = 0;
    320 
    321 	/*
    322 	 * Print details
    323 	 */
    324 
    325 	/* print optional fields */
    326  	OPT_start   ? printf("%-14d ", this->stime/1000) : 1;
    327  	OPT_end     ? printf("%-14d ", this->etime/1000) : 1;
    328  	OPT_endstr  ? printf("%-20Y ", walltimestamp) : 1;
    329  	OPT_devname ? printf("%-7s ", args[1]->dev_statname) : 1;
    330  	OPT_ins     ? printf("%3d ", args[1]->dev_instance) : 1;
    331  	OPT_nums    ? printf("%3d %3d ",
    332 	    args[1]->dev_major, args[1]->dev_minor) : 1;
    333  	OPT_delta   ? printf("%-10d ", this->delta/1000) : 1;
    334  	OPT_dtime   ? printf("%-10d ", this->dtime/1000) : 1;
    335 
    336 	/* print main fields */
    337 	OPT_dump ? 
    338  	    printf("%d %d %d %s %d %d %d %d %d %d %s %d %d %s %s %s %s %S\n",
    339  	    this->etime/1000, this->stime/1000, this->delta/1000,
    340  	    args[1]->dev_statname, args[1]->dev_instance, args[1]->dev_major,
    341 	    args[1]->dev_minor, this->suid, this->spid, this->sppid, 
    342 	    args[0]->b_flags & B_READ ? "R" : "W", 
    343 	    args[0]->b_blkno, args[0]->b_bcount, args[2]->fi_mount,
    344 	    args[2]->fi_name, args[2]->fi_pathname, self->scomm, self->sargs) :
    345  	    printf("%5d %5d %1s %8d %6d ",
    346  	    this->suid, this->spid, args[0]->b_flags & B_READ ? "R" : "W",
    347 	    args[0]->b_blkno, args[0]->b_bcount);
    348 	OPT_args == 0 ? printf("%10s %s\n", self->scomm, args[2]->fi_pathname)
    349 	    : 1;
    350  	OPT_args == 1 ? printf("%28s %S\n",
    351 	    args[2]->fi_pathname, self->sargs) : 1;
    352 
    353 	/* save last disk event */
    354 	last_event[args[1]->dev_statname] = timestamp;
    355 
    356 	/* cleanup */
    357 	self->scomm = 0;
    358 	self->sargs = 0;
    359  }
    360 
    361  /*
    362   * Prevent pending from underflowing
    363   * this can happen if this program is started during disk events.
    364   */
    365  io:::done
    366  /pending[args[1]->dev_statname] < 0/
    367  {
    368 	pending[args[1]->dev_statname] = 0;
    369  }
    370 '
    371