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