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