#!/usr/bin/sh # # procsystime - print process system call time details. # Written using DTrace (Solaris 10 3/05). # # 22-Sep-2005, ver 1.10 # # USAGE: procsystime [-acehoT] [ -p PID | -n name | command ] # # -p PID # examine this PID # -n name # examine this process name # -a # print all details # -c # print syscall counts # -e # print elapsed times # -o # print CPU times # -T # print totals # eg, # procsystime -p 1871 # examine PID 1871 # procsystime -n tar # examine processes called "tar" # procsystime -aTn bash # print all details for bash shells # procsystime df -h # run and examine "df -h" # # The elapsed times are interesting, to help identify syscalls that take # some time to complete (during which the process may have slept). CPU time # helps us identify syscalls that are consuming CPU cycles to run. # # FIELDS: # SYSCALL System call name # TIME (ns) Total time, nanoseconds # COUNT Number of occurrences # # 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] # # 27-Apr-2005 Brendan Gregg Created this. # 08-Jun-2005 " " Added command option. # 22-Sep-2005 " " Allowed systemwide tracing. # ############################## # --- Process Arguments --- # ### Default variables opt_filter=0; opt_pid=0; opt_name=0; pid=0; pname="."; opt_elapsed=0; opt_cpu=0; opt_counts=0; opt_totals=0 opt_command=0; command=""; ### Process options while getopts acehn:op:T name do case $name in p) opt_filter=1; opt_pid=1; pid=$OPTARG ;; n) opt_filter=1; opt_name=1; pname=$OPTARG ;; a) opt_totals=1; opt_elapsed=1; opt_cpu=1; opt_counts=1 ;; e) opt_elapsed=1 ;; c) opt_counts=1 ;; o) opt_cpu=1 ;; T) opt_totals=1 ;; h|?) cat <<-END >&2 USAGE: procsystime [-aceho] [ -p PID | -n name | command ] -p PID # examine this PID -n name # examine this process name -a # print all details -e # print elapsed times -c # print syscall counts -o # print CPU times -T # print totals eg, procsystime -p 1871 # examine PID 1871 procsystime -n tar # examine processes called "tar" procsystime -aTn bash # print all details for bash procsystime df -h # run and examine "df -h" END exit 1 esac done shift `expr $OPTIND - 1` ### Option logic if [ $opt_pid -eq 0 -a $opt_name -eq 0 -a "$*" != "" ]; then opt_filter=1 opt_command=1 command="$*" fi if [ $opt_elapsed -eq 0 -a $opt_cpu -eq 0 -a $opt_counts -eq 0 ]; then opt_elapsed=1; fi ################################# # --- Main Program, DTrace --- # dtrace=' #pragma D option quiet /* * Command line arguments */ inline int OPT_elapsed = '$opt_elapsed'; inline int OPT_cpu = '$opt_cpu'; inline int OPT_counts = '$opt_counts'; inline int OPT_filter = '$opt_filter'; inline int OPT_pid = '$opt_pid'; inline int OPT_name = '$opt_name'; inline int OPT_totals = '$opt_totals'; inline int OPT_command = '$opt_command'; inline int PID = '$pid'; inline string NAME = "'$pname'"; inline string COMMAND = "'$command'"; dtrace:::BEGIN { self->start = 0; self->vstart = 0; } dtrace:::BEGIN /! OPT_command/ { printf("Hit Ctrl-C to stop sampling...\n"); } /* * Set start timestamp and counts */ syscall:::entry /(! OPT_filter) || (OPT_pid && pid == PID) || (OPT_name && execname == NAME) || (OPT_command && pid == $target)/ { self->ok = 1; } syscall:::entry /self->ok/ { OPT_counts ? @Counts[probefunc] = count() : 1; (OPT_counts && OPT_totals) ? @Counts["TOTAL:"] = count() : 1; OPT_elapsed ? self->start = timestamp : 1; OPT_cpu ? self->vstart = vtimestamp : 1; self->ok = 0; } /* * Calculate time deltas */ syscall:::return /self->start/ { this->elapsed = timestamp - self->start; @Elapsed[probefunc] = sum(this->elapsed); OPT_totals ? @Elapsed["TOTAL:"] = sum(this->elapsed) : 1; self->start = 0; } syscall:::return /self->vstart/ { this->cpu = vtimestamp - self->vstart; @CPU[probefunc] = sum(this->cpu); OPT_totals ? @CPU["TOTAL:"] = sum(this->cpu) : 1; self->vstart = 0; } /* * Elapsed time report */ dtrace:::END /OPT_elapsed/ { printf("\nElapsed Times for "); OPT_pid ? printf("PID %d,\n\n",PID) : 1; OPT_name ? printf("processes %s,\n\n",NAME) : 1; OPT_command ? printf("command %s,\n\n",COMMAND) : 1; (! OPT_filter) ? printf("all processes,\n\n") : 1; printf("%16s %18s\n","SYSCALL","TIME (ns)"); printa("%16s %@18d\n",@Elapsed); } /* * CPU time report */ dtrace:::END /OPT_cpu/ { printf("\nCPU Times for "); OPT_pid ? printf("PID %d,\n\n",PID) : 1; OPT_name ? printf("processes %s,\n\n",NAME) : 1; OPT_command ? printf("command %s,\n\n",COMMAND) : 1; (! OPT_filter) ? printf("all processes,\n\n") : 1; printf("%16s %18s\n","SYSCALL","TIME (ns)"); printa("%16s %@18d\n",@CPU); } /* * Syscall count report */ dtrace:::END /OPT_counts/ { printf("\nSyscall Counts for "); OPT_pid ? printf("PID %d,\n\n",PID) : 1; OPT_name ? printf("processes %s,\n\n",NAME) : 1; OPT_command ? printf("command %s,\n\n",COMMAND) : 1; (! OPT_filter) ? printf("all processes,\n\n") : 1; printf("%16s %18s\n","SYSCALL","COUNT"); OPT_counts ? printa("%16s %@18d\n",@Counts) : 1; } ' ### Run DTrace if [ $opt_command -eq 1 ]; then /usr/sbin/dtrace -n "$dtrace" -x evaltime=exec -c "$command" >&2 else /usr/sbin/dtrace -n "$dtrace" >&2 fi