#!/usr/bin/ksh # Version : 0.9.4 # Author : Arnaud Lacour - Directory Server Engineering # Sun Microsystems, Inc # # Copyright 2008 Sun Microsystems, Inc. All rights reserved # Use is subject to license terms. # # 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 # # # Exit codes : # 0 - success # 1 - invalid usage # 10 - invalid argument for PID # 11 - invalid argument for period duration # 12 - invalid argument for number of iterations # 13 - no PID provided and could not find a running ns-slapd process # # Known Issues : # - percentages are rounded and therefore might not add up to 100 (almost never do actually) # - rates are all integer and it would be nice to have decimals # - %I/O time can be greater than 100 if disk accesses are concurrent (FIXME) # # To Do : # - loop indefinitely if no argument provided for number of iteration instead of 1 loop # - fix %I/O computation bug # - implement csv output # ### default variables version=0.9.4 # default pid pid=0; # Display LDAP detailed statistics print_ldap=0; # Display I/O read information print_read=0; # Display I/O write information print_write=0; # Output CSV format instead of human readable format csv=0; # default tracing interval period=10; # default number of iterations iterations=1; # function to determine if an argument is numeric isNum() { if test -z "`echo $1|tr -d [0-9]`" ; then return 0; else return 1; fi } ### process options while getopts clP:rvw argument do case $argument in c) csv=1 ;; l) print_ldap=1 ;; r) print_read=1 ;; w) print_write=1 ;; P) if isNum $OPTARG ; then pid=$OPTARG ; else echo "Argument [$OPTARG] for process ID to trace must be a number"; exit 10; fi ;; v) cat <<-END `basename $0` - version $version Directory Server I/O monitoring tool Copyright 2008 Sun Microsystems, Inc. All rights reserved Use is subject to license terms. END exit 0; ;; *) cat <<-END >&2 USAGE: dsio [-l|-r|-w|-v] [-P pid] [interval [count]] interval: Display interval in sec (def:10) count : Number of iterations (def: 1) -l : Print LDAP detailed statistics -w : Print I/O write detailed statistics -r : Print I/O read detailed statistics -P pid : Trace process by pid number -v : Print the version eg, dsio # default output, one 10 second sample dsio 1 # print one 1 second sample dsio 10 6 # print six 10 second samples dsio -lrw 60 # print the 60 seconds of detailed statistics dsio -P 123 # print default output for process 123 END exit 1; ;; esac done shift $(( $OPTIND - 1 )) if test -n "$1" ; then if isNum $1 ; then period=$1; else echo "Argument [$1] for period duration in seconds must be a number"; exit 11; fi fi if test -n "$2" ; then if isNum $2 ; then iterations=$2; else echo "Argument [$1] for number of iterations must be a number"; exit 12; fi fi if test ${pid}==0 ; then pid=`ps -ef | grep ns-slapd|grep -v grep|awk '{print $2}'|head -1`; if test -z "${pid}" || ! isNum ${pid} ; then echo "Could not find a running ns-slapd process"; exit 13; fi fi /usr/sbin/dtrace -n ' #pragma D option quiet /* Arnaud Lacour - Directory Server Engineering * Sun Microsystems, Inc * * Copyright 2008 Sun Microsystems, Inc. All rights reserved * Use is subject to license terms. * * 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 * * * * Variable naming conventions: * srch = ldap search * mod = ldap modify * add = ldap add * del = ldap delete * ldap = ldap related statistics * io = I/O related statistics * size = I/O operation size related statistics * time = operation time related statistics (either LDAP or I/O) * avg = average * max = maximum * sum = sum (total) * w = I/O write related statistics * r = I/O read related statistics * */ /* declaring this variable this way is required to enable conditional report printing later on */ inline int print_read='${print_read}'; inline int print_write='${print_write}'; inline int print_ldap='${print_ldap}'; dtrace:::BEGIN { print_csv='${csv}'; period='${period}'; maxcount='${iterations}'; seconds=0; prints=0; clearstr="\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n"; printf("%s", clearstr); printf("Acquiring data from Process %d, please wait %d seconds...",$1, period); @all_ldap_avg=avg(0); @all_ldap_max=max(0); @all_io_size_avg_r=avg(0); @all_io_size_avg_w=avg(0); @all_io_size_max_r=max(0); @all_io_size_max_w=max(0); @all_io_time_avg_r=avg(0); @all_io_time_avg_w=avg(0); @all_io_time_max_r=max(0); @all_io_time_max_w=max(0); @all_io_size_avg=avg(0); @all_io_size_max=max(0); @all_io_time_avg=avg(0); @all_io_time_max=max(0); /* Initialize the search counters * I chose not to use count aggregations here * because I have not found a way yet * to initialize a count aggregation to 0 */ /* counter storing the number of ldap search operations */ srch_ldap_cnt=0; /* counter storing the maximum time spent in the search function in the code */ @srch_ldap_max=max(0); /* counter storing the average time spent in the search function in the code */ @srch_ldap_avg=avg(0); /* counter storing the total time spent in the search function in the code * this is later used to calculate the %I/O for read and write I/Os */ srch_ldap_time=0; /* counter storing the number of read I/O operations */ srch_io_cnt_r=0; /* counter storing the number of asynchronous read I/O operations */ srch_io_cnt_r_async=0; /* counter storing the number of synchronous read I/O operations */ srch_io_cnt_r_sync=0; /* counter storing the number of write I/O operations */ srch_io_cnt_w=0; /* counter storing the number of asynchronous write I/O operations */ srch_io_cnt_w_async=0; /* counter storing the number of synchronous write I/O operations */ srch_io_cnt_w_sync=0; /* counter storing the maximum amount of time spent in I/O for an LDAP search operation */ @srch_io_time_max=max(0); @srch_io_time_avg=avg(0); @srch_io_size_max=max(0); @srch_io_size_avg=avg(0); /* counter storing the maximum time for read I/O operation */ @srch_io_time_max_r=max(0); /* counter storing the maximum time for write I/O operation */ @srch_io_time_max_w=max(0); /* counter storing the average time for read I/O operation */ @srch_io_time_avg_r=avg(0); /* counter storing the average time for write I/O operation */ @srch_io_time_avg_w=avg(0); /* counter storing the total time spent in I/O reads for LDAP search operations */ srch_io_time_sum_r=0; /* counter storing the total time spent in I/O writes for LDAP search operations */ srch_io_time_sum_w=0; @srch_io_size_max_r=max(0); @srch_io_size_max_w=max(0); @srch_io_size_avg_r=avg(0); @srch_io_size_avg_w=avg(0); srch_io_size_sum_r=0; srch_io_size_sum_w=0; /* MODIFY variables initialization */ mod_ldap_cnt=0; @mod_ldap_max=max(0); @mod_ldap_avg=avg(0); mod_ldap_time=0; mod_io_cnt_r=0; mod_io_cnt_r_async=0; mod_io_cnt_r_sync=0; mod_io_cnt_w=0; mod_io_cnt_w_async=0; mod_io_cnt_w_sync=0; /* counter storing the maximum amount of time spent in I/O for an LDAP modify operation */ @mod_io_time_max=max(0); @mod_io_time_avg=avg(0); @mod_io_size_max=max(0); @mod_io_size_avg=avg(0); @mod_io_time_max_r=max(0); @mod_io_time_max_w=max(0); @mod_io_time_avg_r=avg(0); @mod_io_time_avg_w=avg(0); mod_io_time_sum_r=0; mod_io_time_sum_w=0; @mod_io_size_max_r=max(0); @mod_io_size_max_w=max(0); @mod_io_size_avg_r=avg(0); @mod_io_size_avg_w=avg(0); mod_io_size_sum_r=0; mod_io_size_sum_w=0; /* ADD variables initialization */ add_ldap_cnt=0; @add_ldap_max=max(0); @add_ldap_avg=avg(0); add_ldap_time=0; add_io_cnt_r=0; add_io_cnt_r_async=0; add_io_cnt_r_sync=0; add_io_cnt_w=0; add_io_cnt_w_async=0; add_io_cnt_w_sync=0; @add_io_time_max_r=max(0); @add_io_time_max_w=max(0); @add_io_time_avg_r=avg(0); @add_io_time_avg_w=avg(0); add_io_time_sum_r=0; add_io_time_sum_w=0; /* counter storing the maximum amount of time spent in I/O for an LDAP modify operation */ @add_io_time_max=max(0); @add_io_time_avg=avg(0); @add_io_size_max=max(0); @add_io_size_avg=avg(0); @add_io_size_max_r=max(0); @add_io_size_max_w=max(0); @add_io_size_avg_r=avg(0); @add_io_size_avg_w=avg(0); add_io_size_sum_r=0; add_io_size_sum_w=0; /* DEL variables initialization */ del_ldap_cnt=0; @del_ldap_max=max(0); @del_ldap_avg=avg(0); del_ldap_time=0; del_io_cnt_r=0; del_io_cnt_r_async=0; del_io_cnt_r_sync=0; del_io_cnt_w=0; del_io_cnt_w_async=0; del_io_cnt_w_sync=0; /* counter storing the maximum amount of time spent in I/O for an LDAP modify operation */ @del_io_time_max=max(0); @del_io_time_avg=avg(0); @del_io_size_max=max(0); @del_io_size_avg=avg(0); @del_io_time_max_r=max(0); @del_io_time_max_w=max(0); @del_io_time_avg_r=avg(0); @del_io_time_avg_w=avg(0); del_io_time_sum_r=0; del_io_time_sum_w=0; @del_io_size_max_r=max(0); @del_io_size_max_w=max(0); @del_io_size_avg_r=avg(0); @del_io_size_avg_w=avg(0); del_io_size_sum_r=0; del_io_size_sum_w=0; } /************************************************* * SEARCH - BEGIN * *************************************************/ /* intercept calls to the search_core_pb function * in Directory Server code for the instance * running under process id "$1" * further IOs in this thread of Directory Server * will be stored in the "search" counters until * we intercept a return from the search_core_pb * function */ pid$1::search_core_pb:entry { /* this is used as a boolean, anything but 0 works * to trigger the return probe, also allows to * measure the time spent in the function * and tie any subsequent I/O operation to * LDAP search */ this->srch_start_time=timestamp; } /* this is when we trap the return from a call to the * function in the C code of the server for search * operations */ pid$1::search_core_pb:return /this->srch_start_time/ { /* increment the count only on the return probe so only * calls actually processed are counted */ srch_ldap_cnt ++; /* store the max time spent in the function (in microseconds) */ this->elapsed_nano=timestamp - this->srch_start_time; this->elapsed_micro=this->elapsed_nano / 1000 ; @srch_ldap_max=max(this->elapsed_micro); @srch_ldap_avg=avg(this->elapsed_micro); @all_ldap_max=max(this->elapsed_micro); @all_ldap_avg=avg(this->elapsed_micro); /* store the total time spent in the function in nanoseconds */ srch_ldap_time += this->elapsed_nano; /* free the memory used here */ this->srch_start_time=0; this->elapsed_nano=0; this->elapsed_micro=0; } /* * Here, we trap all I/O operations called while we are in * search_core_pb function of the directory server code. This * effectively allows us to relate I/Os caused by a particular * type of LDAP operation. */ io:::start /this->srch_start_time/ { /* many operations may occur so we need to identify them by * the device on which each one applies as well as the block * number targeted. This assumes no two I/O operations address * the same block on the same device at any given time. */ srch_start[args[0]->b_edev, args[0]->b_blkno] = timestamp; /* this allows to identify whether the current operation is a * read operation or a write operation */ this->rw=(args[0]->b_flags&B_READ?"R":"W"); /* this allows to identify the operation synchronicity */ this->async=(args[0]->b_flags&B_ASYNC?"A":"S"); } io:::done / srch_start[args[0]->b_edev, args[0]->b_blkno] && this->rw == "W" / { /* store the maximum elapsed time for write operations incurred by * LDAP searches in microseconds * why microseconds? nanoseconds take up too much real estate and * milliseconds do not provide fine enough a resolution */ this->elapsed_nano = timestamp - srch_start[args[0]->b_edev, args[0]->b_blkno]; this->elapsed_micro = this->elapsed_nano / 1000 ; this->size = args[0]->b_bcount / 1024; /* increment the number of write operations completed for LDAP search operations */ srch_io_cnt_w ++; srch_io_cnt_w_sync += ( this->async == "S" ? 1 : 0 ); srch_io_cnt_w_async += ( this->async == "A" ? 1 : 0 ); /* record the maximum elapsed time for write I/Os incurred by LDAP search operations */ @srch_io_time_max_w = max( this->elapsed_micro ); @srch_io_time_max = max( this->elapsed_micro ); @all_io_time_max_w = max( this->elapsed_micro ); @all_io_time_max = max( this->elapsed_micro ); /* store the average time spent in I/O for read I/O */ @srch_io_time_avg_w = avg( this->elapsed_micro ); @srch_io_time_avg = avg( this->elapsed_micro ); @all_io_time_avg_w = avg( this->elapsed_micro ); @all_io_time_avg = avg( this->elapsed_micro ); /* store the total time spent in I/O write to compute %I/O */ srch_io_time_sum_w += this->elapsed_nano; /* store the total size in kB of read I/Os for LDAP searches*/ srch_io_size_sum_w += this->size; /* store the average size in kB of a write I/O for LDAP searches */ @srch_io_size_avg_w = avg( this->size ); @srch_io_size_avg = avg( this->size ); @all_io_size_avg_w = avg( this->size ); @all_io_size_avg = avg( this->size ); /* store the maximum size in kB of a write I/O for LDAP searches */ @srch_io_size_max_w = max( this->size ); @srch_io_size_max = max( this->size ); @all_io_size_max_w = max( this->size ); @all_io_size_max = max( this->size ); /* free up memory used locally */ this->elapsed_nano = 0; this->elapsed_micro = 0; this->size = 0; } io:::done / srch_start[args[0]->b_edev, args[0]->b_blkno] && this->rw == "R" / { /* store the maximum elapsed time for read operations incurred by * LDAP searches in microseconds * why microseconds? nanoseconds take up too much real estate and * milliseconds do not provide fine enough a resolution */ this->elapsed_nano = timestamp - srch_start[args[0]->b_edev, args[0]->b_blkno]; this->elapsed_micro = this->elapsed_nano / 1000 ; this->size = args[0]->b_bcount / 1024; /* increment the number of write operations completed for LDAP search operations */ srch_io_cnt_r ++; srch_io_cnt_r_sync += ( this->async == "S" ? 1 : 0 ); srch_io_cnt_r_async += ( this->async == "A" ? 1 : 0 ); /* record the maximum elapsed time for write I/Os incurred by LDAP search operations */ @srch_io_time_max_r = max( this->elapsed_micro ); @srch_io_time_max = max( this->elapsed_micro ); @all_io_time_max_r = max( this->elapsed_micro ); @all_io_time_max = max( this->elapsed_micro ); /* store the average time spent in I/O for read I/O */ @srch_io_time_avg_r = avg( this->elapsed_micro ); @srch_io_time_avg = avg( this->elapsed_micro ); @all_io_time_avg_r = avg( this->elapsed_micro ); @all_io_time_avg = avg( this->elapsed_micro ); /* store the total time spent in I/O write to compute %I/O */ srch_io_time_sum_r += this->elapsed_nano; /* store the total size in kB of read I/Os for LDAP searches*/ srch_io_size_sum_r += this->size; /* store the average size in kB of a write I/O for LDAP searches */ @srch_io_size_avg_r = avg( this->size ); @srch_io_size_avg = avg( this->size ); @all_io_size_avg_r = avg( this->size ); @all_io_size_avg = avg( this->size ); /* store the maximum size in kB of a write I/O for LDAP searches */ @srch_io_size_max_r = max( this->size ); @srch_io_size_max = max( this->size ); @all_io_size_max_r = max( this->size ); @all_io_size_max = max( this->size ); /* free up memory used locally */ this->elapsed_nano = 0; this->elapsed_micro = 0; this->size = 0; } /* cleanup after ourselves */ io:::done / srch_start[args[0]->b_edev, args[0]->b_blkno] / { this->rw=0; this->async=0; srch_start[args[0]->b_edev, args[0]->b_blkno]=0; } /************************************************* * SEARCH - END * *************************************************/ /************************************************* * MODIFY - BEGIN * *************************************************/ /* intercept calls to the modify_core_pb function * in Directory Server code for the instance * running under process id "$1" * further IOs in this thread of Directory Server * will be stored in the "modify" counters until * we intercept a return from the modify_core_pb * function */ pid$1::modify_core_pb:entry { /* this is used as a boolean, anything but 0 works * to trigger the return probe, also allows to * measure the time spent in the function * and tie any subsequent I/O operation to * LDAP modify */ this->mod_start_time=timestamp; } /* this is when we trap the return from a call to the * function in the C code of the server for modify * operations */ pid$1::modify_core_pb:return /this->mod_start_time/ { /* increment the count only on the return probe so only * calls actually processed are counted */ mod_ldap_cnt ++; /* store the max time spent in the function (in microseconds) */ this->elapsed_nano=timestamp - this->mod_start_time; this->elapsed_micro=this->elapsed_nano / 1000 ; @mod_ldap_max=max(this->elapsed_micro); @mod_ldap_avg=avg(this->elapsed_micro); @all_ldap_max=max(this->elapsed_micro); @all_ldap_avg=avg(this->elapsed_micro); /* store the total time spent in the function in nanoseconds */ mod_ldap_time += this->elapsed_nano; /* free the memory used here */ this->mod_start_time=0; this->elapsed_nano=0; this->elapsed_micro=0; } /* * Here, we trap all I/O operations called while we are in * modify_core_pb function of the directory server code. This * effectively allows us to relate I/Os caused by a particular * type of LDAP operation. */ io:::start /this->mod_start_time/ { /* many operations may occur so we need to identify them by * the device on which each one applies as well as the block * number targeted. This assumes no two I/O operations address * the same block on the same device at any given time (within the * same nanosecond to be more accurate) */ mod_start[args[0]->b_edev, args[0]->b_blkno] = timestamp; /* this allows to identify whether the current operation is a * read operation or a write operation */ this->rw=(args[0]->b_flags&B_READ?"R":"W"); /* this allows to identify the operation synchronicity */ this->async=(args[0]->b_flags&B_ASYNC?"A":"S"); } io:::done / mod_start[args[0]->b_edev, args[0]->b_blkno] && this->rw == "W" / { /* store the maximum elapsed time for write operations incurred by * LDAP modifies in microseconds * why microseconds? nanoseconds take up too much real estate and * milliseconds do not provide fine enough a resolution */ this->elapsed_nano = timestamp - mod_start[args[0]->b_edev, args[0]->b_blkno]; this->elapsed_micro = this->elapsed_nano / 1000 ; this->size = args[0]->b_bcount / 1024; /* increment the number of write operations completed for LDAP modifies operations */ mod_io_cnt_w ++; mod_io_cnt_w_sync += ( this->async == "S" ? 1 : 0 ); mod_io_cnt_w_async += ( this->async == "A" ? 1 : 0 ); /* record the maximum elapsed time for write I/Os incurred by LDAP modifies operations */ @mod_io_time_max_w = max( this->elapsed_micro ); @mod_io_time_max = max( this->elapsed_micro ); @all_io_time_max_w = max( this->elapsed_micro ); @all_io_time_max = max( this->elapsed_micro ); /* store the average time spent in I/O for read I/O */ @mod_io_time_avg_w = avg( this->elapsed_micro ); @mod_io_time_avg = avg( this->elapsed_micro ); @all_io_time_avg_w = avg( this->elapsed_micro ); @all_io_time_avg = avg( this->elapsed_micro ); /* store the total time spent in I/O write to compute %I/O */ mod_io_time_sum_w += this->elapsed_nano; /* store the total size in kB of read I/Os for LDAP searches*/ mod_io_size_sum_w += this->size; /* store the average size in kB of a write I/O for LDAP modifies */ @mod_io_size_avg_w = avg( this->size ); @mod_io_size_avg = avg( this->size ); @all_io_size_avg_w = avg( this->size ); @all_io_size_avg = avg( this->size ); /* store the maximum size in kB of a write I/O for LDAP modifies */ @mod_io_size_max_w = max( this->size ); @mod_io_size_max = max( this->size ); @all_io_size_max_w = max( this->size ); @all_io_size_max = max( this->size ); /* free up memory used locally */ this->elapsed_nano = 0; this->elapsed_micro = 0; this->size = 0; } io:::done / mod_start[args[0]->b_edev, args[0]->b_blkno] && this->rw == "R" / { /* store the maximum elapsed time for read operations incurred by * LDAP searches in microseconds * why microseconds? nanoseconds take up too much real estate and * milliseconds do not provide fine enough a resolution */ this->elapsed_nano = timestamp - mod_start[args[0]->b_edev, args[0]->b_blkno]; this->elapsed_micro = this->elapsed_nano / 1000 ; this->size = args[0]->b_bcount / 1024; /* increment the number of write operations completed for LDAP modifies operations */ mod_io_cnt_r ++; mod_io_cnt_r_sync += ( this->async == "S" ? 1 : 0 ); mod_io_cnt_r_async += ( this->async == "A" ? 1 : 0 ); /* record the maximum elapsed time for write I/Os incurred by LDAP modifies operations */ @mod_io_time_max_r = max( this->elapsed_micro ); @mod_io_time_max = max( this->elapsed_micro ); @all_io_time_max_r = max( this->elapsed_micro ); @all_io_time_max = max( this->elapsed_micro ); /* store the average time spent in I/O for read I/O */ @mod_io_time_avg_r = avg( this->elapsed_micro ); @mod_io_time_avg = avg( this->elapsed_micro ); @all_io_time_avg_r = avg( this->elapsed_micro ); @all_io_time_avg = avg( this->elapsed_micro ); /* store the total time spent in I/O write to compute %I/O */ mod_io_time_sum_r += this->elapsed_nano; /* store the total size in kB of read I/Os for LDAP modifies*/ mod_io_size_sum_r += this->size; /* store the average size in kB of a write I/O for LDAP modifies */ @mod_io_size_avg_r = avg( this->size ); @mod_io_size_avg = avg( this->size ); @all_io_size_avg_r = avg( this->size ); @all_io_size_avg = avg( this->size ); /* store the maximum size in kB of a write I/O for LDAP modifies */ @mod_io_size_max_r = max( this->size ); @mod_io_size_max = max( this->size ); @all_io_size_max_r = max( this->size ); @all_io_size_max = max( this->size ); /* free up memory used locally */ this->elapsed_nano = 0; this->elapsed_micro = 0; this->size = 0; } /* cleanup after ourselves */ io:::done / mod_start[args[0]->b_edev, args[0]->b_blkno] / { this->rw=0; this->async=0; mod_start[args[0]->b_edev, args[0]->b_blkno]=0; } /************************************************* * MODIFY - END * *************************************************/ /************************************************* * DELETE - BEGIN * *************************************************/ /* intercept calls to the delete_core_pb function * in Directory Server code for the instance * running under process id "$1" * further IOs in this thread of Directory Server * will be stored in the "delete" counters until * we intercept a return from the delete_core_pb * function */ pid$1::delete_core_pb:entry { /* this is used as a boolean, anything but 0 works * to trigger the return probe, also allows to * measure the time spent in the function * and tie any subsequent I/O operation to * LDAP delete */ this->del_start_time=timestamp; } /* this is when we trap the return from a call to the * function in the C code of the server for delete * operations */ pid$1::delete_core_pb:return /this->del_start_time/ { /* increment the count only on the return probe so only * calls actually processed are counted */ del_ldap_cnt ++; /* store the max time spent in the function (in microseconds) */ this->elapsed_nano=timestamp - this->del_start_time; this->elapsed_micro=this->elapsed_nano / 1000 ; @del_ldap_max=max(this->elapsed_micro); @del_ldap_avg=avg(this->elapsed_micro); @all_ldap_max=max(this->elapsed_micro); @all_ldap_avg=avg(this->elapsed_micro); /* store the total time spent in the function in nanoseconds */ del_ldap_time += this->elapsed_nano; /* free the memory used here */ this->del_start_time=0; this->elapsed_nano=0; this->elapsed_micro=0; } /* * Here, we trap all I/O operations called while we are in * delete_core_pb function of the directory server code. This * effectively allows us to relate I/Os caused by a particular * type of LDAP operation. */ io:::start /this->del_start_time/ { /* many operations may occur so we need to identify them by * the device on which each one applies as well as the block * number targeted. This assumes no two I/O operations address * the same block on the same device at any given time (within the * same nanosecond to be more accurate) */ del_start[args[0]->b_edev, args[0]->b_blkno] = timestamp; /* this allows to identify whether the current operation is a * read operation or a write operation */ this->rw=(args[0]->b_flags&B_READ?"R":"W"); /* this allows to identify the operation synchronicity */ this->async=(args[0]->b_flags&B_ASYNC?"A":"S"); } io:::done / del_start[args[0]->b_edev, args[0]->b_blkno] && this->rw == "W" / { /* store the maximum elapsed time for write operations incurred by * LDAP deletes in microseconds * why microseconds? nanoseconds take up too much real estate and * milliseconds do not provide fine enough a resolution */ this->elapsed_nano = timestamp - del_start[args[0]->b_edev, args[0]->b_blkno]; this->elapsed_micro = this->elapsed_nano / 1000 ; this->size = args[0]->b_bcount / 1024; /* increment the number of write operations completed for LDAP delete operations */ del_io_cnt_w ++; del_io_cnt_w_sync += ( this->async == "S" ? 1 : 0 ); del_io_cnt_w_async += ( this->async == "A" ? 1 : 0 ); /* record the maximum elapsed time for write I/Os incurred by LDAP delete operations */ @del_io_time_max_w = max( this->elapsed_micro ); @del_io_time_max = max( this->elapsed_micro ); @all_io_time_max_w = max( this->elapsed_micro ); @all_io_time_max = max( this->elapsed_micro ); /* store the average time spent in I/O for read I/O */ @del_io_time_avg_w = avg( this->elapsed_micro ); @del_io_time_avg = avg( this->elapsed_micro ); @all_io_time_avg_w = avg( this->elapsed_micro ); @all_io_time_avg = avg( this->elapsed_micro ); /* store the total time spent in I/O write to compute %I/O */ del_io_time_sum_w += this->elapsed_nano; /* store the total size in kB of read I/Os for LDAP deletes*/ del_io_size_sum_w += this->size; /* store the average size in kB of a write I/O for LDAP deletes */ @del_io_size_avg_w = avg( this->size ); @del_io_size_avg = avg( this->size ); @all_io_size_avg_w = avg( this->size ); @all_io_size_avg = avg( this->size ); /* store the maximum size in kB of a write I/O for LDAP deletes */ @del_io_size_max_w = max( this->size ); @del_io_size_max = max( this->size ); @all_io_size_max_w = max( this->size ); @all_io_size_max = max( this->size ); /* free up memory used locally */ this->elapsed_nano = 0; this->elapsed_micro = 0; this->size = 0; } io:::done / del_start[args[0]->b_edev, args[0]->b_blkno] && this->rw == "R" / { /* store the maximum elapsed time for read operations incurred by * LDAP searches in microseconds * why microseconds? nanoseconds take up too much real estate and * milliseconds do not provide fine enough a resolution */ this->elapsed_nano = timestamp - del_start[args[0]->b_edev, args[0]->b_blkno]; this->elapsed_micro = this->elapsed_nano / 1000 ; this->size = args[0]->b_bcount / 1024; /* increment the number of write operations completed for LDAP delete operations */ del_io_cnt_r ++; del_io_cnt_r_sync += ( this->async == "S" ? 1 : 0 ); del_io_cnt_r_async += ( this->async == "A" ? 1 : 0 ); /* record the maximum elapsed time for write I/Os incurred by LDAP delete operations */ @del_io_time_max_r = max( this->elapsed_micro ); @del_io_time_max = max( this->elapsed_micro ); @all_io_time_max_r = max( this->elapsed_micro ); @all_io_time_max = max( this->elapsed_micro ); /* store the average time spent in I/O for read I/O */ @del_io_time_avg_r = avg( this->elapsed_micro ); @del_io_time_avg = avg( this->elapsed_micro ); @all_io_time_avg_r = avg( this->elapsed_micro ); @all_io_time_avg = avg( this->elapsed_micro ); /* store the total time spent in I/O write to compute %I/O */ del_io_time_sum_r += this->elapsed_nano; /* store the total size in kB of read I/Os for LDAP deletes */ del_io_size_sum_r += this->size; /* store the average size in kB of a write I/O for LDAP deletes */ @del_io_size_avg_r = avg( this->size ); @del_io_size_avg = avg( this->size ); @all_io_size_avg_r = avg( this->size ); @all_io_size_avg = avg( this->size ); /* store the maximum size in kB of a write I/O for LDAP deletes */ @del_io_size_max_r = max( this->size ); @del_io_size_max = max( this->size ); @all_io_size_max_r = max( this->size ); @all_io_size_max = max( this->size ); /* free up memory used locally */ this->elapsed_nano = 0; this->elapsed_micro = 0; this->size = 0; } /* cleanup after ourselves */ io:::done / del_start[args[0]->b_edev, args[0]->b_blkno] / { this->rw=0; this->async=0; del_start[args[0]->b_edev, args[0]->b_blkno]=0; } /************************************************* * DELETE - END * *************************************************/ /************************************************* * ADD - BEGIN * *************************************************/ /* intercept calls to the add_core_pb function * in Directory Server code for the instance * running under process id "$1" * further IOs in this thread of Directory Server * will be stored in the "add" counters until * we intercept a return from the add_core_pb * function */ pid$1::add_core_pb:entry { /* this is used as a boolean, anything but 0 works * to trigger the return probe, also allows to * measure the time spent in the function * and tie any subsequent I/O operation to * LDAP add */ this->add_start_time=timestamp; } /* this is when we trap the return from a call to the * function in the C code of the server for delete * operations */ pid$1::add_core_pb:return /this->add_start_time/ { /* increment the count only on the return probe so only * calls actually processed are counted */ add_ldap_cnt ++; /* store the max time spent in the function (in microseconds) */ this->elapsed_nano=timestamp - this->add_start_time; this->elapsed_micro=this->elapsed_nano / 1000 ; @add_ldap_max=max(this->elapsed_micro); @add_ldap_avg=avg(this->elapsed_micro); @all_ldap_max=max(this->elapsed_micro); @all_ldap_avg=avg(this->elapsed_micro); /* store the total time spent in the function in nanoseconds */ add_ldap_time += this->elapsed_nano; /* free the memory used here */ this->add_start_time=0; this->elapsed_nano=0; this->elapsed_micro=0; } /* * Here, we trap all I/O operations called while we are in * add_core_pb function of the directory server code. This * effectively allows us to relate I/Os caused by a particular * type of LDAP operation. */ io:::start /this->add_start_time/ { /* many operations may occur so we need to identify them by * the device on which each one applies as well as the block * number targeted. This assumes no two I/O operations address * the same block on the same device at any given time (within the * same nanosecond to be more accurate) */ add_start[args[0]->b_edev, args[0]->b_blkno] = timestamp; /* this allows to identify whether the current operation is a * read operation or a write operation */ this->rw=(args[0]->b_flags&B_READ?"R":"W"); /* this allows to identify the operation synchronicity */ this->async=(args[0]->b_flags&B_ASYNC?"A":"S"); } io:::done / add_start[args[0]->b_edev, args[0]->b_blkno] && this->rw == "W" / { /* store the maximum elapsed time for write operations incurred by * LDAP adds in microseconds * why microseconds? nanoseconds take up too much real estate and * milliseconds do not provide fine enough a resolution */ this->elapsed_nano = timestamp - add_start[args[0]->b_edev, args[0]->b_blkno]; this->elapsed_micro = this->elapsed_nano / 1000 ; this->size = args[0]->b_bcount / 1024; /* increment the number of write operations completed for LDAP add operations */ add_io_cnt_w ++; add_io_cnt_w_sync += ( this->async == "S" ? 1 : 0 ); add_io_cnt_w_async += ( this->async == "A" ? 1 : 0 ); /* record the maximum elapsed time for write I/Os incurred by LDAP add operations */ @add_io_time_max_w = max( this->elapsed_micro ); @add_io_time_max = max( this->elapsed_micro ); @all_io_time_max_w = max( this->elapsed_micro ); @all_io_time_max = max( this->elapsed_micro ); /* store the average time spent in I/O for read I/O */ @add_io_time_avg_w = avg( this->elapsed_micro ); @add_io_time_avg = avg( this->elapsed_micro ); @all_io_time_avg_w = avg( this->elapsed_micro ); @all_io_time_avg = avg( this->elapsed_micro ); /* store the total time spent in I/O write to compute %I/O */ add_io_time_sum_w += this->elapsed_nano; /* store the total size in kB of read I/Os for LDAP adds */ add_io_size_sum_w += this->size; /* store the average size in kB of a write I/O for LDAP adds */ @add_io_size_avg_w = avg( this->size ); @add_io_size_avg = avg( this->size ); @all_io_size_avg_w = avg( this->size ); @all_io_size_avg = avg( this->size ); /* store the maximum size in kB of a write I/O for LDAP adds */ @add_io_size_max_w = max( this->size ); @add_io_size_max = max( this->size ); @all_io_size_max_w = max( this->size ); @all_io_size_max = max( this->size ); /* free up memory used locally */ this->elapsed_nano = 0; this->elapsed_micro = 0; this->size = 0; } io:::done / add_start[args[0]->b_edev, args[0]->b_blkno] && this->rw == "R" / { /* store the maximum elapsed time for read operations incurred by * LDAP adds in microseconds * why microseconds? nanoseconds take up too much real estate and * milliseconds do not provide fine enough a resolution */ this->elapsed_nano = timestamp - add_start[args[0]->b_edev, args[0]->b_blkno]; this->elapsed_micro = this->elapsed_nano / 1000 ; this->size = args[0]->b_bcount / 1024; /* increment the number of write operations completed for LDAP add operations */ add_io_cnt_r ++; add_io_cnt_r_sync += ( this->async == "S" ? 1 : 0 ); add_io_cnt_r_async += ( this->async == "A" ? 1 : 0 ); /* record the maximum elapsed time for write I/Os incurred by LDAP add operations */ @add_io_time_max_r = max( this->elapsed_micro ); @add_io_time_max = max( this->elapsed_micro ); @all_io_time_max_r = max( this->elapsed_micro ); @all_io_time_max = max( this->elapsed_micro ); /* store the average time spent in I/O for read I/O */ @add_io_time_avg_r = avg( this->elapsed_micro ); @add_io_time_avg = avg( this->elapsed_micro ); @all_io_time_avg_r = avg( this->elapsed_micro ); @all_io_time_avg = avg( this->elapsed_micro ); /* store the total time spent in I/O write to compute %I/O */ add_io_time_sum_r += this->elapsed_nano; /* store the total size in kB of read I/Os for LDAP adds */ add_io_size_sum_r += this->size; /* store the average size in kB of a write I/O for LDAP adds */ @add_io_size_avg_r = avg( this->size ); @add_io_size_avg = avg( this->size ); @all_io_size_avg_r = avg( this->size ); @all_io_size_avg = avg( this->size ); /* store the maximum size in kB of a write I/O for LDAP adds */ @add_io_size_max_r = max( this->size ); @add_io_size_max = max( this->size ); @all_io_size_max_r = max( this->size ); @all_io_size_max = max( this->size ); /* free up memory used locally */ this->elapsed_nano = 0; this->elapsed_micro = 0; this->size = 0; } /* cleanup after ourselves */ io:::done / add_start[args[0]->b_edev, args[0]->b_blkno] / { this->rw=0; this->async=0; add_start[args[0]->b_edev, args[0]->b_blkno]=0; } /************************************************* * ADD - END * *************************************************/ profile-1sec { seconds++; quiet=seconds%period; } profile-1sec /!quiet/ { prints++; /* Prepare data for output */ this->all_ldap_cnt = srch_ldap_cnt + mod_ldap_cnt + add_ldap_cnt + del_ldap_cnt; this->srch_ldap_ratio = ( this->all_ldap_cnt==0?0:(srch_ldap_cnt*100)/this->all_ldap_cnt); this->mod_ldap_ratio = ( this->all_ldap_cnt==0?0:(mod_ldap_cnt*100)/this->all_ldap_cnt); this->add_ldap_ratio = ( this->all_ldap_cnt==0?0:(add_ldap_cnt*100)/this->all_ldap_cnt); this->del_ldap_ratio = ( this->all_ldap_cnt==0?0:(del_ldap_cnt*100)/this->all_ldap_cnt); this->all_io_cnt_r = srch_io_cnt_r+mod_io_cnt_r+add_io_cnt_r+del_io_cnt_r; this->srch_io_cnt_ratio_r = (this->all_io_cnt_r==0?0:(srch_io_cnt_r*100)/this->all_io_cnt_r); this->mod_io_cnt_ratio_r = (this->all_io_cnt_r==0?0:( mod_io_cnt_r*100)/this->all_io_cnt_r); this->add_io_cnt_ratio_r = (this->all_io_cnt_r==0?0:( add_io_cnt_r*100)/this->all_io_cnt_r); this->del_io_cnt_ratio_r = (this->all_io_cnt_r==0?0:( del_io_cnt_r*100)/this->all_io_cnt_r); this->all_io_cnt_w = srch_io_cnt_w+mod_io_cnt_w+add_io_cnt_w+del_io_cnt_w; this->srch_io_cnt_ratio_w = (this->all_io_cnt_w==0?0:(srch_io_cnt_w*100)/this->all_io_cnt_w); this->mod_io_cnt_ratio_w = (this->all_io_cnt_w==0?0:( mod_io_cnt_w*100)/this->all_io_cnt_w); this->add_io_cnt_ratio_w = (this->all_io_cnt_w==0?0:( add_io_cnt_w*100)/this->all_io_cnt_w); this->del_io_cnt_ratio_w = (this->all_io_cnt_w==0?0:( del_io_cnt_w*100)/this->all_io_cnt_w); this->all_io_cnt = this->all_io_cnt_r + this->all_io_cnt_w ; this->srch_io_cnt = srch_io_cnt_r + srch_io_cnt_w; this->mod_io_cnt = mod_io_cnt_r + mod_io_cnt_w; this->add_io_cnt = add_io_cnt_r + add_io_cnt_w; this->del_io_cnt = del_io_cnt_r + del_io_cnt_w; this->srch_io_ratio = (this->all_io_cnt==0?0: (this->srch_io_cnt*100)/this->all_io_cnt); this->mod_io_ratio = (this->all_io_cnt==0?0: (this->mod_io_cnt*100)/this->all_io_cnt); this->add_io_ratio = (this->all_io_cnt==0?0: (this->add_io_cnt*100)/this->all_io_cnt); this->del_io_ratio = (this->all_io_cnt==0?0: (this->del_io_cnt*100)/this->all_io_cnt); this->all_io_size_sum_r = srch_io_size_sum_r+ mod_io_size_sum_r+ add_io_size_sum_r+ del_io_size_sum_r; this->all_io_size_sum_w = srch_io_size_sum_w+ mod_io_size_sum_w+ add_io_size_sum_w+ del_io_size_sum_w; this->all_io_size_sum = this->all_io_size_sum_r + this->all_io_size_sum_w; this->srch_io_size_sum = srch_io_size_sum_r + srch_io_size_sum_w; this->mod_io_size_sum = mod_io_size_sum_r + mod_io_size_sum_w; this->add_io_size_sum = del_io_size_sum_r + add_io_size_sum_w; this->del_io_size_sum = del_io_size_sum_r + del_io_size_sum_w; this->all_ldap_time = srch_ldap_time+mod_ldap_time+add_ldap_time+del_ldap_time; this->all_io_time_w = srch_io_time_sum_w+mod_io_time_sum_w+add_io_time_sum_w+del_io_time_sum_w; this->all_io_time_ratio_w = (this->all_io_time_w==0?0:(this->all_io_time_w*100)/this->all_ldap_time); this->srch_io_time_ratio_w = (srch_ldap_time==0?0:(srch_io_time_sum_w*100)/srch_ldap_time); this->mod_io_time_ratio_w = (mod_ldap_time==0 ?0:( mod_io_time_sum_w*100)/ mod_ldap_time); this->add_io_time_ratio_w = (add_ldap_time==0 ?0:( add_io_time_sum_w*100)/ add_ldap_time); this->del_io_time_ratio_w = (del_ldap_time==0 ?0:( del_io_time_sum_w*100)/ del_ldap_time); this->all_io_time_r = srch_io_time_sum_r+mod_io_time_sum_r+add_io_time_sum_r+del_io_time_sum_r; this->all_io_time_ratio_r = (this->all_io_time_r==0?0:(this->all_io_time_r*100)/this->all_ldap_time); this->srch_io_time_ratio_r = (srch_ldap_time==0?0:(srch_io_time_sum_r*100)/srch_ldap_time); this->mod_io_time_ratio_r = (mod_ldap_time==0 ?0:( mod_io_time_sum_r*100)/ mod_ldap_time); this->add_io_time_ratio_r = (add_ldap_time==0 ?0:( add_io_time_sum_r*100)/ add_ldap_time); this->del_io_time_ratio_r = (del_ldap_time==0 ?0:( del_io_time_sum_r*100)/ del_ldap_time); this->all_io_time = this->all_io_time_r + this->all_io_time_w; this->all_io_time_ratio = (this->all_ldap_time==0?0:(this->all_io_time*100)/this->all_ldap_time); this->srch_io_time_ratio = (srch_ldap_time==0?0:((srch_io_time_sum_r+srch_io_time_sum_w)*100)/srch_ldap_time); this->mod_io_time_ratio = (mod_ldap_time==0?0:((mod_io_time_sum_r+mod_io_time_sum_w)*100)/mod_ldap_time); this->add_io_time_ratio = (add_ldap_time==0?0:((add_io_time_sum_r+add_io_time_sum_w)*100)/mod_ldap_time); this->del_io_time_ratio = (del_ldap_time==0?0:((del_io_time_sum_r+del_io_time_sum_w)*100)/mod_ldap_time); this->all_sync_w = srch_io_cnt_w_sync+mod_io_cnt_w_sync+add_io_cnt_w_sync+del_io_cnt_w_sync; this->all_async_w = srch_io_cnt_w_async+mod_io_cnt_w_async+add_io_cnt_w_async+del_io_cnt_w_async; this->all_syncasync_w = this->all_sync_w + this->all_async_w; this->all_sync_ratio_w = (this->all_syncasync_w==0?0:(this->all_sync_w*100)/this->all_syncasync_w); this->srch_syncasync_w = srch_io_cnt_w_sync + srch_io_cnt_w_async; this->srch_sync_ratio_w = (this->srch_syncasync_w==0?0:(srch_io_cnt_w_sync*100)/this->srch_syncasync_w); this->mod_syncasync_w = mod_io_cnt_w_sync + mod_io_cnt_w_async; this->mod_sync_ratio_w = (this->mod_syncasync_w==0?0:(mod_io_cnt_w_sync*100)/this->mod_syncasync_w); this->add_syncasync_w = add_io_cnt_w_sync + add_io_cnt_w_async; this->add_sync_ratio_w = (this->add_syncasync_w==0?0:(add_io_cnt_w_sync*100)/this->add_syncasync_w); this->del_syncasync_w = del_io_cnt_w_sync + del_io_cnt_w_async; this->del_sync_ratio_w = (this->del_syncasync_w==0?0:(del_io_cnt_w_sync*100)/this->del_syncasync_w); this->all_sync_r = srch_io_cnt_r_sync+mod_io_cnt_r_sync+add_io_cnt_r_sync+del_io_cnt_r_sync; this->all_async_r = srch_io_cnt_r_async+mod_io_cnt_r_async+add_io_cnt_r_async+del_io_cnt_r_async; this->all_syncasync_r = this->all_sync_r + this->all_async_r; this->all_sync_ratio_r = (this->all_syncasync_r==0?0:(this->all_sync_r*100)/this->all_syncasync_r); this->srch_syncasync_r = srch_io_cnt_r_sync + srch_io_cnt_r_async; this->srch_sync_ratio_r = (this->srch_syncasync_r==0?0:(srch_io_cnt_r_sync*100)/this->srch_syncasync_r); this->mod_syncasync_r = mod_io_cnt_r_sync + mod_io_cnt_r_async; this->mod_sync_ratio_r = (this->mod_syncasync_r==0?0:(mod_io_cnt_r_sync*100)/this->mod_syncasync_r); this->add_syncasync_r = add_io_cnt_r_sync + add_io_cnt_r_async; this->add_sync_ratio_r = (this->add_syncasync_r==0?0:(add_io_cnt_r_sync*100)/this->add_syncasync_r); this->del_syncasync_r = del_io_cnt_r_sync + del_io_cnt_r_async; this->del_sync_ratio_r = (this->del_syncasync_r==0?0:(del_io_cnt_r_sync*100)/this->del_syncasync_r); } profile-1sec /quiet == 0/ { /* kinda clears the screen :) */ printf("%s",clearstr); printf("LDAP | Total | SRCH | MOD | ADD | DEL |\n"); printf("___________________|___________|___%3d%%____|___%3d%%____|___%3d%%____|___%3d%%____|\n", this->srch_ldap_ratio, this->mod_ldap_ratio, this->add_ldap_ratio, this->del_ldap_ratio ); printf("Rate (per sec) |%10d |%10d |%10d |%10d |%10d |\n", this->all_ldap_cnt/period, srch_ldap_cnt/period, mod_ldap_cnt/period, add_ldap_cnt/period,del_ldap_cnt/period); print_ldap?printf("Count |%10d |%10d |%10d |%10d |%10d |\n", this->all_ldap_cnt , srch_ldap_cnt, mod_ldap_cnt, add_ldap_cnt, del_ldap_cnt):1; print_ldap?printf("Avg time (usec) |"):1; print_ldap?printa("%@10d |" , @all_ldap_avg):1; print_ldap?printa("%@10d |" , @srch_ldap_avg):1; print_ldap?printa("%@10d |" , @mod_ldap_avg):1; print_ldap?printa("%@10d |" , @add_ldap_avg):1; print_ldap?printa("%@10d |\n", @del_ldap_avg):1; print_ldap?printf("Max time (usec) |"):1; print_ldap?printa("%@10d |", @all_ldap_max):1; print_ldap?printa("%@10d |" , @srch_ldap_max):1; print_ldap?printa("%@10d |" , @mod_ldap_max):1; print_ldap?printa("%@10d |" , @add_ldap_max):1; print_ldap?printa("%@10d |\n", @del_ldap_max):1; printf("I/O________________|___________|___________|___________|___________|___________|\n"); /* * I/O Write output */ print_write?printf("-Write |___________|____%3d%%___|____%3d%%___|____%3d%%___|____%3d%%___|\n",this->srch_io_cnt_ratio_w,this->mod_io_cnt_ratio_w, this->add_io_cnt_ratio_w,this->del_io_cnt_ratio_w):1; print_write?printf(" +Count |%10d |%10d |%10d |%10d |%10d |\n", this->all_io_cnt_w, srch_io_cnt_w, mod_io_cnt_w, add_io_cnt_w, del_io_cnt_w):1; print_write?printf(" +Rate (per sec) |%10d |%10d |%10d |%10d |%10d |\n", this->all_io_cnt_w/period, srch_io_cnt_w/period, mod_io_cnt_w/period, add_io_cnt_w/period, del_io_cnt_w/period):1; print_write?printf(" +Avg size (kB) |"):1; print_write?printa("%@10d |", @all_io_size_avg_w):1; print_write?printa("%@10d |", @srch_io_size_avg_w):1; print_write?printa("%@10d |", @mod_io_size_avg_w):1; print_write?printa("%@10d |", @add_io_size_avg_w):1; print_write?printa("%@10d |\n", @del_io_size_avg_w):1; print_write?printf(" +Max size (kB) |"):1; print_write?printa("%@10d |", @all_io_size_max_w):1; print_write?printa("%@10d |", @srch_io_size_max_w):1; print_write?printa("%@10d |", @mod_io_size_max_w):1; print_write?printa("%@10d |", @add_io_size_max_w):1; print_write?printa("%@10d |\n", @del_io_size_max_w):1; print_write?printf(" +kB/s |%10d |%10d |%10d |%10d |%10d |\n",this->all_io_size_sum_w/period, srch_io_size_sum_w/period, mod_io_size_sum_w/period, add_io_size_sum_w/period, del_io_size_sum_w/period):1; print_write?printf(" +Avg time (usec) |"):1; print_write?printa("%@10d |", @all_io_time_avg_w):1; print_write?printa("%@10d |", @srch_io_time_avg_w):1; print_write?printa("%@10d |", @mod_io_time_avg_w):1; print_write?printa("%@10d |", @add_io_time_avg_w):1; print_write?printa("%@10d |\n",@del_io_time_avg_w):1; print_write?printf(" +Max time (usec) |"):1; print_write?printa("%@10d |", @all_io_time_max_w):1; print_write?printa("%@10d |", @srch_io_time_max_w):1; print_write?printa("%@10d |", @mod_io_time_max_w):1; print_write?printa("%@10d |", @add_io_time_max_w):1; print_write?printa("%@10d |\n", @del_io_time_max_w):1; print_write?printf(" +%%I/O | %8d%% | %8d%% | %8d%% | %8d%% | %8d%% |\n", this->all_io_time_ratio_w, this->srch_io_time_ratio_w, this->mod_io_time_ratio_w, this->add_io_time_ratio_w, this->del_io_time_ratio_w ):1; print_write?printf(" +%%sync | %8d%% | %8d%% | %8d%% | %8d%% | %8d%% |\n", this->all_sync_ratio_w, this->srch_sync_ratio_w, this->mod_sync_ratio_w, this->add_sync_ratio_w, this->del_sync_ratio_w ):1; /* * I/O Read Output */ print_read?printf("-Read |___________|____%3d%%___|____%3d%%___|____%3d%%___|____%3d%%___|\n",this->srch_io_cnt_ratio_r,this->mod_io_cnt_ratio_r, this->add_io_cnt_ratio_r,this->del_io_cnt_ratio_r):1; print_read?printf(" +Count |%10d |%10d |%10d |%10d |%10d |\n", this->all_io_cnt_r, srch_io_cnt_r, mod_io_cnt_r, add_io_cnt_r, del_io_cnt_r):1; print_read?printf(" +Rate (per sec) |%10d |%10d |%10d |%10d |%10d |\n", this->all_io_cnt_r/period, srch_io_cnt_r/period, mod_io_cnt_r/period, add_io_cnt_r/period, del_io_cnt_r/period):1; print_read?printf(" +Avg size (kB) |"):1; print_read?printa("%@10d |", @all_io_size_avg_r):1; print_read?printa("%@10d |", @srch_io_size_avg_r):1; print_read?printa("%@10d |", @mod_io_size_avg_r):1; print_read?printa("%@10d |", @add_io_size_avg_r):1; print_read?printa("%@10d |\n", @del_io_size_avg_r):1; print_read?printf(" +Max size (kB) |"):1; print_read?printa("%@10d |", @all_io_size_max_r):1; print_read?printa("%@10d |", @srch_io_size_max_r):1; print_read?printa("%@10d |", @mod_io_size_max_r):1; print_read?printa("%@10d |", @add_io_size_max_r):1; print_read?printa("%@10d |\n", @del_io_size_max_r):1; print_read?printf(" +kB/s |%10d |%10d |%10d |%10d |%10d |\n",this->all_io_size_sum_r/period, srch_io_size_sum_r/period, mod_io_size_sum_r/period, add_io_size_sum_r/period, del_io_size_sum_r/period):1; print_read?printf(" +Avg time (usec) |"):1; print_read?printa("%@10d |", @all_io_time_avg_r):1; print_read?printa("%@10d |", @srch_io_time_avg_r):1; print_read?printa("%@10d |", @mod_io_time_avg_r):1; print_read?printa("%@10d |", @add_io_time_avg_r):1; print_read?printa("%@10d |\n",@del_io_time_avg_r):1; print_read?printf(" +Max time (usec) |"):1; print_read?printa("%@10d |", @all_io_time_max_r):1; print_read?printa("%@10d |", @srch_io_time_max_r):1; print_read?printa("%@10d |", @mod_io_time_max_r):1; print_read?printa("%@10d |", @add_io_time_max_r):1; print_read?printa("%@10d |\n", @del_io_time_max_r):1; print_read?printf(" +%%I/O | %8d%% | %8d%% | %8d%% | %8d%% | %8d%% |\n", this->all_io_time_ratio_r, this->srch_io_time_ratio_r, this->mod_io_time_ratio_r, this->add_io_time_ratio_r, this->del_io_time_ratio_r ):1; print_read?printf(" +%%sync | %8d%% | %8d%% | %8d%% | %8d%% | %8d%% |\n", this->all_sync_ratio_r, this->srch_sync_ratio_r, this->mod_sync_ratio_r, this->add_sync_ratio_r, this->del_sync_ratio_r ):1; /* * I/O Total Output */ printf("-Total |___________|____%3d%%___|____%3d%%___|____%3d%%___|____%3d%%___|\n",this->srch_io_ratio,this->mod_io_ratio, this->add_io_ratio,this->del_io_ratio); printf(" +Count |%10d |%10d |%10d |%10d |%10d |\n", this->all_io_cnt, this->srch_io_cnt, this->mod_io_cnt, this->add_io_cnt, this->del_io_cnt); printf(" +Rate (per sec) |%10d |%10d |%10d |%10d |%10d |\n", this->all_io_cnt/period, this->srch_io_cnt/period, this->mod_io_cnt/period, this->add_io_cnt/period, this->del_io_cnt/period); printf(" +Avg size (kB) |"); printa("%@10d |", @all_io_size_avg); printa("%@10d |", @srch_io_size_avg); printa("%@10d |", @mod_io_size_avg); printa("%@10d |", @add_io_size_avg); printa("%@10d |\n", @del_io_size_avg); printf(" +Max size (kB) |"); printa("%@10d |", @all_io_size_max); printa("%@10d |", @srch_io_size_max); printa("%@10d |", @mod_io_size_max); printa("%@10d |", @add_io_size_max); printa("%@10d |\n", @del_io_size_max); printf(" +kB/s |%10d |%10d |%10d |%10d |%10d |\n",this->all_io_size_sum/period, this->srch_io_size_sum/period, this->mod_io_size_sum/period, this->add_io_size_sum/period, this->del_io_size_sum/period); printf(" +Avg time (usec) |"); printa("%@10d |", @all_io_time_avg); printa("%@10d |", @srch_io_time_avg); printa("%@10d |", @mod_io_time_avg); printa("%@10d |", @add_io_time_avg); printa("%@10d |\n",@del_io_time_avg); printf(" +Max time (usec) |"); printa("%@10d |", @all_io_time_max); printa("%@10d |", @srch_io_time_max); printa("%@10d |", @mod_io_time_max); printa("%@10d |", @add_io_time_max); printa("%@10d |\n", @del_io_time_max); printf(" +%%I/O | %8d%% | %8d%% | %8d%% | %8d%% | %8d%% |", this->all_io_time_ratio, this->srch_io_time_ratio, this->mod_io_time_ratio, this->add_io_time_ratio, this->del_io_time_ratio ); /* * Clean up */ this->all_io_ratio = 0; this->srch_io_ratio = 0; this->mod_io_ratio = 0; this->add_io_ratio = 0; this->del_io_ratio = 0; this->all_ldap_time = 0; this->all_sync_ratio = 0; this->all_sync = 0; this->all_async = 0; this->all_syncasync = 0; this->srch_syncasync = 0; this->srch_sync_ratio = 0; this->mod_syncasync = 0; this->mod_sync_ratio = 0; this->add_syncasync = 0; this->add_sync_ratio = 0; this->del_syncasync = 0; this->del_sync_ratio = 0; this->all_ldap_cnt = 0; this->srch_ldap_ratio = 0; this->mod_ldap_ratio = 0; this->add_ldap_ratio = 0; this->del_ldap_ratio = 0; this->all_io_time_r = 0; this->all_io_time_w = 0; this->all_io_cnt_r = 0; this->srch_io_cnt_ratio_r = 0; this->mod_io_cnt_ratio_r = 0; this->add_io_cnt_ratio_r = 0; this->del_io_cnt_ratio_r = 0; this->all_io_cnt_w = 0; this->srch_io_cnt_ratio_w = 0; this->mod_io_cnt_ratio_w = 0; this->add_io_cnt_ratio_w = 0; this->del_io_cnt_ratio_w = 0; this->all_io_cnt = 0; this->srch_io_cnt = 0; this->mod_io_cnt = 0; this->add_io_cnt = 0; this->del_io_cnt = 0; this->srch_io_ratio = 0; this->mod_io_ratio = 0; this->add_io_ratio = 0; this->del_io_ratio = 0; this->all_io_time_ratio_r = 0; this->srch_io_time_ratio_r= 0; this->mod_io_time_ratio_r = 0; this->add_io_time_ratio_r = 0; this->del_io_time_ratio_r = 0; this->all_io_time_ratio_w = 0; this->srch_io_time_ratio_w= 0; this->mod_io_time_ratio_w = 0; this->add_io_time_ratio_w = 0; this->del_io_time_ratio_w = 0; this->all_io_size_sum_r = 0; this->all_io_size_sum_w = 0; /*clobber the data between two cycles */ trunc(@all_ldap_avg); trunc(@all_ldap_max); trunc(@all_io_size_avg_r); trunc(@all_io_size_avg_w); trunc(@all_io_size_max_r); trunc(@all_io_size_max_w); trunc(@all_io_time_avg_r); trunc(@all_io_time_avg_w); trunc(@all_io_time_max_r); trunc(@all_io_time_max_w); trunc(@srch_ldap_max); trunc(@srch_ldap_avg); trunc(@srch_io_time_max_r); trunc(@srch_io_time_max_w); trunc(@srch_io_time_avg_r); trunc(@srch_io_time_avg_w); trunc(@srch_io_size_max_r); trunc(@srch_io_size_max_w); trunc(@srch_io_size_avg_r); trunc(@srch_io_size_avg_w); trunc(@mod_ldap_max); trunc(@mod_ldap_avg); trunc(@mod_io_time_max_r); trunc(@mod_io_time_max_w); trunc(@mod_io_time_avg_r); trunc(@mod_io_time_avg_w); trunc(@mod_io_size_max_r); trunc(@mod_io_size_max_w); trunc(@mod_io_size_avg_r); trunc(@mod_io_size_avg_w); trunc(@add_ldap_max); trunc(@add_ldap_avg); trunc(@add_io_time_max_r); trunc(@add_io_time_max_w); trunc(@add_io_time_avg_r); trunc(@add_io_time_avg_w); trunc(@add_io_size_max_r); trunc(@add_io_size_max_w); trunc(@add_io_size_avg_r); trunc(@add_io_size_avg_w); trunc(@del_ldap_max); trunc(@del_ldap_avg); trunc(@del_io_time_max_r); trunc(@del_io_time_max_w); trunc(@del_io_time_avg_r); trunc(@del_io_time_avg_w); trunc(@del_io_size_max_r); trunc(@del_io_size_max_w); trunc(@del_io_size_avg_r); trunc(@del_io_size_avg_w); } profile-1sec / prints == maxcount / { exit(0); } /* * Cleanup for Ctrl-C */ dtrace:::END { /* Global variables de-initialization */ /* the DTrace program is too big if I implement a trunc for every aggregation in the script here */ } ' ${pid} 2> /dev/null exit 0;