digger.sh

Leave a comment Go to comments 
#!/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
  1. No comments yet.
  1. No trackbacks yet.

Leave a Reply

Fill in your details below or click an icon to log in:

Gravatar
WordPress.com Logo

You are commenting using your WordPress.com account. ( Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. ( Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. ( Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. ( Log Out /  Change )

w
Cancel

Connecting to %s

%d bloggers like this: