digger.sh
#!/usr/bin/sh
#
# digger - trace user and library functions, system calls,
# kernel calls, scheduler and I/O actions.
# Written using DTrace (Solaris 10 3/05).
#
# homepage: https://alexanderanokhin.com/tools/digger
#
# 17-Jun-2005, ver 0.61
# 24-Jul-2012, ver 2.00b
#
# USAGE: digger [-acdeFlhoUS] [-u lib] [-t functions] [-f functions] [-s functions] { -p PID | command }
#
# -p PID # examine this PID
# -a # print all details
# -c # print cpu ID
# -d # print relative timestamps (us)
# -e # print elapsed times (us)
# -F # print flow indentation
# -l # print pid/lwpid per line
# -m # print module name
# -o # print on cpu times (us)
# -u lib # trace this library instead
# -U # trace all libraries + user funcs
# -b bufsize # dynamic variable buf size
# -S # trace all syscalls
# -s function(s) # trace syscalls with filter
# -f function(s) # to trace calls inside some function (patterns * and ? are allowed)
# -g # print timestamps (us)
# -K # to trace kernel calls (fbt provider)
# -k function(s) # to trace kernel calls (fbt provider) using filter
# -z # print call stack
# -I # print fired probes of io provider
# -H # print fired probes of sched provider
# eg,
# digger -FSp 1871 -f qertbFetch -t kcb* # print calls of kcb* functions inside function qertbFetch using flow indents
#
# SEE ALSO: dappprof # DTraceToolkit
# dtruss # DTraceToolkit
# apptrace
#
# CDDL HEADER START
#
# The contents of this file are subject to the terms of the
# Common Development and Distribution License, Version 1.0 only
# (the "License"). You may not use this file except in compliance
# with the License.
#
# You can obtain a copy of the license at Docs/cddl1.txt
# or http://www.opensolaris.org/os/licensing.
# See the License for the specific language governing permissions
# and limitations under the License.
#
# CDDL HEADER END
#
# Author: Brendan Gregg [Sydney, Australia]
# Alexander Anokhin ( https://alexanderanokhin.wordpress.com )
#
# 16-May-2005 Brendan Gregg Created this.
# Jul-2012 Alexander Anokhin Created version 2
#
set -f
IFS=','
ftraced_footer='printf("\n***\n\n");'
##############################
# --- Process Arguments ---
#
### Default variables
opt_pid=0; pid=0; opt_indent=0; opt_lib=0; lib=""
opt_elapsed=0; opt_cpu=0; opt_cpuid=0; opt_tim=0;
opt_relative=0; opt_printid=0; opt_liball=0
opt_command=0; command=""; opt_buf=0; buf="4m";
opt_func_trc=0; func_traced_list="";
opt_calls_filter=0; calls_filter_list="";
opt_syscall=0; syscall_filter_list="";
opt_printmod=0; opt_debug=0; opt_ustack=0;
opt_fbt=0; fbt_filter_list="";
opt_sched=0; opt_io=0;
### Process options
while getopts ab:cdDef:FgHIKk:lmop:s:t:Su:Uz name
do
case $name in
a) opt_liball=1; opt_relative=1; opt_elapsed=1
opt_indent=1; opt_printid=1; opt_cpu=1 ; opt_printmod=1 ;;
b) opt_buf=1; buf=$OPTARG ;;
c) opt_cpuid=1 ;;
p) opt_pid=1; pid=$OPTARG ;;
u) opt_lib=1; lib=$OPTARG ;;
f) opt_func_trc=1; func_traced_list=$OPTARG ;;
t) opt_calls_filter=1; calls_filter_list=$OPTARG ;;
U) opt_liball=1 ;;
d) opt_relative=1 ;;
e) opt_elapsed=1 ;;
g) opt_tim=1 ;;
F) opt_indent=1 ;;
K) opt_fbt=1 ;;
k) opt_fbt=1 ; fbt_filter_list=$OPTARG ;;
l) opt_printid=1 ;;
D) opt_debug=1 ;;
m) opt_printmod=1 ;;
o) opt_cpu=1 ;;
S) opt_syscall=1 ;;
s) opt_syscall=1; syscall_filter_list=$OPTARG;;
z) opt_ustack=1;;
I) opt_io=1;;
H) opt_sched=1;;
h|?) cat <<-END >&2
USAGE: digger [-acdeholFLU] [-u lib] { -p PID | command }
-p PID # examine this PID
-a # print all details
-c # print cpu ID
-d # print relative timestamps (us)
-e # print elapsed times (us)
-F # print flow indentation
-l # print pid/lwpid per line
-m # print module name
-o # print on cpu times (us)
-u lib # trace this library instead
-U # trace all libraries + user funcs
-b bufsize # dynamic variable buf size
-S # trace all syscalls
-s function(s) # trace syscalls with filter
-f function(s) # to trace calls inside some function (patterns * and ? are allowed)
-g # print timestamps (us)
-K # to trace kernel calls (fbt provider)
-k function(s) # to trace kernel calls (fbt provider) using filter
-z # print call stack
-I # print fired probes of io provider
-H # print fired probes of sched provider
eg,
digger df -h # run and examine "df -h"
digger -p 1871 # examine PID 1871
digger -Fp 1871 # print using flow indents
digger -eop 1871 # print elapsed and CPU times
digger -FSp 1871 -f qertbFetch # print all application calls and system calls inside function qertbFetch using flow indents
digger -Fp 1871 -f qertbFetch -t kcb* -s *read*,*aio # print kcb* calls and *read*,*aio system calls
inside function qertbFetch using flow indents
END
exit 1
esac
done
shift `expr $OPTIND - 1`
### Option logic
if [ $opt_pid -eq 0 ]; then
opt_command=1
if [ "$*" = "" ]; then
$0 -h
exit
fi
command="$*"
fi
### Probe logic
if [ $opt_liball -eq 1 ]; then
traced_module='';
opt_printmod=1;
elif [ $opt_lib -eq 1 ]; then
traced_module=$lib;
else
traced_module='a.out';
fi
# calls filter
if [ $opt_calls_filter -eq 1 and "$calls_filter_list" ]; then
for calls_filter in $calls_filter_list
do
if [ "$calls_filter_probe_entry" ]; then
calls_filter_probe_entry=$calls_filter_probe_entry','
calls_filter_probe_return=$calls_filter_probe_return','
fi
case $calls_filter in
*:* ) mod_func=$calls_filter;; # if format contains ":", so <module:function>
*) mod_func=$traced_module':'$calls_filter;;
esac
calls_filter_probe_entry=$calls_filter_probe_entry'pid$target:'$mod_func':entry'
calls_filter_probe_return=$calls_filter_probe_return'pid$target:'$mod_func':return'
done
else
calls_filter_probe_entry=$calls_filter_probe_entry'pid$target:'$traced_module'::entry'
calls_filter_probe_return=$calls_filter_probe_return'pid$target:'$traced_module'::return'
fi
# syscalls
if [ $opt_syscall -eq 1 ]; then
if [ "$syscall_filter_list" ]; then
for syscall_filter in $syscall_filter_list
do
if [ "$syscall_probe_entry" ]; then
syscall_probe_entry=$syscall_probe_entry','
syscall_probe_return=$syscall_probe_return','
fi
syscall_probe_entry=$syscall_probe_entry'syscall::'$syscall_filter':entry'
syscall_probe_return=$syscall_probe_return'syscall::'$syscall_filter':return'
done
else
syscall_probe_entry=$syscall_probe_entry'syscall:::entry'
syscall_probe_return=$syscall_probe_return'syscall:::return'
fi
fi
# fbt
if [ $opt_fbt -eq 1 ]; then
if [ "$fbt_filter_list" ]; then
for fbt_filter in $fbt_filter_list
do
if [ "$fbt_probe_entry" ]; then
fbt_probe_entry=$fbt_probe_entry','
fbt_probe_return=$fbt_probe_return','
fi
case $calls_filter in
*:* ) mod_func=$fbt_filter;;
*) mod_func=':'$fbt_filter;;
esac
fbt_probe_entry=$fbt_probe_entry'fbt:'$mod_func':entry'
fbt_probe_return=$fbt_probe_return'fbt:'$mod_func':return'
done
else
fbt_probe_entry=$fbt_probe_entry'fbt:::entry'
fbt_probe_return=$fbt_probe_return'fbt:::return'
fi
fi
# to trace calls inside some function
if [ $opt_func_trc -eq 1 ]; then
for func_traced in $func_traced_list
do
if [ "$probe_entry_traced" ]; then
probe_entry_traced=$probe_entry_traced','
probe_return_traced=$probe_return_traced','
fi
case $func_traced in
*:* ) mod_func=$func_traced;; # if format contains ":", so <module:function>
*) mod_func=$traced_module':'$func_traced;;
esac
probe_entry_traced=$probe_entry_traced'pid$target:'$mod_func':entry'
probe_return_traced=$probe_return_traced'pid$target:'$mod_func':return'
done
calls_filter_probe_entry=$calls_filter_probe_entry'/self->ftraced != "" && self->ftraced != probefunc/'
calls_filter_probe_return=$calls_filter_probe_return'/self->ftraced != "" && self->ftraced != probefunc/'
probe_entry_traced=$probe_entry_traced'/self->ftraced == ""/'
probe_return_traced=$probe_return_traced'/self->ftraced == probefunc/'
if [ $opt_syscall -eq 1 ]; then
syscall_probe_entry=$syscall_probe_entry'/pid==pid_target && self->ftraced != ""/'
syscall_probe_return=$syscall_probe_return'/pid==pid_target && self->ftraced != ""/'
fi
if [ $opt_fbt -eq 1 ]; then
fbt_probe_entry=$fbt_probe_entry'/pid==pid_target && self->ftraced != ""/'
fbt_probe_return=$fbt_probe_return'/pid==pid_target && self->ftraced != ""/'
fi
else
if [ $opt_syscall -eq 1 ]; then
syscall_probe_entry=$syscall_probe_entry'/pid==pid_target/'
syscall_probe_return=$syscall_probe_return'/pid==pid_target/'
fi
if [ $opt_fbt -eq 1 ]; then
fbt_probe_entry=$fbt_probe_entry'/pid==pid_target/'
fbt_probe_return=$fbt_probe_return'/pid==pid_target/'
fi
fi
### Define D Script
header='
/* print header */
OPT_printid ? printf("%-8s ","pid/lwp") : 1;
OPT_cpuid ? printf("%4s ","CPU#") : 1;
OPT_tim ? printf("%9s ","timestamp") : 1;
OPT_relative ? printf("%8s ","relative") : 1;
OPT_elapsed ? printf("%7s ","elapsed") : 1;
OPT_cpu ? printf("%6s ","cpu") : 1;
OPT_printmod ? printf("%9s ","module") : 1;
printf("call(args) \t\t = return\n");
OPT_printid ? printf("-------- ") : 1;
OPT_cpuid ? printf("---- ") : 1;
OPT_tim ? printf("--------- ") : 1;
OPT_relative ? printf("-------- ") : 1;
OPT_elapsed ? printf("------- ") : 1;
OPT_cpu ? printf("------ ") : 1;
OPT_printmod ? printf("--------- ") : 1;
printf("---------------------------------\n");
'
if [ $opt_func_trc -eq 0 ]; then
main_header=$header
fi
dtrace='
#pragma D option quiet
#pragma D option switchrate=10Hz
/*
* Command line arguments
*/
inline int OPT_command = '$opt_command';
inline int OPT_liball = '$opt_liball';
inline int OPT_printmod = '$opt_printmod';
inline int OPT_indent = '$opt_indent';
inline int OPT_printid = '$opt_printid';
inline int OPT_cpuid = '$opt_cpuid';
inline int OPT_tim = '$opt_tim';
inline int OPT_relative = '$opt_relative';
inline int OPT_elapsed = '$opt_elapsed';
inline int OPT_cpu = '$opt_cpu';
inline int OPT_pid = '$opt_pid';
inline int pid_target = '$pid';
inline string NAME = "'$pname'";
dtrace:::BEGIN
{
printf("\nThe Digger is ready...\n\n");
'$main_header'
/* indent depth */
self->indent = 0;
self->ftraced = "";
self->start_timestamp = timestamp;
}
'
probe_entry_template='
/* set function depth */
this->fdepth = ++fdepth[probefunc];
self->indent += 2;
findent[probefunc,this->fdepth]=self->indent;
/* set start details */
self->start[probefunc,this->fdepth] = timestamp;
self->vstart[probefunc,this->fdepth] = vtimestamp;
/* print optional fields */
OPT_printid ? printf("%5d/%d: ",pid_target,tid) : 1;
OPT_cpuid ? printf("%4d ",cpu) : 1;
OPT_tim && self->start_timestamp == 0 ? self->start_timestamp = timestamp : 1;
OPT_tim ? printf("%9d ",(timestamp - self->start_timestamp)/1000) : 1;
OPT_relative ? printf("%8d ",vtimestamp/1000) : 1;
OPT_elapsed ? printf(" . ") : 1;
OPT_cpu ? printf(" . ") : 1;
OPT_printmod ? this->module = (probeprov == "syscall") ? "syscall" : probemod : 1;
OPT_printmod ? printf("%9s ",this->module) : 1;
OPT_indent ? printf("%*s",self->indent-2,"") : 1;
/* print main data */
this->ptr = (probeprov == "syscall") ? "=>" : "->";
printf("%s ", this->ptr);
printf("%s(0x%X, 0x%X, 0x%X)\t\t\n",probefunc,arg0,arg1,arg2);
'
probe_return_template='
/* fetch function indent */
this->fdepth = fdepth[probefunc];
/* calculate elapsed time */
this->elapsed = this->fdepth ? lltostr((timestamp - self->start[probefunc,this->fdepth])/1000) : "-";
this->cpu = this->fdepth ? lltostr((vtimestamp - self->vstart[probefunc,this->fdepth])/1000) : "-";
self->start[probefunc,this->fdepth] = 0;
self->vstart[probefunc,this->fdepth] = 0;
/* print optional fields */
OPT_printid ? printf("%5d/%d: ",pid_target,tid) : 1;
OPT_cpuid ? printf("%4d ",cpu) : 1;
OPT_tim && self->start_timestamp == 0 ? self->start_timestamp = timestamp : 1;
OPT_tim ? printf("%9d ",(timestamp-self->start_timestamp)/1000) : 1;
OPT_relative ? printf("%8d ",vtimestamp/1000) : 1;
OPT_elapsed ? printf("%7s ",this->elapsed) : 1;
OPT_cpu ? printf("%6s ",this->cpu) : 1;
OPT_printmod ? this->module = (probeprov == "syscall") ? "syscall" : probemod : 1;
OPT_printmod ? printf("%9s ",this->module) : 1;
self->indent = findent[probefunc,this->fdepth] ? findent[probefunc,this->fdepth] : 2;
OPT_indent ? printf("%*s",self->indent-2,"") : 1;
self->indent -= 2;
findent[probefunc,this->fdepth]=0;
/* print main data */
this->ptr = (probeprov == "syscall") ? "<=" : "<-";
printf("%s ", this->ptr);
printf("%s = 0x%X\n",probefunc,(int)arg1);
fdepth[probefunc] = this->fdepth ? fdepth[probefunc] - 1 : 0;
'
msg_template='
/* print optional fields */
OPT_printid ? printf("%5d/%d: ",pid_target,tid) : 1;
OPT_cpuid ? printf("%4d ",cpu) : 1;
OPT_tim && self->start_timestamp == 0 ? self->start_timestamp = timestamp : 1;
OPT_tim ? printf("%9d ",(timestamp-self->start_timestamp)/1000) : 1;
OPT_relative ? printf("%8d ",vtimestamp/1000) : 1;
OPT_elapsed ? printf(" . ") : 1;
OPT_cpu ? printf(" . ") : 1;
OPT_printmod ? printf("%9s",probemod) : 1;
OPT_indent ? printf("%*s",self->indent-2,"") : 1;
/* print main data */
printf(" - %s:%s:%s:%s",probeprov,probemod,probefunc,probename);
'
# add traced function probes, should be added before filters to support patterns like -f func*
if [ $opt_func_trc -eq 1 ]; then
dtrace=$dtrace$probe_entry_traced'{'
if [ $opt_ustack -eq 1 ]; then
dtrace=$dtrace'printf("call stack:"); ustack(); printf("\n");'
fi
dtrace=$dtrace$header'
self->ftraced=probefunc;
'$probe_entry_template'}
'$probe_return_traced'
{self->ftraced="";
'$probe_return_template'
self->ftraced="";
'$ftraced_footer'
}'
fi
# add call filters probes
dtrace=$dtrace'
/*
* Save call entry info
*/
'$calls_filter_probe_entry'
{'$probe_entry_template'}
/*
* Print return data
*/
/* print 3 arg output - default */
'$calls_filter_probe_return'
{'$probe_return_template'}
'
# add syscalls probes
if [ $opt_syscall -eq 1 ]; then
dtrace=$dtrace$syscall_probe_entry'
{'$probe_entry_template'}
'$syscall_probe_return'
{'$probe_return_template'}'
fi
# add fbt probes
if [ $opt_fbt -eq 1 ]; then
dtrace=$dtrace$fbt_probe_entry'
{'$probe_entry_template'}
'$fbt_probe_return'
{'$probe_return_template'}'
fi
# add sched probes
if [ $opt_sched -eq 1 ]; then
dtrace=$dtrace'
sched:::change-pri
/pid==pid_target && self->ftraced != ""/
{
'$msg_template'
this->pr_clname = stringof(args[0]->pr_clname);
this->pr_sname = args[0]->pr_sname;
this->pr_pri = args[0]->pr_pri;
this->new_pri = args[2];
printf(" [pr_clname=%s, pr_sname=%c, pr_pri=%d, new_pri=%d]\n", this->pr_clname, this->pr_sname, this->pr_pri, this->new_pri);
}'
dtrace=$dtrace'
sched:::dequeue,
sched:::enqueue
/pid==pid_target && self->ftraced != ""/
{
'$msg_template'
this->pr_clname = stringof(args[0]->pr_clname);
this->pr_sname = args[0]->pr_sname;
this->cpu_id = args[2]->cpu_id;
printf(" [pr_clname=%s, pr_sname=%c, cpu_id=%d]\n", this->pr_clname, this->pr_sname, this->cpu_id);
}'
dtrace=$dtrace'
sched:::cpucaps-sleep,
sched:::cpucaps-wakeup,
sched:::schedctl-nopreempt,
sched:::schedctl-preempt,
sched:::surrender,
sched:::tick,
sched:::wakeup
/pid==pid_target && self->ftraced != ""/
{
'$msg_template'
this->pr_clname = stringof(args[0]->pr_clname);
this->pr_sname = args[0]->pr_sname;
printf(" [pr_clname=%s, pr_sname=%c]\n", this->pr_clname, this->pr_sname);
}'
dtrace=$dtrace'
sched:::off-cpu
/pid==pid_target && self->ftraced != ""/
{
'$msg_template'
this->pr_clname = stringof(args[0]->pr_clname);
this->pr_sname = args[0]->pr_sname;
printf(" [cpu_id=%d, pr_clname=%s, pr_sname=%c]\n", curcpu->cpu_id, this->pr_clname, this->pr_sname);
}'
dtrace=$dtrace'
sched:::preempt,
sched:::schedctl-yield,
sched:::sleep
/pid==pid_target && self->ftraced != ""/
{
'$msg_template'
printf("\n");
}'
dtrace=$dtrace'
sched:::remain-cpu,
sched:::on-cpu
/pid==pid_target && self->ftraced != ""/
{
'$msg_template'
printf(" [cpu_id=%d]\n", curcpu->cpu_id);
}'
fi
# add IO probes
if [ $opt_io -eq 1 ]; then
dtrace=$dtrace'
io:::start,
io:::done,
io:::wait-start,
io:::wait-done
/pid==pid_target && self->ftraced != ""/
{
'$msg_template'
printf(" [d=%s f=%s b=%d]\n", args[1]->dev_statname, args[2]->fi_pathname, args[0]->b_bcount);
}'
fi
# debug option
if [ $opt_debug -eq 1 ]; then
echo $dtrace > digger.dbg
exit
fi
### Run DTrace
if [ $opt_command -eq 1 ]; then
/usr/sbin/dtrace -x dynvarsize=$buf -x evaltime=exec -n "$dtrace" \
-c "$command"
else
/usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" -p "$pid"
fi
Comments (0)
Trackbacks (0)
Leave a comment
Trackback
Alexander Anokhin 