dapptrace   [plain text]

#!/bin/sh
# #!/usr/bin/sh
#
# dapptrace - trace user and library function usage.
#             Written using DTrace (Solaris 10 3/05).
#
# The default output traces user functions as they are called. Options
#  can be used to examine libraries and timestamps.
#
# 17-Jun-2005, ver 0.61         (early release! check for newer versions)
#
# USAGE: dapptrace [-acdeFlhoU] [-u lib] { -p PID | command }
#
#          -p PID          # examine this PID
#          -a              # print all details
#          -c              # print call counts
#          -d              # print relative timestamps (us)
#          -e              # print elapsed times (us)
#          -F              # print flow indentation
#          -l              # print pid/lwpid per line
#          -o              # print on cpu times (us)
#          -u lib          # trace this library instead
#          -U              # trace all libraries + user functions
#          -b bufsize      # dynamic variable buf size (default is "4m")
#  eg,
#       dapptrace df -h       # run and examine the "df -h" command
#       dapptrace -p 1871     # examine PID 1871
#       dapptrace -Fp 1871    # print using flow indents
#       dapptrace -eop 1871   # print elapsed and CPU times
#
# The elapsed times are interesting, to help identify calls that take
#  some time to complete (during which the process may have context
#  switched off the CPU). 
#
# SEE ALSO: dappprof       # DTraceToolkit
#           dtruss         # DTraceToolkit
#           apptrace
#
# COPYRIGHT: Copyright (c) 2005 Brendan Gregg.
#
# 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]
#
# 16-May-2005   Brendan Gregg   Created this.
#


##############################
# --- Process Arguments ---
#

### Default variables
opt_pid=0; pid=0; opt_indent=0; opt_lib=0; lib=""
opt_elapsed=0; opt_cpu=0; opt_counts=0; 
opt_relative=0; opt_printid=0; opt_liball=0
opt_command=0; command=""; opt_buf=0; buf="4m"

### Process options
while getopts ab:cdeFhlop:u:U name
do
        case $name in
        a)      opt_liball=1; opt_counts=1; opt_relative=1; opt_elapsed=1
		opt_indent=1; opt_printid=1; opt_cpu=1 ;; 
	b)	opt_buf=1; buf=$OPTARG ;;
        p)      opt_pid=1; pid=$OPTARG ;;
        u)      opt_lib=1; lib=$OPTARG ;;
        U)      opt_liball=1 ;; 
	c)	opt_counts=1 ;;
	d)	opt_relative=1 ;;
	e)	opt_elapsed=1 ;;
	F)	opt_indent=1 ;;
	l)	opt_printid=1 ;;
	o)	opt_cpu=1 ;;
        h|?)    cat <<-END >&2
		USAGE: dapptrace [-acdeholFLU] [-u lib] { -p PID | command }

		          -p PID          # examine this PID
		          -a              # print all details
		          -c              # print syscall counts
		          -d              # print relative times (us)
		          -e              # print elapsed times (us)
		          -F              # print flow indentation
		          -l              # print pid/lwpid
		          -o              # print CPU on cpu times
		          -u lib          # trace this library instead
		          -U              # trace all libraries + user funcs
		          -b bufsize      # dynamic variable buf size
		   eg,
		       dapptrace df -h       # run and examine "df -h"
		       dapptrace -p 1871     # examine PID 1871
		       dapptrace -Fp 1871    # print using flow indents
		       dapptrace -eop 1871   # print elapsed and CPU times
		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
	probe_entry='pid$target:::entry'
	probe_return='pid$target:::return'
elif [ $opt_lib -eq 1 ]; then
	probe_entry='pid$target:'$lib'::entry'
	probe_return='pid$target:'$lib'::return'
else
 	probe_entry='pid$target:a.out::entry'
 	probe_return='pid$target:a.out::return'
fi

#################################
# --- Main Program, DTrace ---
#

