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