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