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