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