iosnoop revision 1.2 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