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