1#!/usr/bin/sh
2#
3# dappprof - profile user and library function usage.
4#            Written using DTrace (Solaris 10 3/05).
5#
6# The default output traces user functions as they are called. Options
7#  can be used to examine libraries and timestamps.
8#
9# $Id: dappprof 65 2007-10-04 11:09:40Z brendan $
10#
11# USAGE: dappprof [-acehoTU] [-u lib] { -p PID | command }
12#
13#          -p PID          # examine this PID
14#          -a              # print all details
15#          -c              # print call counts
16#          -e              # print elapsed times (us)
17#          -o              # print on cpu times (us)
18#          -T              # print totals
19#          -u lib          # trace this library instead
20#          -U              # trace all libraries + user functions
21#          -b bufsize      # dynamic variable buf size (default is "4m")
22#  eg,
23#       dappprof df -h       # run and examine the "df -h" command
24#       dappprof -p 1871     # examine PID 1871
25#
26# The elapsed times are interesting, to help identify calls that take
27#  some time to complete (during which the process may have context
28#  switched off the CPU). 
29#
30# SEE ALSO: dapptrace      # DTraceToolkit
31#           dtruss         # DTraceToolkit
32#           apptrace           
33#
34# COPYRIGHT: Copyright (c) 2005 Brendan Gregg.
35#
36# CDDL HEADER START
37#
38#  The contents of this file are subject to the terms of the
39#  Common Development and Distribution License, Version 1.0 only
40#  (the "License").  You may not use this file except in compliance
41#  with the License.
42#
43#  You can obtain a copy of the license at Docs/cddl1.txt
44#  or http://www.opensolaris.org/os/licensing.
45#  See the License for the specific language governing permissions
46#  and limitations under the License.
47#
48# CDDL HEADER END
49#
50# Author: Brendan Gregg  [Sydney, Australia]
51#
52# 16-May-2005   Brendan Gregg   Created this.
53# 17-Jul-2005	   "      "	Last update.
54#
55
56
57##############################
58# --- Process Arguments ---
59#
60
61### Default variables
62opt_totals=0; opt_pid=0; pid=0; opt_lib=0; lib=""
63opt_elapsed=0; opt_cpu=0; opt_counts=0; opt_liball=0
64opt_command=0; command=""; opt_buf=0; buf="4m"
65
66### Process options
67while getopts ab:cehop:Tu:U name
68do
69        case $name in
70        a)      opt_liball=1; opt_counts=1; opt_elapsed=1; opt_cpu=1 
71		opt_totals=1 ;;
72	b)	opt_buf=1; buf=$OPTARG ;;
73        p)      opt_pid=1; pid=$OPTARG ;;
74        u)      opt_lib=1; lib=$OPTARG ;;
75        U)      opt_liball=1 ;; 
76	c)	opt_counts=1 ;;
77	e)	opt_elapsed=1 ;;
78	o)	opt_cpu=1 ;;
79	T)	opt_totals=1 ;;
80        h|?)    cat <<-END >&2
81		USAGE: dappprof [-cehoTU] [-u lib] { -p PID | command }
82
83		          -p PID          # examine this PID
84		          -a              # print all details
85		          -c              # print syscall counts
86		          -e              # print elapsed times (us)
87		          -o              # print on cpu times
88		          -T              # print totals
89		          -u lib          # trace this library instead
90		          -U              # trace all libraries + user funcs
91		          -b bufsize      # dynamic variable buf size
92		   eg,
93		       dappprof df -h       # run and examine "df -h"
94		       dappprof -p 1871     # examine PID 1871
95		       dappprof -ap 1871    # print all data
96		END
97		exit 1
98        esac
99done
100shift `expr $OPTIND - 1`
101
102### Option logic
103if [ $opt_pid -eq 0 ]; then
104	opt_command=1
105	if [ "$*" = "" ]; then
106		$0 -h
107		exit
108	fi
109	command="$*"
110fi
111if [ $opt_elapsed -eq 0 -a $opt_cpu -eq 0 -a $opt_counts -eq 0 ]; then
112        opt_elapsed=1;
113fi
114
115
116### Probe logic
117if [ $opt_liball -eq 1 ]; then
118	probe_entry='pid$target:::entry'
119	probe_return='pid$target:::return'
120elif [ $opt_lib -eq 1 ]; then
121	probe_entry='pid$target:'$lib'::entry'
122	probe_return='pid$target:'$lib'::return'
123else
124 	probe_entry='pid$target:a.out::entry'
125 	probe_return='pid$target:a.out::return'
126fi
127
128#################################
129# --- Main Program, DTrace ---
130#
131
132### Define D Script
133dtrace='
134 #pragma D option quiet
135
136 /*
137  * Command line arguments
138  */
139 inline int OPT_command   = '$opt_command';
140 inline int OPT_liball    = '$opt_liball';
141 inline int OPT_elapsed   = '$opt_elapsed';
142 inline int OPT_cpu       = '$opt_cpu';
143 inline int OPT_counts    = '$opt_counts';
144 inline int OPT_totals    = '$opt_totals';
145 inline int OPT_pid       = '$opt_pid';
146 inline int PID           = '$pid';
147 inline string NAME       = "'$pname'";
148
149 dtrace:::BEGIN 
150 /! OPT_command/
151 {
152	printf("Tracing... Hit Ctrl-C to end...\n");
153 }
154
155 /*
156  * Save syscall entry info
157  */
158 '$probe_entry'
159 {
160        /* set function depth */
161        this->fdepth = ++fdepth[probefunc];
162
163	/* set start details */
164	self->start[probefunc,this->fdepth] = timestamp;
165	self->vstart[probefunc,this->fdepth] = vtimestamp;
166
167	/* count occurances */
168	OPT_counts && OPT_liball ? @Counts[probemod,probefunc] = count() : 1;
169	OPT_counts && ! OPT_liball ? @Counts[probefunc] = count() : 1;
170	OPT_counts && OPT_totals && OPT_liball ? 
171	    @Counts["TOTAL:",""] = count() : 1;
172	OPT_counts && OPT_totals && ! OPT_liball ? 
173	    @Counts["TOTAL:"] = count() : 1;
174 }
175
176 /*
177  * Print return data
178  */
179 /* print 3 arg output - default */
180 '$probe_return'
181 /self->start[probefunc,fdepth[probefunc]]/
182 {
183        /* fetch function depth */
184        this->fdepth = fdepth[probefunc];
185
186	/* calculate elapsed time */
187	this->elapsed = timestamp - self->start[probefunc,this->fdepth];
188	self->start[probefunc,this->fdepth] = 0;
189	this->cpu = vtimestamp - self->vstart[probefunc,this->fdepth];
190	self->vstart[probefunc,this->fdepth] = 0;
191
192	/* save elapsed times */
193	OPT_elapsed && OPT_liball ? 
194	    @Elapsed[probemod,probefunc] = sum(this->elapsed) : 1;
195	OPT_elapsed && ! OPT_liball ? 
196	    @Elapsed[probefunc] = sum(this->elapsed) : 1;
197	OPT_elapsed && OPT_totals && OPT_liball ? 
198	    @Elapsed["TOTAL:",""] = sum(this->elapsed) : 1;
199	OPT_elapsed && OPT_totals && ! OPT_liball ? 
200	    @Elapsed["TOTAL:"] = sum(this->elapsed) : 1;
201
202	/* save cpu times */
203	OPT_cpu && OPT_liball ? @CPU[probemod,probefunc] = sum(this->cpu) : 1;
204	OPT_cpu && ! OPT_liball ? @CPU[probefunc] = sum(this->cpu) : 1;
205	OPT_cpu && OPT_totals && OPT_liball ? 
206	    @CPU["TOTAL:",""] = sum(this->cpu) : 1;
207	OPT_cpu && OPT_totals && ! OPT_liball ? 
208	    @CPU["TOTAL:"] = sum(this->cpu) : 1;
209	
210 }
211
212 /* print counts */
213 dtrace:::END
214 {
215	/* print counts */
216	OPT_counts ? printf("\n%-49s %16s\n","CALL","COUNT") : 1;
217	OPT_counts && OPT_liball ? printa("%-16s %-32s %@16d\n",@Counts) : 1;
218	OPT_counts && ! OPT_liball ? printa("%-49s %@16d\n",@Counts) : 1;
219
220	/* print elapsed times */
221	OPT_elapsed ? printf("\n%-49s %16s\n","CALL","ELAPSED") : 1;
222	OPT_elapsed && OPT_liball ? printa("%-16s %-32s %@16d\n",@Elapsed) : 1;
223	OPT_elapsed && ! OPT_liball ? printa("%-49s %@16d\n",@Elapsed) : 1;
224
225	/* print cpu times */
226	OPT_cpu ? printf("\n%-49s %16s\n","CALL","CPU") : 1;
227	OPT_cpu && OPT_liball ? printa("%-16s %-32s %@16d\n",@CPU) : 1;
228	OPT_cpu && ! OPT_liball ? printa("%-49s %@16d\n",@CPU) : 1;
229 }
230'
231
232### Run DTrace
233if [ $opt_command -eq 1 ]; then
234	/usr/sbin/dtrace -x dynvarsize=$buf -x evaltime=exec -n "$dtrace" \
235	    -c "$command" >&2
236else
237	/usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" -p "$pid" >&2
238fi
239
240