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,v 1.1.1.1 2015/09/30 22:01:07 christos Exp $
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
49opt_read=0; opt_write=0
50
51### Process options
52while getopts hrw name
53do
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
67done
68shift `expr $OPTIND - 1`
69
70PID=$1
71clearstr=`clear`
72
73if [ -z "$PID" ]
74then
75	echo "Must supply pid"
76	exit 1
77fi
78
79### Option logic
80if [ $opt_read -eq 0 -a $opt_write -eq 0 ]; then
81	opt_read=1; opt_write=1
82fi
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'
283