pfilestat revision 235368
1235368Sgnn#!/usr/bin/sh 2235368Sgnn# 3235368Sgnn# pfilestat 4235368Sgnn# 5235368Sgnn# This prints I/O statistics for each file descriptor within a process. 6235368Sgnn# In particular, the time break down during read() and write() events is 7235368Sgnn# measured. 8235368Sgnn# 9235368Sgnn# $Id: pfilestat 4 2007-08-01 11:01:38Z brendan $ 10235368Sgnn# 11235368Sgnn# USAGE: pfilestat [-r|-w] pid 12235368Sgnn# 13235368Sgnn# FIELDS: 14235368Sgnn# STATE microstate: running, sleeping, waitcpu, read, write 15235368Sgnn# FDUM File Descriptor ID 16235368Sgnn# Time Percentage of wallclock time in each STATE 17235368Sgnn# File Name of file, if known 18235368Sgnn# 19235368Sgnn# COPYRIGHT: Copyright (c) 2006 Richard McDougall. 20235368Sgnn# 21235368Sgnn# CDDL HEADER START 22235368Sgnn# 23235368Sgnn# The contents of this file are subject to the terms of the 24235368Sgnn# Common Development and Distribution License, Version 1.0 only 25235368Sgnn# (the "License"). You may not use this file except in compliance 26235368Sgnn# with the License. 27235368Sgnn# 28235368Sgnn# You can obtain a copy of the license at Docs/cddl1.txt 29235368Sgnn# or http://www.opensolaris.org/os/licensing. 30235368Sgnn# See the License for the specific language governing permissions 31235368Sgnn# and limitations under the License. 32235368Sgnn# 33235368Sgnn# CDDL HEADER END 34235368Sgnn# 35235368Sgnn# ToDo: 36235368Sgnn# Trace readv() and writev(). 37235368Sgnn# 38235368Sgnn# 20-Feb-2006 Richard McDougall created this. 39235368Sgnn# 24-Feb-2006 Brendan Gregg tweaked code. 40235368Sgnn# 20-Mar-2006 " " tweaked code. 41235368Sgnn# 20-Mar-2006 " " last update. 42235368Sgnn 43235368Sgnn 44235368Sgnn############################## 45235368Sgnn# --- Process Arguments --- 46235368Sgnn# 47235368Sgnn 48235368Sgnn### Default variables 49235368Sgnnopt_read=0; opt_write=0 50235368Sgnn 51235368Sgnn### Process options 52235368Sgnnwhile getopts hrw name 53235368Sgnndo 54235368Sgnn case $name in 55235368Sgnn r) opt_read=1 ;; 56235368Sgnn w) opt_write=1 ;; 57235368Sgnn h|?) cat <<-END >&2 58235368Sgnn USAGE: pfilestat [-r|-w] pid 59235368Sgnn -r # reads only 60235368Sgnn -w # writes only 61235368Sgnn eg, 62235368Sgnn pfilestat pid # default, r+w counts 63235368Sgnn pfilestat -r pid # read count only 64235368Sgnn END 65235368Sgnn exit 1 66235368Sgnn esac 67235368Sgnndone 68235368Sgnnshift `expr $OPTIND - 1` 69235368Sgnn 70235368SgnnPID=$1 71235368Sgnnclearstr=`clear` 72235368Sgnn 73235368Sgnnif [ -z "$PID" ] 74235368Sgnnthen 75235368Sgnn echo "Must supply pid" 76235368Sgnn exit 1 77235368Sgnnfi 78235368Sgnn 79235368Sgnn### Option logic 80235368Sgnnif [ $opt_read -eq 0 -a $opt_write -eq 0 ]; then 81235368Sgnn opt_read=1; opt_write=1 82235368Sgnnfi 83235368Sgnn 84235368Sgnn 85235368Sgnn################################# 86235368Sgnn# --- Main Program, DTrace --- 87235368Sgnn# 88235368Sgnn/usr/sbin/dtrace -n ' 89235368Sgnn #pragma D option quiet 90235368Sgnn 91235368Sgnn inline string CLEAR = "'$clearstr'"; 92235368Sgnn inline int OPT_read = '$opt_read'; 93235368Sgnn inline int OPT_write = '$opt_write'; 94235368Sgnn inline int PID = '$PID'; 95235368Sgnn 96235368Sgnn unsigned long long totaltime; 97235368Sgnn unsigned long long totalbytes; 98235368Sgnn 99235368Sgnn enum runstate { 100235368Sgnn READ, 101235368Sgnn WRITE, 102235368Sgnn OTHER 103235368Sgnn }; 104235368Sgnn 105235368Sgnn /* print header */ 106235368Sgnn dtrace:::BEGIN 107235368Sgnn { 108235368Sgnn printf("Tracing "); 109235368Sgnn OPT_read && OPT_write ? printf("reads and writes") : 1; 110235368Sgnn OPT_read && ! OPT_write ? printf("reads") : 1; 111235368Sgnn ! OPT_read && OPT_write ? printf("writes") : 1; 112235368Sgnn printf("..."); 113235368Sgnn totaltime = 0; 114235368Sgnn totalbytes = 0; 115235368Sgnn last = timestamp; 116235368Sgnn stamp = timestamp; 117235368Sgnn } 118235368Sgnn 119235368Sgnn /* sample reads */ 120235368Sgnn syscall::read:entry, 121235368Sgnn syscall::pread*:entry 122235368Sgnn /pid == PID && OPT_read/ 123235368Sgnn { 124235368Sgnn runstate = READ; 125235368Sgnn @logical["running", (uint64_t)0, ""] = sum(timestamp - last); 126235368Sgnn totaltime += timestamp - last; 127235368Sgnn last = timestamp; 128235368Sgnn 129235368Sgnn self->fd = arg0 + 1; 130235368Sgnn } 131235368Sgnn 132235368Sgnn fbt::fop_read:entry, 133235368Sgnn fbt::fop_write:entry 134235368Sgnn /self->fd/ 135235368Sgnn { 136235368Sgnn self->path = args[0]->v_path == 0 ? "<none>" : 137235368Sgnn cleanpath(args[0]->v_path); 138235368Sgnn } 139235368Sgnn 140235368Sgnn syscall::read:return, 141235368Sgnn syscall::pread*:return 142235368Sgnn /pid == PID && OPT_read/ 143235368Sgnn { 144235368Sgnn runstate = OTHER; 145235368Sgnn this->bytes = (int)arg0 > 0 ? (int)arg0 : 0; 146235368Sgnn @logical["read", self->fd - 1, self->path] = sum(timestamp - last); 147235368Sgnn @bytes["read", self->fd - 1, self->path] = sum(this->bytes); 148235368Sgnn totalbytes += this->bytes; 149235368Sgnn totaltime += timestamp - last; 150235368Sgnn last = timestamp; 151235368Sgnn self->path = 0; 152235368Sgnn self->fd = 0; 153235368Sgnn } 154235368Sgnn 155235368Sgnn 156235368Sgnn /* sample writes */ 157235368Sgnn syscall::write:entry, 158235368Sgnn syscall::pwrite*:entry 159235368Sgnn /pid == PID && OPT_write/ 160235368Sgnn { 161235368Sgnn runstate = WRITE; 162235368Sgnn @logical["running", (uint64_t)0, ""] = sum(timestamp - last); 163235368Sgnn totaltime += timestamp - last; 164235368Sgnn last = timestamp; 165235368Sgnn 166235368Sgnn self->fd = (int)arg0 + 1; 167235368Sgnn } 168235368Sgnn 169235368Sgnn syscall::write:return, 170235368Sgnn syscall::pwrite*:return 171235368Sgnn /pid == PID && OPT_write/ 172235368Sgnn { 173235368Sgnn runstate = OTHER; 174235368Sgnn this->bytes = (int)arg0 > 0 ? (int)arg0 : 0; 175235368Sgnn @logical["write", self->fd - 1, self->path] = sum(timestamp - last); 176235368Sgnn @bytes["write", self->fd - 1, self->path] = sum(this->bytes); 177235368Sgnn totalbytes += this->bytes; 178235368Sgnn totaltime += timestamp - last; 179235368Sgnn last = timestamp; 180235368Sgnn self->path = 0; 181235368Sgnn self->fd = 0; 182235368Sgnn } 183235368Sgnn 184235368Sgnn sched:::on-cpu 185235368Sgnn /pid == PID/ 186235368Sgnn { 187235368Sgnn @logical["waitcpu", (uint64_t)0, ""] = sum(timestamp - last); 188235368Sgnn totaltime += timestamp - last; 189235368Sgnn last = timestamp; 190235368Sgnn } 191235368Sgnn 192235368Sgnn 193235368Sgnn sched:::off-cpu 194235368Sgnn /pid == PID/ 195235368Sgnn { 196235368Sgnn @logical["running", (uint64_t)0, ""] = sum(timestamp - last); 197235368Sgnn totaltime += timestamp - last; 198235368Sgnn last = timestamp; 199235368Sgnn } 200235368Sgnn 201235368Sgnn sched:::sleep 202235368Sgnn /pid == PID/ 203235368Sgnn { 204235368Sgnn @logical["running", (uint64_t)0, ""] = sum(timestamp - last); 205235368Sgnn totaltime += timestamp - last; 206235368Sgnn last = timestamp; 207235368Sgnn } 208235368Sgnn 209235368Sgnn sched:::wakeup 210235368Sgnn /args[1]->pr_pid == PID && runstate == OTHER/ 211235368Sgnn { 212235368Sgnn @logical["sleep", (uint64_t)0, ""] = sum(timestamp - last); 213235368Sgnn totaltime += timestamp - last; 214235368Sgnn last = timestamp; 215235368Sgnn } 216235368Sgnn 217235368Sgnn sched:::wakeup 218235368Sgnn /args[1]->pr_pid == PID && runstate == READ/ 219235368Sgnn { 220235368Sgnn @logical["sleep-r", (uint64_t)0, ""] = sum(timestamp - last); 221235368Sgnn totaltime += timestamp - last; 222235368Sgnn last = timestamp; 223235368Sgnn } 224235368Sgnn 225235368Sgnn sched:::wakeup 226235368Sgnn /args[1]->pr_pid == PID && runstate == WRITE/ 227235368Sgnn { 228235368Sgnn @logical["sleep-w", (uint64_t)0, ""] = sum(timestamp - last); 229235368Sgnn totaltime += timestamp - last; 230235368Sgnn last = timestamp; 231235368Sgnn } 232235368Sgnn 233235368Sgnn sched:::enqueue 234235368Sgnn /args[1]->pr_pid == PID/ 235235368Sgnn { 236235368Sgnn @logical["waitcpu", (uint64_t)0, ""] = sum(timestamp - last); 237235368Sgnn totaltime += timestamp - last; 238235368Sgnn last = timestamp; 239235368Sgnn } 240235368Sgnn 241235368Sgnn sched:::dequeue 242235368Sgnn /args[1]->pr_pid == PID/ 243235368Sgnn { 244235368Sgnn @logical["waitcpu", (uint64_t)0, ""] = sum(timestamp - last); 245235368Sgnn totaltime += timestamp - last; 246235368Sgnn last = timestamp; 247235368Sgnn } 248235368Sgnn 249235368Sgnn /* print report */ 250235368Sgnn profile:::tick-5s 251235368Sgnn { 252235368Sgnn printf("%s", CLEAR); 253235368Sgnn normalize(@logical, totaltime / 100); 254235368Sgnn trunc(@logical, 10); 255235368Sgnn printf("%10s %7s %9s %-44s\n", "STATE", "FDNUM", "Time", "Filename"); 256235368Sgnn printa("%10s %7d %@8d%% %-44.44s\n", @logical); 257235368Sgnn trunc(@logical); 258235368Sgnn 259235368Sgnn delta = timestamp - stamp; 260235368Sgnn stamp = timestamp; 261235368Sgnn normalize(@bytes, (1024 * delta) / 1000000000); 262235368Sgnn trunc(@bytes, 10); 263235368Sgnn printf("\n%10s %7s %9s %-44s\n", "STATE", "FDNUM", "KB/s", 264235368Sgnn "Filename"); 265235368Sgnn printa("%10s %7d %@9d %-44.44s\n", @bytes); 266235368Sgnn trunc(@bytes); 267235368Sgnn 268235368Sgnn printf("\nTotal event time (ms): %d Total Mbytes/sec: %d\n", 269235368Sgnn totaltime / 1000000, 270235368Sgnn (totalbytes * 1000000000) / (delta * 1048576)); 271235368Sgnn 272235368Sgnn totaltime = 0; 273235368Sgnn totalbytes = 0; 274235368Sgnn last = timestamp; 275235368Sgnn } 276235368Sgnn 277235368Sgnn dtrace:::END 278235368Sgnn { 279235368Sgnn trunc(@logical); 280235368Sgnn trunc(@bytes); 281235368Sgnn } 282235368Sgnn' 283