dappprof revision 1.1 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,v 1.1 2015/09/30 22:01:07 christos Exp $
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
62 opt_totals=0; opt_pid=0; pid=0; opt_lib=0; lib=""
63 opt_elapsed=0; opt_cpu=0; opt_counts=0; opt_liball=0
64 opt_command=0; command=""; opt_buf=0; buf="4m"
65
66 ### Process options
67 while getopts ab:cehop:Tu:U name
68 do
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
99 done
100 shift `expr $OPTIND - 1`
101
102 ### Option logic
103 if [ $opt_pid -eq 0 ]; then
104 opt_command=1
105 if [ "$*" = "" ]; then
106 $0 -h
107 exit
108 fi
109 command="$*"
110 fi
111 if [ $opt_elapsed -eq 0 -a $opt_cpu -eq 0 -a $opt_counts -eq 0 ]; then
112 opt_elapsed=1;
113 fi
114
115
116 ### Probe logic
117 if [ $opt_liball -eq 1 ]; then
118 probe_entry='pid$target:::entry'
119 probe_return='pid$target:::return'
120 elif [ $opt_lib -eq 1 ]; then
121 probe_entry='pid$target:'$lib'::entry'
122 probe_return='pid$target:'$lib'::return'
123 else
124 probe_entry='pid$target:a.out::entry'
125 probe_return='pid$target:a.out::return'
126 fi
127
128 #################################
129 # --- Main Program, DTrace ---
130 #
131
132 ### Define D Script
133 dtrace='
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
233 if [ $opt_command -eq 1 ]; then
234 /usr/sbin/dtrace -x dynvarsize=$buf -x evaltime=exec -n "$dtrace" \
235 -c "$command" >&2
236 else
237 /usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" -p "$pid" >&2
238 fi
239
240