1251697Sgnn#!/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