1N/A# dappprof - profile user and library function usage. 1N/A# Written using DTrace (Solaris 10 3/05). 1N/A# The default output traces user functions as they are called. Options 1N/A# can be used to examine libraries and timestamps. 1N/A# $Id: dappprof 65 2007-10-04 11:09:40Z brendan $ 1N/A# USAGE: dappprof [-acehoTU] [-u lib] { -p PID | command } 1N/A# -p PID # examine this PID 1N/A# -a # print all details 1N/A# -c # print call counts 1N/A# -e # print elapsed times (us) 1N/A# -o # print on cpu times (us) 1N/A# -u lib # trace this library instead 1N/A# -U # trace all libraries + user functions 1N/A# -b bufsize # dynamic variable buf size (default is "4m") 1N/A# dappprof df -h # run and examine the "df -h" command 1N/A# dappprof -p 1871 # examine PID 1871 1N/A# The elapsed times are interesting, to help identify calls that take 1N/A# some time to complete (during which the process may have context 1N/A# switched off the CPU). 1N/A# SEE ALSO: dapptrace # DTraceToolkit 1N/A# dtruss # DTraceToolkit 1N/A# COPYRIGHT: Copyright (c) 2005 Brendan Gregg. 1N/A# The contents of this file are subject to the terms of the 1N/A# Common Development and Distribution License, Version 1.0 only 1N/A# (the "License"). You may not use this file except in compliance 1N/A# See the License for the specific language governing permissions 1N/A# and limitations under the License. 1N/A# Author: Brendan Gregg [Sydney, Australia] 1N/A# 16-May-2005 Brendan Gregg Created this. 1N/A# 17-Jul-2005 " " Last update. 1N/A############################## 1N/A# --- Process Arguments --- 1N/A### Default variables 1N/A USAGE: dappprof [-cehoTU] [-u lib] { -p PID | command } 1N/A -p PID # examine this PID 1N/A -a # print all details 1N/A -c # print syscall counts 1N/A -e # print elapsed times (us) 1N/A -o # print on cpu times 1N/A -u lib # trace this library instead 1N/A -U # trace all libraries + user funcs 1N/A -b bufsize # dynamic variable buf size 1N/A dappprof df -h # run and examine "df -h" 1N/A dappprof -p 1871 # examine PID 1871 1N/A dappprof -ap 1871 # print all data 1N/Ashift `expr $OPTIND - 1` 1N/Aif [ $opt_pid -eq 0 ]; then 1N/A if [ "$*" = "" ]; then 1N/Aif [ $opt_elapsed -eq 0 -a $opt_cpu -eq 0 -a $opt_counts -eq 0 ]; then 1N/Aif [ $opt_liball -eq 1 ]; then 1N/A probe_entry='pid$target:::entry' 1N/A probe_return='pid$target:::return' 1N/Aelif [ $opt_lib -eq 1 ]; then 1N/A probe_entry='pid$target:'$lib'::entry' 1N/A probe_return='pid$target:'$lib'::return' 1N/A probe_entry='pid$target:a.out::entry' 1N/A probe_return='pid$target:a.out::return' 1N/A################################# 1N/A# --- Main Program, DTrace --- 1N/A #pragma D option quiet 1N/A * Command line arguments 1N/A inline int OPT_command = '$opt_command'; 1N/A inline int OPT_liball = '$opt_liball'; 1N/A inline int OPT_elapsed = '$opt_elapsed'; 1N/A inline int OPT_cpu = '$opt_cpu'; 1N/A inline int OPT_counts = '$opt_counts'; 1N/A inline int OPT_totals = '$opt_totals'; 1N/A inline int OPT_pid = '$opt_pid'; 1N/A inline int PID = '$pid'; 1N/A inline string NAME = "'$pname'"; 1N/A printf("Tracing... Hit Ctrl-C to end...\n"); 1N/A * Save syscall entry info 1N/A /* set function depth */ 1N/A this->fdepth = ++fdepth[probefunc]; 1N/A /* set start details */ 1N/A self->start[probefunc,this->fdepth] = timestamp; 1N/A self->vstart[probefunc,this->fdepth] = vtimestamp; 1N/A /* count occurances */ 1N/A OPT_counts && OPT_liball ? @Counts[probemod,probefunc] = count() : 1; 1N/A OPT_counts && ! OPT_liball ? @Counts[probefunc] = count() : 1; 1N/A OPT_counts && OPT_totals && OPT_liball ? 1N/A @Counts["TOTAL:",""] = count() : 1; 1N/A OPT_counts && OPT_totals && ! OPT_liball ? 1N/A @Counts["TOTAL:"] = count() : 1; 1N/A /* print 3 arg output - default */ 1N/A /self->start[probefunc,fdepth[probefunc]]/ 1N/A /* fetch function depth */ 1N/A this->fdepth = fdepth[probefunc]; 1N/A /* calculate elapsed time */ 1N/A this->elapsed = timestamp - self->start[probefunc,this->fdepth]; 1N/A self->start[probefunc,this->fdepth] = 0; 1N/A this->cpu = vtimestamp - self->vstart[probefunc,this->fdepth]; 1N/A self->vstart[probefunc,this->fdepth] = 0; 1N/A /* save elapsed times */ 1N/A OPT_elapsed && OPT_liball ? 1N/A @Elapsed[probemod,probefunc] = sum(this->elapsed) : 1; 1N/A OPT_elapsed && ! OPT_liball ? 1N/A @Elapsed[probefunc] = sum(this->elapsed) : 1; 1N/A OPT_elapsed && OPT_totals && OPT_liball ? 1N/A @Elapsed["TOTAL:",""] = sum(this->elapsed) : 1; 1N/A OPT_elapsed && OPT_totals && ! OPT_liball ? 1N/A @Elapsed["TOTAL:"] = sum(this->elapsed) : 1; 1N/A /* save cpu times */ 1N/A OPT_cpu && OPT_liball ? @CPU[probemod,probefunc] = sum(this->cpu) : 1; 1N/A OPT_cpu && ! OPT_liball ? @CPU[probefunc] = sum(this->cpu) : 1; 1N/A OPT_cpu && OPT_totals && OPT_liball ? 1N/A @CPU["TOTAL:",""] = sum(this->cpu) : 1; 1N/A OPT_cpu && OPT_totals && ! OPT_liball ? 1N/A @CPU["TOTAL:"] = sum(this->cpu) : 1; 1N/A OPT_counts ? printf("\n%-49s %16s\n","CALL","COUNT") : 1; 1N/A OPT_counts && OPT_liball ? printa("%-16s %-32s %@16d\n",@Counts) : 1; 1N/A OPT_counts && ! OPT_liball ? printa("%-49s %@16d\n",@Counts) : 1; 1N/A /* print elapsed times */ 1N/A OPT_elapsed ? printf("\n%-49s %16s\n","CALL","ELAPSED") : 1; 1N/A OPT_elapsed && OPT_liball ? printa("%-16s %-32s %@16d\n",@Elapsed) : 1; 1N/A OPT_elapsed && ! OPT_liball ? printa("%-49s %@16d\n",@Elapsed) : 1; 1N/A /* print cpu times */ 1N/A OPT_cpu ? printf("\n%-49s %16s\n","CALL","CPU") : 1; 1N/A OPT_cpu && OPT_liball ? printa("%-16s %-32s %@16d\n",@CPU) : 1; 1N/A OPT_cpu && ! OPT_liball ? printa("%-49s %@16d\n",@CPU) : 1; 1N/Aif [ $opt_command -eq 1 ]; then 1N/A /usr/sbin/dtrace -x dynvarsize=$buf -x evaltime=exec -n "$dtrace" \ 1N/A /usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" -p "$pid" >&2