1#!/bin/sh
2#
3# dtruss - print process system call time details.
4#          Written using DTrace (Solaris 10 3/05).
5#
6# $Id: dtruss 9 2007-08-07 10:21:07Z brendan $
7#
8# USAGE: dtruss [-acdeflhoLs] [-t syscall] { -p PID | -n name | command }
9#
10#		-p PID		# examine this PID
11#		-n name		# examine this process name
12#		-t syscall	# examine this syscall only
13#		-a		# print all details
14#		-c		# print system call counts
15#		-d		# print relative timestamps (us)
16#		-e		# print elapsed times (us)
17#		-f		# follow children as they are forked
18#		-l		# force printing of pid/lwpid per line
19#		-o		# print on cpu times (us)
20#		-s		# print stack backtraces
21#		-L		# don't print pid/lwpid per line
22#		-b bufsize	# dynamic variable buf size (default is "4m")
23#  eg,
24#		dtruss df -h	# run and examine the "df -h" command
25#		dtruss -p 1871	# examine PID 1871
26#		dtruss -n tar	# examine all processes called "tar"
27#		dtruss -f test.sh	# run test.sh and follow children
28#
29# See the man page dtruss(1M) for further details.
30#
31# SEE ALSO: procsystime    # DTraceToolkit
32#           dapptrace      # DTraceToolkit
33#           truss
34#
35# COPYRIGHT: Copyright (c) 2005, 2006, 2007 Brendan Gregg.
36#
37# CDDL HEADER START
38#
39#  The contents of this file are subject to the terms of the
40#  Common Development and Distribution License, Version 1.0 only
41#  (the "License").  You may not use this file except in compliance
42#  with the License.
43#
44#  You can obtain a copy of the license at Docs/cddl1.txt
45#  or http://www.opensolaris.org/os/licensing.
46#  See the License for the specific language governing permissions
47#  and limitations under the License.
48#
49# CDDL HEADER END
50#
51# TODO: Track signals, more output formatting.
52#
53# 29-Apr-2005   Brendan Gregg   Created this.
54# 09-May-2005      "      " 	Fixed evaltime (thanks Adam L.)
55# 16-May-2005	   "      "	Added -t syscall tracing.
56# 17-Jun-2005	   "      "	Added -s stack backtraces.
57# 17-Jun-2005	   "      "	Last update.
58# 29-Jun-2007	   "      "	Used progenyof() (thanks Aaron Gutman).
59# 06-Aug-2007	   "      "	Various updates.
60#
61
62
63##############################
64# --- Process Arguments ---
65#
66
67### Default variables
68opt_pid=0; opt_name=0; pid=0; pname="."; opt_elapsed=0; opt_cpu=0
69opt_counts=0; opt_relative=0; opt_printid=0; opt_follow=0; opt_command=0
70command=""; opt_buf=0; buf="4m"; opt_trace=0; trace="."; opt_stack=0
71
72### Process options
73while getopts ab:cdefhln:op:st:L name
74do
75        case $name in
76	b)	opt_buf=1; buf=$OPTARG ;;
77        p)      opt_pid=1; pid=$OPTARG ;;
78        n)      opt_name=1; pname=$OPTARG ;;
79        t)      opt_trace=1; trace=$OPTARG ;;
80	a)	opt_counts=1; opt_relative=1; opt_elapsed=1; opt_follow=1
81		opt_printid=1; opt_cpu=1 ;;
82	c)	opt_counts=1 ;;
83	d)	opt_relative=1 ;;
84	e)	opt_elapsed=1 ;;
85	f)	opt_follow=1 ;;
86	l)	opt_printid=1 ;;
87	o)	opt_cpu=1 ;;
88	L)	opt_printid=-1 ;;
89	s)	opt_stack=-1 ;;
90        h|?)    cat <<-END >&2
91		USAGE: dtruss [-acdefholLs] [-t syscall] { -p PID | -n name | command }
92
93		          -p PID          # examine this PID
94		          -n name         # examine this process name
95		          -t syscall      # examine this syscall only
96		          -a              # print all details
97		          -c              # print syscall counts
98		          -d              # print relative times (us)
99		          -e              # print elapsed times (us)
100		          -f              # follow children (-p or cmd only)
101		          -l              # force printing pid/lwpid
102		          -o              # print on cpu times
103		          -s              # print stack backtraces
104		          -L              # don't print pid/lwpid
105		          -b bufsize      # dynamic variable buf size
106		   eg,
107		       dtruss df -h       # run and examine "df -h"
108		       dtruss -p 1871     # examine PID 1871
109		       dtruss -n tar      # examine all processes called "tar"
110		       dtruss -f test.sh  # run test.sh and follow children
111		END
112		exit 1
113        esac
114done
115shift `expr $OPTIND - 1`
116
117### Option logic
118if [ $opt_pid -eq 0 -a $opt_name -eq 0 ]; then
119	opt_command=1
120	if [ "$*" = "" ]; then
121		$0 -h
122		exit
123	fi
124	command="$*"	# yes, I meant $*!
125fi
126if [ $opt_follow -eq 1 -o $opt_name -eq 1 ]; then
127	if [ $opt_printid -ne -1 ]; then
128		opt_printid=1
129	else
130		opt_printid=0
131	fi
132fi
133if [ $opt_follow -eq 1 -a $opt_name -eq 1 ]; then
134	echo "ERROR: -f option cannot be used with -n (use -p or cmd instead)."
135	exit 1
136fi
137
138### Option translation
139if [ "$trace" = "exec" ]; then trace="exece"; fi
140if [ "$trace" = "time" ]; then trace="gtime"; fi
141if [ "$trace" = "exit" ]; then trace="rexit"; fi
142
143
144#################################
145# --- Main Program, DTrace ---
146#
147
148### Define D Script
149dtrace='
150#pragma D option quiet
151#pragma D option switchrate=10
152 
153/*
154 * Command line arguments
155 */
156inline int OPT_command   = '$opt_command';
157inline int OPT_follow    = '$opt_follow';
158inline int OPT_printid   = '$opt_printid';
159inline int OPT_relative  = '$opt_relative';
160inline int OPT_elapsed   = '$opt_elapsed';
161inline int OPT_cpu       = '$opt_cpu';
162inline int OPT_counts    = '$opt_counts';
163inline int OPT_pid       = '$opt_pid';
164inline int OPT_name      = '$opt_name';
165inline int OPT_trace     = '$opt_trace';
166inline int OPT_stack     = '$opt_stack';
167inline string NAME       = "'$pname'";
168inline string TRACE      = "'$trace'";
169
170dtrace:::BEGIN 
171{
172	/* print header */
173	OPT_printid  ? printf("%-9s  ", "PID/LWP") : 1;
174	OPT_relative ? printf("%8s ", "RELATIVE") : 1;
175	OPT_elapsed  ? printf("%7s ", "ELAPSD") : 1;
176	OPT_cpu      ? printf("%6s ", "CPU") : 1;
177	printf("SYSCALL(args) \t\t = return\n");
178}
179
180/*
181 * Save syscall entry info
182 */
183syscall:::entry
184/((OPT_command || OPT_pid) && pid == $target) || 
185 (OPT_name && execname == NAME) ||
186 (OPT_follow && progenyof($target))/
187{
188	/* set start details */
189	self->start = timestamp;
190	self->vstart = vtimestamp;
191	self->arg0 = arg0;
192	self->arg1 = arg1;
193	self->arg2 = arg2;
194
195	/* count occurances */
196	OPT_counts == 1 ? @Counts[probefunc] = count() : 1;
197}
198
199/*
200 * Follow children
201 */
202syscall::fork*:return
203/(OPT_follow && progenyof($target)) && (!OPT_trace || (TRACE == probefunc))/
204{
205	/* print output */
206	self->code = errno == 0 ? "" : "Err#";
207	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
208	OPT_relative ? printf("%8d:  ", vtimestamp/1000) : 1;
209	OPT_elapsed  ? printf("%7d:  ", 0) : 1;
210	OPT_cpu      ? printf("%6d ", 0) : 1;
211	printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc,
212	    self->arg0, self->arg1, self->arg2, (int)arg0, self->code,
213	    (int)errno);
214}
215
216/*
217 * Check for syscall tracing
218 */
219syscall:::entry
220/OPT_trace && probefunc != TRACE/
221{
222	/* drop info */
223	self->start = 0;
224	self->vstart = 0;
225	self->arg0 = 0;
226	self->arg1 = 0;
227	self->arg2 = 0;
228}
229
230/*
231 * Print return data
232 */
233
234/*
235 * The following code is written in an intentionally repetative way.
236 * The first versions had no code redundancies, but performed badly during
237 * benchmarking. The priority here is speed, not cleverness. I know there
238 * are many obvious shortcuts to this code, I have tried them. This style has
239 * shown in benchmarks to be the fastest (fewest probes fired, fewest actions).
240 */
241
242/* print 3 args, return as hex */
243syscall::sigprocmask:return
244/self->start/
245{
246	/* calculate elapsed time */
247	this->elapsed = timestamp - self->start;
248	self->start = 0;
249	this->cpu = vtimestamp - self->vstart;
250	self->vstart = 0;
251	self->code = errno == 0 ? "" : "Err#";
252 
253	/* print optional fields */
254	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
255	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
256	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
257	OPT_cpu ? printf("%6d ", this->cpu/1000) : 1;
258 
259	/* print main data */
260	printf("%s(0x%X, 0x%X, 0x%X)\t\t = 0x%X %s%d\n", probefunc,
261	    (int)self->arg0, self->arg1, self->arg2, (int)arg0,
262	    self->code, (int)errno);
263	OPT_stack ? ustack()    : 1;
264	OPT_stack ? trace("\n") : 1;
265	self->arg0 = 0;
266	self->arg1 = 0;
267	self->arg2 = 0;
268}
269
270/* print 3 args, arg0 as a string */
271syscall::access*:return,
272syscall::stat*:return, 
273syscall::lstat*:return, 
274syscall::readlink*:return,
275syscall::open*:return
276/self->start/
277{
278	/* calculate elapsed time */
279	this->elapsed = timestamp - self->start;
280	self->start = 0;
281	this->cpu = vtimestamp - self->vstart;
282	self->vstart = 0;
283	self->code = errno == 0 ? "" : "Err#";
284 
285	/* print optional fields */
286	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
287	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
288	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
289	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
290 
291	/* print main data */
292	printf("%s(\"%S\", 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc,
293	    copyinstr(self->arg0), self->arg1, self->arg2, (int)arg0,
294	    self->code, (int)errno);
295	OPT_stack ? ustack()    : 1;
296	OPT_stack ? trace("\n") : 1;
297	self->arg0 = 0;
298	self->arg1 = 0;
299	self->arg2 = 0;
300}
301
302/* print 3 args, arg1 as a string */
303syscall::write:return,
304syscall::pwrite:return,
305syscall::*read*:return
306/self->start/
307{
308	/* calculate elapsed time */
309	this->elapsed = timestamp - self->start;
310	self->start = 0;
311	this->cpu = vtimestamp - self->vstart;
312	self->vstart = 0;
313	self->code = errno == 0 ? "" : "Err#";
314 
315	/* print optional fields */
316	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
317	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
318	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
319	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
320 
321	/* print main data */
322	printf("%s(0x%X, \"%S\", 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
323	    stringof(copyin(self->arg1, self->arg2)), self->arg2, (int)arg0,
324	    self->code, (int)errno);
325	OPT_stack ? ustack()    : 1;
326	OPT_stack ? trace("\n") : 1;
327	self->arg0 = 0;
328	self->arg1 = 0;
329	self->arg2 = 0;
330}
331
332/* print 0 arg output */
333syscall::*fork*:return
334/self->start/
335{
336	/* calculate elapsed time */
337	this->elapsed = timestamp - self->start;
338	self->start = 0;
339	this->cpu = vtimestamp - self->vstart;
340	self->vstart = 0;
341	self->code = errno == 0 ? "" : "Err#";
342 
343	/* print optional fields */
344	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
345	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
346	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
347	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
348 
349	/* print main data */
350	printf("%s()\t\t = %d %s%d\n", probefunc,
351	    (int)arg0, self->code, (int)errno);
352	OPT_stack ? ustack()    : 1;
353	OPT_stack ? trace("\n") : 1;
354	self->arg0 = 0;
355	self->arg1 = 0;
356	self->arg2 = 0;
357}
358
359/* print 1 arg output */
360syscall::close:return
361/self->start/
362{
363	/* calculate elapsed time */
364	this->elapsed = timestamp - self->start;
365	self->start = 0;
366	this->cpu = vtimestamp - self->vstart;
367	self->vstart = 0;
368	self->code = errno == 0 ? "" : "Err#";
369 
370	/* print optional fields */
371	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
372	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
373	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
374	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
375 
376	/* print main data */
377	printf("%s(0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
378	    (int)arg0, self->code, (int)errno);
379	OPT_stack ? ustack()    : 1;
380	OPT_stack ? trace("\n") : 1;
381	self->arg0 = 0;
382	self->arg1 = 0;
383	self->arg2 = 0;
384}
385
386/* print 2 arg output */
387syscall::utimes:return,
388syscall::munmap:return
389/self->start/
390{
391	/* calculate elapsed time */
392	this->elapsed = timestamp - self->start;
393	self->start = 0;
394	this->cpu = vtimestamp - self->vstart;
395	self->vstart = 0;
396	self->code = errno == 0 ? "" : "Err#";
397 
398	/* print optional fields */
399	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
400	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
401	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
402	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
403 
404	/* print main data */
405	printf("%s(0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
406	    self->arg1, (int)arg0, self->code, (int)errno);
407	OPT_stack ? ustack()    : 1;
408	OPT_stack ? trace("\n") : 1;
409	self->arg0 = 0;
410	self->arg1 = 0;
411	self->arg2 = 0;
412}
413
414/* print 3 arg output - default */
415syscall:::return
416/self->start/
417{
418	/* calculate elapsed time */
419	this->elapsed = timestamp - self->start;
420	self->start = 0;
421	this->cpu = vtimestamp - self->vstart;
422	self->vstart = 0;
423	self->code = errno == 0 ? "" : "Err#";
424 
425	/* print optional fields */
426	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
427	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
428	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
429	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
430 
431	/* print main data */
432	printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
433	    self->arg1, self->arg2, (int)arg0, self->code, (int)errno);
434	OPT_stack ? ustack()    : 1;
435	OPT_stack ? trace("\n") : 1;
436	self->arg0 = 0;
437	self->arg1 = 0;
438	self->arg2 = 0;
439}
440
441/* program exited */
442proc:::exit
443/(OPT_command || OPT_pid) && pid == $target/
444{
445	exit(0);
446}
447
448/* print counts */
449dtrace:::END
450{
451	OPT_counts == 1 ? printf("\n%-32s %16s\n", "CALL", "COUNT") : 1;
452	OPT_counts == 1 ? printa("%-32s %@16d\n", @Counts) : 1;
453}
454'
455
456### Run DTrace
457if [ $opt_command -eq 1 ]; then
458	/usr/sbin/dtrace -x dynvarsize=$buf -x evaltime=exec -n "$dtrace" \
459	    -c "$command" >&2
460elif [ $opt_pid -eq 1 ]; then
461	/usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" -p "$pid" >&2
462else
463	/usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" >&2
464fi
465