procsystime revision 235368
1235368Sgnn#!/usr/bin/sh 2235368Sgnn# 3235368Sgnn# procsystime - print process system call time details. 4235368Sgnn# Written using DTrace (Solaris 10 3/05). 5235368Sgnn# 6235368Sgnn# $Id: procsystime 4 2007-08-01 11:01:38Z brendan $ 7235368Sgnn# 8235368Sgnn# USAGE: procsystime [-acehoT] [ -p PID | -n name | command ] 9235368Sgnn# 10235368Sgnn# -p PID # examine this PID 11235368Sgnn# -n name # examine this process name 12235368Sgnn# -a # print all details 13235368Sgnn# -c # print syscall counts 14235368Sgnn# -e # print elapsed times 15235368Sgnn# -o # print CPU times 16235368Sgnn# -T # print totals 17235368Sgnn# eg, 18235368Sgnn# procsystime -p 1871 # examine PID 1871 19235368Sgnn# procsystime -n tar # examine processes called "tar" 20235368Sgnn# procsystime -aTn bash # print all details for bash shells 21235368Sgnn# procsystime df -h # run and examine "df -h" 22235368Sgnn# 23235368Sgnn# The elapsed times are interesting, to help identify syscalls that take 24235368Sgnn# some time to complete (during which the process may have slept). CPU time 25235368Sgnn# helps us identify syscalls that are consuming CPU cycles to run. 26235368Sgnn# 27235368Sgnn# FIELDS: 28235368Sgnn# SYSCALL System call name 29235368Sgnn# TIME (ns) Total time, nanoseconds 30235368Sgnn# COUNT Number of occurrences 31235368Sgnn# 32235368Sgnn# COPYRIGHT: Copyright (c) 2005 Brendan Gregg. 33235368Sgnn# 34235368Sgnn# CDDL HEADER START 35235368Sgnn# 36235368Sgnn# The contents of this file are subject to the terms of the 37235368Sgnn# Common Development and Distribution License, Version 1.0 only 38235368Sgnn# (the "License"). You may not use this file except in compliance 39235368Sgnn# with the License. 40235368Sgnn# 41235368Sgnn# You can obtain a copy of the license at Docs/cddl1.txt 42235368Sgnn# or http://www.opensolaris.org/os/licensing. 43235368Sgnn# See the License for the specific language governing permissions 44235368Sgnn# and limitations under the License. 45235368Sgnn# 46235368Sgnn# CDDL HEADER END 47235368Sgnn# 48235368Sgnn# Author: Brendan Gregg [Sydney, Australia] 49235368Sgnn# 50235368Sgnn# 27-Apr-2005 Brendan Gregg Created this. 51235368Sgnn# 08-Jun-2005 " " Added command option. 52235368Sgnn# 22-Sep-2005 " " Allowed systemwide tracing. 53235368Sgnn# 22-Sep-2005 " " Last update. 54235368Sgnn# 55235368Sgnn 56235368Sgnn 57235368Sgnn############################## 58235368Sgnn# --- Process Arguments --- 59235368Sgnn# 60235368Sgnn 61235368Sgnn### Default variables 62235368Sgnnopt_filter=0; opt_pid=0; opt_name=0; pid=0; pname="."; 63235368Sgnnopt_elapsed=0; opt_cpu=0; opt_counts=0; opt_totals=0 64235368Sgnnopt_command=0; command=""; 65235368Sgnn 66235368Sgnn### Process options 67235368Sgnnwhile getopts acehn:op:T name 68235368Sgnndo 69235368Sgnn case $name in 70235368Sgnn p) opt_filter=1; opt_pid=1; pid=$OPTARG ;; 71235368Sgnn n) opt_filter=1; opt_name=1; pname=$OPTARG ;; 72235368Sgnn a) opt_totals=1; opt_elapsed=1; opt_cpu=1; opt_counts=1 ;; 73235368Sgnn e) opt_elapsed=1 ;; 74235368Sgnn c) opt_counts=1 ;; 75235368Sgnn o) opt_cpu=1 ;; 76235368Sgnn T) opt_totals=1 ;; 77235368Sgnn h|?) cat <<-END >&2 78235368Sgnn USAGE: procsystime [-aceho] [ -p PID | -n name | command ] 79235368Sgnn -p PID # examine this PID 80235368Sgnn -n name # examine this process name 81235368Sgnn -a # print all details 82235368Sgnn -e # print elapsed times 83235368Sgnn -c # print syscall counts 84235368Sgnn -o # print CPU times 85235368Sgnn -T # print totals 86235368Sgnn eg, 87235368Sgnn procsystime -p 1871 # examine PID 1871 88235368Sgnn procsystime -n tar # examine processes called "tar" 89235368Sgnn procsystime -aTn bash # print all details for bash 90235368Sgnn procsystime df -h # run and examine "df -h" 91235368Sgnn END 92235368Sgnn exit 1 93235368Sgnn esac 94235368Sgnndone 95235368Sgnnshift `expr $OPTIND - 1` 96235368Sgnn 97235368Sgnn### Option logic 98235368Sgnnif [ $opt_pid -eq 0 -a $opt_name -eq 0 -a "$*" != "" ]; then 99235368Sgnn opt_filter=1 100235368Sgnn opt_command=1 101235368Sgnn command="$*" 102235368Sgnnfi 103235368Sgnnif [ $opt_elapsed -eq 0 -a $opt_cpu -eq 0 -a $opt_counts -eq 0 ]; then 104235368Sgnn opt_elapsed=1; 105235368Sgnnfi 106235368Sgnn 107235368Sgnn 108235368Sgnn################################# 109235368Sgnn# --- Main Program, DTrace --- 110235368Sgnn# 111235368Sgnndtrace=' 112235368Sgnn #pragma D option quiet 113235368Sgnn 114235368Sgnn /* 115235368Sgnn * Command line arguments 116235368Sgnn */ 117235368Sgnn inline int OPT_elapsed = '$opt_elapsed'; 118235368Sgnn inline int OPT_cpu = '$opt_cpu'; 119235368Sgnn inline int OPT_counts = '$opt_counts'; 120235368Sgnn inline int OPT_filter = '$opt_filter'; 121235368Sgnn inline int OPT_pid = '$opt_pid'; 122235368Sgnn inline int OPT_name = '$opt_name'; 123235368Sgnn inline int OPT_totals = '$opt_totals'; 124235368Sgnn inline int OPT_command = '$opt_command'; 125235368Sgnn inline int PID = '$pid'; 126235368Sgnn inline string NAME = "'$pname'"; 127235368Sgnn inline string COMMAND = "'$command'"; 128235368Sgnn 129235368Sgnn dtrace:::BEGIN 130235368Sgnn { 131235368Sgnn self->start = 0; 132235368Sgnn self->vstart = 0; 133235368Sgnn } 134235368Sgnn dtrace:::BEGIN 135235368Sgnn /! OPT_command/ 136235368Sgnn { 137235368Sgnn printf("Tracing... Hit Ctrl-C to end...\n"); 138235368Sgnn } 139235368Sgnn 140235368Sgnn /* 141235368Sgnn * Set start timestamp and counts 142235368Sgnn */ 143235368Sgnn syscall:::entry 144235368Sgnn /(! OPT_filter) || 145235368Sgnn (OPT_pid && pid == PID) || 146235368Sgnn (OPT_name && execname == NAME) || 147235368Sgnn (OPT_command && pid == $target)/ 148235368Sgnn { 149235368Sgnn self->ok = 1; 150235368Sgnn } 151235368Sgnn syscall:::entry 152235368Sgnn /self->ok/ 153235368Sgnn { 154235368Sgnn OPT_counts ? @Counts[probefunc] = count() : 1; 155235368Sgnn (OPT_counts && OPT_totals) ? @Counts["TOTAL:"] = count() : 1; 156235368Sgnn OPT_elapsed ? self->start = timestamp : 1; 157235368Sgnn OPT_cpu ? self->vstart = vtimestamp : 1; 158235368Sgnn self->ok = 0; 159235368Sgnn } 160235368Sgnn 161235368Sgnn /* 162235368Sgnn * Calculate time deltas 163235368Sgnn */ 164235368Sgnn syscall:::return 165235368Sgnn /self->start/ 166235368Sgnn { 167235368Sgnn this->elapsed = timestamp - self->start; 168235368Sgnn @Elapsed[probefunc] = sum(this->elapsed); 169235368Sgnn OPT_totals ? @Elapsed["TOTAL:"] = sum(this->elapsed) : 1; 170235368Sgnn self->start = 0; 171235368Sgnn } 172235368Sgnn syscall:::return 173235368Sgnn /self->vstart/ 174235368Sgnn { 175235368Sgnn this->cpu = vtimestamp - self->vstart; 176235368Sgnn @CPU[probefunc] = sum(this->cpu); 177235368Sgnn OPT_totals ? @CPU["TOTAL:"] = sum(this->cpu) : 1; 178235368Sgnn self->vstart = 0; 179235368Sgnn } 180235368Sgnn 181235368Sgnn /* 182235368Sgnn * Elapsed time report 183235368Sgnn */ 184235368Sgnn dtrace:::END 185235368Sgnn /OPT_elapsed/ 186235368Sgnn { 187235368Sgnn printf("\nElapsed Times for "); 188235368Sgnn OPT_pid ? printf("PID %d,\n\n",PID) : 1; 189235368Sgnn OPT_name ? printf("processes %s,\n\n",NAME) : 1; 190235368Sgnn OPT_command ? printf("command %s,\n\n",COMMAND) : 1; 191235368Sgnn (! OPT_filter) ? printf("all processes,\n\n") : 1; 192235368Sgnn printf("%16s %18s\n","SYSCALL","TIME (ns)"); 193235368Sgnn printa("%16s %@18d\n",@Elapsed); 194235368Sgnn } 195235368Sgnn 196235368Sgnn /* 197235368Sgnn * CPU time report 198235368Sgnn */ 199235368Sgnn dtrace:::END 200235368Sgnn /OPT_cpu/ 201235368Sgnn { 202235368Sgnn printf("\nCPU Times for "); 203235368Sgnn OPT_pid ? printf("PID %d,\n\n",PID) : 1; 204235368Sgnn OPT_name ? printf("processes %s,\n\n",NAME) : 1; 205235368Sgnn OPT_command ? printf("command %s,\n\n",COMMAND) : 1; 206235368Sgnn (! OPT_filter) ? printf("all processes,\n\n") : 1; 207235368Sgnn printf("%16s %18s\n","SYSCALL","TIME (ns)"); 208235368Sgnn printa("%16s %@18d\n",@CPU); 209235368Sgnn } 210235368Sgnn 211235368Sgnn /* 212235368Sgnn * Syscall count report 213235368Sgnn */ 214235368Sgnn dtrace:::END 215235368Sgnn /OPT_counts/ 216235368Sgnn { 217235368Sgnn printf("\nSyscall Counts for "); 218235368Sgnn OPT_pid ? printf("PID %d,\n\n",PID) : 1; 219235368Sgnn OPT_name ? printf("processes %s,\n\n",NAME) : 1; 220235368Sgnn OPT_command ? printf("command %s,\n\n",COMMAND) : 1; 221235368Sgnn (! OPT_filter) ? printf("all processes,\n\n") : 1; 222235368Sgnn printf("%16s %18s\n","SYSCALL","COUNT"); 223235368Sgnn OPT_counts ? printa("%16s %@18d\n",@Counts) : 1; 224235368Sgnn } 225235368Sgnn' 226235368Sgnn 227235368Sgnn### Run DTrace 228235368Sgnnif [ $opt_command -eq 1 ]; then 229235368Sgnn /usr/sbin/dtrace -n "$dtrace" -x evaltime=exec -c "$command" >&2 230235368Sgnnelse 231235368Sgnn /usr/sbin/dtrace -n "$dtrace" >&2 232235368Sgnnfi 233235368Sgnn 234