xref: /freebsd-9.3-release/cddl/contrib/dtracetoolkit/Proc/pfilestat

#!/usr/bin/sh
#
# pfilestat
#
# This prints I/O statistics for each file descriptor within a process.
# In particular, the time break down during read() and write() events is
# measured.
#
# $Id: pfilestat 4 2007-08-01 11:01:38Z brendan $
#
# USAGE:        pfilestat [-r|-w] pid
#
# FIELDS:
#               STATE      microstate: running, sleeping, waitcpu, read, write
#               FDUM       File Descriptor ID
#               Time       Percentage of wallclock time in each STATE
#               File       Name of file, if known
# 
# COPYRIGHT: Copyright (c) 2006 Richard McDougall.
#
# 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
#
# ToDo:
#	Trace readv() and writev().
#
# 20-Feb-2006   Richard McDougall	created this.
# 24-Feb-2006   Brendan Gregg		tweaked code.
# 20-Mar-2006      "      " 		tweaked code.
# 20-Mar-2006      "      " 		last update.


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

### Default variables
opt_read=0; opt_write=0

### Process options
while getopts hrw name
do
	case $name in
	r)      opt_read=1 ;;
	w)      opt_write=1 ;;
	h|?)    cat <<-END >&2
		USAGE: pfilestat [-r|-w] pid
		              -r           # reads only
		              -w           # writes only
		  eg,
		       pfilestat pid       # default, r+w counts
		       pfilestat -r pid    # read count only
		END
		exit 1
	esac
done
shift `expr $OPTIND - 1`

PID=$1
clearstr=`clear`

if [ -z "$PID" ]
then
	echo "Must supply pid"
	exit 1
fi

### Option logic
if [ $opt_read -eq 0 -a $opt_write -eq 0 ]; then
	opt_read=1; opt_write=1
fi


#################################
# --- Main Program, DTrace ---
#
/usr/sbin/dtrace -n '
 #pragma D option quiet

 inline string CLEAR   = "'$clearstr'";
 inline int OPT_read   = '$opt_read';
 inline int OPT_write  = '$opt_write';
 inline int PID        = '$PID';

 unsigned long long totaltime;
 unsigned long long totalbytes;

 enum runstate {
	READ,
	WRITE,
	OTHER
 };

 /* print header */
 dtrace:::BEGIN
 {
	printf("Tracing ");
	OPT_read && OPT_write ? printf("reads and writes") : 1;
	OPT_read && ! OPT_write ? printf("reads") : 1;
	! OPT_read && OPT_write ? printf("writes") : 1;
	printf("...");
	totaltime = 0;
	totalbytes = 0;
	last = timestamp;
	stamp = timestamp;
 }

 /* sample reads */
 syscall::read:entry,
 syscall::pread*:entry
 /pid == PID && OPT_read/
 {
	runstate = READ;
	@logical["running", (uint64_t)0, ""] = sum(timestamp - last);
	totaltime += timestamp - last;
	last = timestamp;

	self->fd = arg0 + 1;
 }

 fbt::fop_read:entry,
 fbt::fop_write:entry
 /self->fd/
 {
	self->path = args[0]->v_path == 0 ? "<none>" : 
	    cleanpath(args[0]->v_path);
 }

 syscall::read:return,
 syscall::pread*:return
 /pid == PID && OPT_read/
 {
	runstate = OTHER;
	this->bytes = (int)arg0 > 0 ? (int)arg0 : 0;
	@logical["read", self->fd - 1, self->path] = sum(timestamp - last);
	@bytes["read", self->fd - 1, self->path] = sum(this->bytes);
	totalbytes += this->bytes;
	totaltime += timestamp - last;
	last = timestamp;
	self->path = 0;
	self->fd = 0;
 }


 /* sample writes */
 syscall::write:entry,
 syscall::pwrite*:entry
 /pid == PID && OPT_write/
 {
	runstate = WRITE;
	@logical["running", (uint64_t)0, ""] = sum(timestamp - last);
	totaltime += timestamp - last;
	last = timestamp;

	self->fd = (int)arg0 + 1;
 }

 syscall::write:return,
 syscall::pwrite*:return
 /pid == PID && OPT_write/
 {
	runstate = OTHER;
	this->bytes = (int)arg0 > 0 ? (int)arg0 : 0;
	@logical["write", self->fd - 1, self->path] = sum(timestamp - last);
	@bytes["write", self->fd - 1, self->path] = sum(this->bytes);
	totalbytes += this->bytes;
	totaltime += timestamp - last;
	last = timestamp;
	self->path = 0;
	self->fd = 0;
 }

 sched:::on-cpu
 /pid == PID/
 {
	@logical["waitcpu", (uint64_t)0, ""] = sum(timestamp - last);
	totaltime += timestamp - last;
	last = timestamp;
 }


 sched:::off-cpu
 /pid == PID/
 {
	@logical["running", (uint64_t)0, ""] = sum(timestamp - last);
	totaltime += timestamp - last;
	last = timestamp;
 }

 sched:::sleep
 /pid == PID/
 {
	@logical["running", (uint64_t)0, ""] = sum(timestamp - last);
	totaltime += timestamp - last;
	last = timestamp;
 }

 sched:::wakeup
 /args[1]->pr_pid == PID && runstate == OTHER/
 {
	@logical["sleep", (uint64_t)0, ""] = sum(timestamp - last);
	totaltime += timestamp - last;
	last = timestamp;
 }

 sched:::wakeup
 /args[1]->pr_pid == PID && runstate == READ/
 {
	@logical["sleep-r", (uint64_t)0, ""] = sum(timestamp - last);
	totaltime += timestamp - last;
	last = timestamp;
 }

 sched:::wakeup
 /args[1]->pr_pid == PID && runstate == WRITE/
 {
	@logical["sleep-w", (uint64_t)0, ""] = sum(timestamp - last);
	totaltime += timestamp - last;
	last = timestamp;
 }

 sched:::enqueue
 /args[1]->pr_pid == PID/
 {
	@logical["waitcpu", (uint64_t)0, ""] = sum(timestamp - last);
	totaltime += timestamp - last;
	last = timestamp;
 }

 sched:::dequeue
 /args[1]->pr_pid == PID/
 {
	@logical["waitcpu", (uint64_t)0, ""] = sum(timestamp - last);
	totaltime += timestamp - last;
	last = timestamp;
 }

 /* print report */
 profile:::tick-5s
 {
	printf("%s", CLEAR);
	normalize(@logical, totaltime / 100);
	trunc(@logical, 10);
	printf("%10s %7s %9s %-44s\n", "STATE", "FDNUM", "Time", "Filename");
	printa("%10s %7d %@8d%% %-44.44s\n", @logical);
	trunc(@logical);

	delta = timestamp - stamp;
	stamp = timestamp;
	normalize(@bytes, (1024 * delta) / 1000000000);
	trunc(@bytes, 10);
	printf("\n%10s %7s %9s %-44s\n", "STATE", "FDNUM", "KB/s",
	    "Filename");
	printa("%10s %7d %@9d %-44.44s\n", @bytes);
	trunc(@bytes);

	printf("\nTotal event time (ms): %d   Total Mbytes/sec: %d\n",
	    totaltime / 1000000,
	    (totalbytes * 1000000000) / (delta * 1048576));

	totaltime = 0;
	totalbytes = 0;
	last = timestamp;
 }

 dtrace:::END
 {
	trunc(@logical);
	trunc(@bytes);
 }
'