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