### Define D Script
dtrace='
 #pragma D option quiet

 /*
  * Command line arguments
  */
 inline int OPT_command   = '$opt_command';
 inline int OPT_liball    = '$opt_liball';
 inline int OPT_indent    = '$opt_indent';
 inline int OPT_printid   = '$opt_printid';
 inline int OPT_relative  = '$opt_relative';
 inline int OPT_elapsed   = '$opt_elapsed';
 inline int OPT_cpu       = '$opt_cpu';
 inline int OPT_counts    = '$opt_counts';
 inline int OPT_pid       = '$opt_pid';
 inline int PID           = '$pid';
 inline string NAME       = "'$pname'";

 dtrace:::BEGIN 
 {
	/* print header */
	/* SOLARIS: OPT_printid  ? printf("%-8s  ","PID/LWP") : 1; */
	OPT_printid  ? printf("%-8s  ","PID/THRD") : 1;
	OPT_relative ? printf("%8s ","RELATIVE") : 1;
	OPT_elapsed  ? printf("%7s ","ELAPSD") : 1;
	OPT_cpu      ? printf("%6s ","CPU") : 1;
	printf("CALL(args) \t\t = return\n");

	/* indent depth */
	depth = 0;
 }

 /*
  * Save syscall entry info
  */
 '$probe_entry'
 {
	/* set function depth */
	this->fdepth = ++fdepth[probefunc];
	depth += 2;

	/* set start details */
	self->start[probefunc,this->fdepth] = timestamp;
	self->vstart[probefunc,this->fdepth] = vtimestamp;

	/* count occurances */
	OPT_counts && OPT_liball ? @Counts[probemod,probefunc] = count() : 1;
	OPT_counts && ! OPT_liball ? @Counts[probefunc] = count() : 1;

	/* print optional fields */
	/* SOLARIS: OPT_printid  ? printf("%5d/%d:  ",pid,tid) : 1; */
	OPT_printid  ? printf("%5d/0x%x:  ",pid,tid) : 1;
	OPT_relative ? printf("%8d ",vtimestamp/1000) : 1;
	OPT_elapsed  ? printf("      . ") : 1;
	OPT_cpu      ? printf("     . ") : 1;
	OPT_indent   ? printf("%*s",depth,"") : 1;

	/* print main data */
	printf("-> ");
	OPT_liball ? printf("%s:",probemod) : 1;
	printf("%s(0x%X, 0x%X, 0x%X)\t\t\n",probefunc,arg0,arg1,arg2);

 }

 /*
  * Print return data
  */
 /* print 3 arg output - default */
 '$probe_return'
 /self->start[probefunc,fdepth[probefunc]]/
 {
	/* fetch function depth */
	this->fdepth = fdepth[probefunc];

	/* calculate elapsed time */
	this->elapsed = timestamp - self->start[probefunc,this->fdepth];
	self->start[probefunc,this->fdepth] = 0;
	this->cpu = vtimestamp - self->vstart[probefunc,this->fdepth];
	self->vstart[probefunc,this->fdepth] = 0;

	/* print optional fields */
	/* SOLARIS: OPT_printid  ? printf("%5d/%d:  ",pid,tid) : 1; */
	OPT_printid  ? printf("%5d/0x%x:  ",pid,tid) : 1;
	OPT_relative ? printf("%8d ",vtimestamp/1000) : 1;
	OPT_elapsed  ? printf("%7d ",this->elapsed/1000) : 1;
	OPT_cpu      ? printf("%6d ",this->cpu/1000) : 1;
	OPT_indent   ? printf("%*s",depth,"") : 1;

	/* print main data */
	printf("<- ");
	OPT_liball ? printf("%s:",probemod) : 1;
	printf("%s = %d\n",probefunc,(int)arg0);
	depth -= 2;
	fdepth[probefunc]--;
 }

 /* reset indent depth */
 /* SOLARIS: profile:::tick-1sec */
 profile:::tick-10Hz
 {
	/* 
	 * some probes generated by the pid provider have entries
 	 * but not returns. this is a klude to fix that problem. this
	 * also explains fdepth[probefunc] rather than a single depth.
	 */
	depth = 0;
 }

 /* print counts */
 dtrace:::END
 {
	OPT_counts ? printf("\n%-49s %16s\n","CALL","COUNT") : 1;
	OPT_counts && OPT_liball ? printa("%-16s %-32s %@16d\n",@Counts) : 1;
	OPT_counts && ! OPT_liball ? printa("%-49s %@16d\n",@Counts) : 1;
 }
'

### Run DTrace
if [ $opt_command -eq 1 ]; then
	/usr/sbin/dtrace -x dynvarsize=$buf -x evaltime=exec -n "$dtrace" \
	    -c "$command" >&2
else
	/usr/sbin/dtrace -x dynvarsize=$buf -n "$dtrace" -p "$pid" >&2
fi