dappprof revision 235368
1235368Sgnn#!/usr/bin/sh 2235368Sgnn# 3235368Sgnn# dappprof - profile user and library function usage. 4235368Sgnn# Written using DTrace (Solaris 10 3/05). 5235368Sgnn# 6235368Sgnn# The default output traces user functions as they are called. Options 7235368Sgnn# can be used to examine libraries and timestamps. 8235368Sgnn# 9235368Sgnn# $Id: dappprof 65 2007-10-04 11:09:40Z brendan $ 10235368Sgnn# 11235368Sgnn# USAGE: dappprof [-acehoTU] [-u lib] { -p PID | command } 12235368Sgnn# 13235368Sgnn# -p PID # examine this PID 14235368Sgnn# -a # print all details 15235368Sgnn# -c # print call counts 16235368Sgnn# -e # print elapsed times (us) 17235368Sgnn# -o # print on cpu times (us) 18235368Sgnn# -T # print totals 19235368Sgnn# -u lib # trace this library instead 20235368Sgnn# -U # trace all libraries + user functions 21235368Sgnn# -b bufsize # dynamic variable buf size (default is "4m") 22235368Sgnn# eg, 23235368Sgnn# dappprof df -h # run and examine the "df -h" command 24235368Sgnn# dappprof -p 1871 # examine PID 1871 25235368Sgnn# 26235368Sgnn# The elapsed times are interesting, to help identify calls that take 27235368Sgnn# some time to complete (during which the process may have context 28235368Sgnn# switched off the CPU). 29235368Sgnn# 30235368Sgnn# SEE ALSO: dapptrace # DTraceToolkit 31235368Sgnn# dtruss # DTraceToolkit 32235368Sgnn# apptrace 33235368Sgnn# 34235368Sgnn# COPYRIGHT: Copyright (c) 2005 Brendan Gregg. 35235368Sgnn# 36235368Sgnn# CDDL HEADER START 37235368Sgnn# 38235368Sgnn# The contents of this file are subject to the terms of the 39235368Sgnn# Common Development and Distribution License, Version 1.0 only 40235368Sgnn# (the "License"). You may not use this file except in compliance 41235368Sgnn# with the License. 42235368Sgnn# 43235368Sgnn# You can obtain a copy of the license at Docs/cddl1.txt 44235368Sgnn# or http://www.opensolaris.org/os/licensing. 45235368Sgnn# See the License for the specific language governing permissions 46235368Sgnn# and limitations under the License. 47235368Sgnn# 48235368Sgnn# CDDL HEADER END 49235368Sgnn# 50235368Sgnn# Author: Brendan Gregg [Sydney, Australia] 51235368Sgnn# 52235368Sgnn# 16-May-2005 Brendan Gregg Created this. 53235368Sgnn# 17-Jul-2005 " " Last update. 54235368Sgnn# 55235368Sgnn 56235368Sgnn 57235368Sgnn############################## 58235368Sgnn# --- Process Arguments --- 59235368Sgnn# 60235368Sgnn 61235368Sgnn### Default variables 62235368Sgnnopt_totals=0; opt_pid=0; pid=0; opt_lib=0; lib="" 63235368Sgnnopt_elapsed=0; opt_cpu=0; opt_counts=0; opt_liball=0 64235368Sgnnopt_command=0; command=""; opt_buf=0; buf="4m" 65235368Sgnn 66235368Sgnn### Process options 67235368Sgnnwhile getopts ab:cehop:Tu:U name 68235368Sgnndo 69235368Sgnn case $name in 70235368Sgnn a) opt_liball=1; opt_counts=1; opt_elapsed=1; opt_cpu=1 71235368Sgnn opt_totals=1 ;; 72235368Sgnn b) opt_buf=1; buf=$OPTARG ;; 73235368Sgnn p) opt_pid=1; pid=$OPTARG ;; 74235368Sgnn u) opt_lib=1; lib=$OPTARG ;; 75235368Sgnn U) opt_liball=1 ;; 76235368Sgnn c) opt_counts=1 ;; 77235368Sgnn e) opt_elapsed=1 ;; 78235368Sgnn o) opt_cpu=1 ;; 79235368Sgnn T) opt_totals=1 ;; 80235368Sgnn h|?) cat <<-END >&2 81235368Sgnn USAGE: dappprof [-cehoTU] [-u lib] { -p PID | command } 82235368Sgnn 83235368Sgnn -p PID # examine this PID 84235368Sgnn -a # print all details 85235368Sgnn -c # print syscall counts 86235368Sgnn -e # print elapsed times (us) 87235368Sgnn -o # print on cpu times 88235368Sgnn -T # print totals 89235368Sgnn -u lib # trace this library instead 90235368Sgnn -U # trace all libraries + user funcs 91235368Sgnn -b bufsize # dynamic variable buf size 92235368Sgnn eg, 93235368Sgnn dappprof df -h # run and examine "df -h" 94235368Sgnn dappprof -p 1871 # examine PID 1871 95235368Sgnn dappprof -ap 1871 # print all data 96235368Sgnn END 97235368Sgnn exit 1 98235368Sgnn esac 99235368Sgnndone 100235368Sgnnshift `expr $OPTIND - 1` 101235368Sgnn 102235368Sgnn### Option logic 103235368Sgnnif [ $opt_pid -eq 0 ]; then 104235368Sgnn opt_command=1 105235368Sgnn if [ "$*" = "" ]; then 106235368Sgnn $0 -h 107235368Sgnn exit 108235368Sgnn fi 109235368Sgnn command="$*" 110235368Sgnnfi 111235368Sgnnif [ $opt_elapsed -eq 0 -a $opt_cpu -eq 0 -a $opt_counts -eq 0 ]; then 112235368Sgnn opt_elapsed=1; 113235368Sgnnfi 114235368Sgnn 115235368Sgnn 116235368Sgnn### Probe logic 117235368Sgnnif [ $opt_liball -eq 1 ]; then 118235368Sgnn probe_entry='pid$target:::entry' 119235368Sgnn probe_return='pid$target:::return' 120235368Sgnnelif [ $opt_lib -eq 1 ]; then 121235368Sgnn probe_entry='pid$target:'$lib'::entry' 122235368Sgnn probe_return='pid$target:'$lib'::return' 123235368Sgnnelse 124235368Sgnn probe_entry='pid$target:a.out::entry' 125235368Sgnn probe_return='pid$target:a.out::return' 126235368Sgnnfi 127235368Sgnn 128235368Sgnn################################# 129235368Sgnn# --- Main Program, DTrace --- 130235368Sgnn# 131235368Sgnn 132235368Sgnn### Define D Script 133235368Sgnndtrace=' 134235368Sgnn #pragma D option quiet 135235368Sgnn 136235368Sgnn /* 137235368Sgnn * Command line arguments 138235368Sgnn */ 139235368Sgnn inline int OPT_command = '$opt_command'; 140235368Sgnn inline int OPT_liball = '$opt_liball'; 141235368Sgnn inline int OPT_elapsed = '$opt_elapsed'; 142235368Sgnn inline int OPT_cpu = '$opt_cpu'; 143235368Sgnn inline int OPT_counts = '$opt_counts'; 144235368Sgnn inline int OPT_totals = '$opt_totals'; 145235368Sgnn inline int OPT_pid = '$opt_pid'; 146235368Sgnn inline int PID = '$pid'; 147235368Sgnn inline string NAME = "'$pname'"; 148235368Sgnn 149235368Sgnn dtrace:::BEGIN 150235368Sgnn /! OPT_command/ 151235368Sgnn { 152235368Sgnn printf("Tracing... Hit Ctrl-C to end...\n"); 153235368Sgnn } 154235368Sgnn 155235368Sgnn /* 156235368Sgnn * Save syscall entry info 157235368Sgnn */ 158235368Sgnn '$probe_entry' 159235368Sgnn { 160235368Sgnn /* set function depth */ 161235368Sgnn this->fdepth = ++fdepth[probefunc]; 162235368Sgnn 163235368Sgnn /* set start details */ 164235368Sgnn self->start[probefunc,this->fdepth] = timestamp; 165235368Sgnn self->vstart[probefunc,this->fdepth] = vtimestamp; 166235368Sgnn 167235368Sgnn /* count occurances */ 168235368Sgnn OPT_counts && OPT_liball ? @Counts[probemod,probefunc] = count() : 1; 169235368Sgnn OPT_counts && ! OPT_liball ? @Counts[probefunc] = count() : 1; 170235368Sgnn OPT_counts && OPT_totals && OPT_liball ? 171235368Sgnn @Counts["TOTAL:",""] = count() : 1; 172235368Sgnn OPT_counts && OPT_totals && ! OPT_liball ? 173235368Sgnn @Counts["TOTAL:"] = count() : 1; 174235368Sgnn } 175235368Sgnn 176235368Sgnn /* 177235368Sgnn * Print return data 178235368Sgnn */ 179235368Sgnn /* print 3 arg output - default */ 180235368Sgnn '$probe_return' 181235368Sgnn /self->start[probefunc,fdepth[probefunc]]/ 182235368Sgnn { 183235368Sgnn /* fetch function depth */ 184235368Sgnn this->fdepth = fdepth[probefunc]; 185235368Sgnn 186235368Sgnn /* calculate elapsed time */ 187235368Sgnn this->elapsed = timestamp - self->start[probefunc,this->fdepth]; 188235368Sgnn self->start[probefunc,this->fdepth] = 0; 189235368Sgnn this->cpu = vtimestamp - self->vstart[probefunc,this->fdepth]; 190235368Sgnn self->vstart[probefunc,this->fdepth] = 0; 191235368Sgnn 192235368Sgnn /* save elapsed times */ 193235368Sgnn OPT_elapsed && OPT_liball ? 194235368Sgnn @Elapsed[probemod,probefunc] = sum(this->elapsed) : 1; 195235368Sgnn OPT_elapsed && ! OPT_liball ? 196235368Sgnn @Elapsed[probefunc] = sum(this->elapsed) : 1; 197235368Sgnn OPT_elapsed && OPT_totals && OPT_liball ? 198235368Sgnn @Elapsed["TOTAL:",""] = sum(this->elapsed) : 1; 199235368Sgnn OPT_elapsed && OPT_totals && ! OPT_liball ? 200235368Sgnn @Elapsed["TOTAL:"] = sum(this->elapsed) : 1; 201235368Sgnn 202235368Sgnn /* save cpu times */ 203235368Sgnn OPT_cpu && OPT_liball ? @CPU[probemod,probefunc] = sum(this->cpu) : 1; 204235368Sgnn OPT_cpu && ! OPT_liball ? @CPU[probefunc] = sum(this->cpu) : 1; 205235368Sgnn OPT_cpu && OPT_totals && OPT_liball ? 206235368Sgnn @CPU["TOTAL:",""] = sum(this->cpu) : 1; 207235368Sgnn OPT_cpu && OPT_totals && ! OPT_liball ? 208235368Sgnn @CPU["TOTAL:"] = sum(this->cpu) : 1; 209235368Sgnn 210235368Sgnn } 211235368Sgnn 212235368Sgnn /* print counts */ 213235368Sgnn dtrace:::END 214235368Sgnn { 215235368Sgnn /* print counts */ 216235368Sgnn OPT_counts ? printf("\n%-49s %16s\n","CALL","COUNT") : 1; 217235368Sgnn OPT_counts && OPT_liball ? printa("%-16s %-32s %@16d\n",@Counts) : 1; 218235368Sgnn OPT_counts && ! OPT_liball ? printa("%-49s %@16d\n",@Counts) : 1; 219235368Sgnn 220235368Sgnn /* print elapsed times */ 221235368Sgnn OPT_elapsed ? printf("\n%-49s %16s\n","CALL","ELAPSED") : 1; 222235368Sgnn OPT_elapsed && OPT_liball ? printa("%-16s %-32s %@16d\n",@Elapsed) : 1; 223235368Sgnn OPT_elapsed && ! OPT_liball ? printa("%-49s %@16d\n",@Elapsed) : 1; 224235368Sgnn 225235368Sgnn /* print cpu times */ 226235368Sgnn OPT_cpu ? printf("\n%-49s %16s\n","CALL","CPU") : 1; 227235368Sgnn OPT_cpu && OPT_liball ? printa("%-16s %-32s %@16d\n",@CPU) : 1; 228235368Sgnn OPT_cpu && ! OPT_liball ? printa("%-49s %@16d\n",@CPU) : 1; 229235368Sgnn } 230235368Sgnn' 231235368Sgnn 232235368Sgnn### Run DTrace 233235368Sgnnif [ $opt_command -eq 1 ]; then 234235368Sgnn /usr/sbin/dtrace -x dynvarsize=$buf -x evaltime=exec -n "$dtrace" \ 235235368Sgnn -c "$command" >&2 236235368Sgnnelse 237235368Sgnn /usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" -p "$pid" >&2 238235368Sgnnfi 239235368Sgnn 240