Skip to main content

By clicking Submit, you agree to the developerWorks terms of use.

The first time you sign into developerWorks, a profile is created for you. Select information in your profile (name, country/region, and company) is displayed to the public and will accompany any content you post. You may update your IBM account at any time.

All information submitted is secure.

  • Close [x]

The first time you sign in to developerWorks, a profile is created for you, so you need to choose a display name. Your display name accompanies the content you post on developerworks.

Please choose a display name between 3-31 characters. Your display name must be unique in the developerWorks community and should not be your email address for privacy reasons.

By clicking Submit, you agree to the developerWorks terms of use.

All information submitted is secure.

  • Close [x]

Select a language:

  • Close [x]
  • Close [x]

ksh_timer

An interface to evaluate function execution time in shell script in each function or in user-defined sections

Alexandre Blancke (ablancke@fr.ibm.com), AIX Development Support Specialist, IBM France
Photo of Alexandre Blancke
Alexandre Blancke is an IBM AIX Development Support Specialist on AIX. He is currently supporting commands (including ksh), libraries, and security on AIX. He has 22 years of experience in administering and supporting the AIX operating system and is recognized as an IBM Certified Product Services Professional.

Summary:  ksh_timer helps ksh script developers or administrators to find out quickly and with minimal change in their script, what functions or user-defined sections are time consuming. By default, ksh_timer will time the overall script and each function defined and used in the script. Users can define additional sections of the scripts they need to be timed.

Date:  28 Nov 2012
Level:  Intermediate
PDF:  A4 and Letter (244 KB | 11 pages)Get Adobe® Reader®
Also available in:   Chinese

Activity:  5722 views
Comments:  

Introduction

ksh_timer is designed to help administrators or developers of ksh or ksh93 scripts with calculating the time spent on each function or user-defined sections of their shell script.

The following points define the functionality of ksh_timer:

  • Functions that are called in the script are timed automatically when the script is ran from ksh_timer
  • User can define sections in the core of the script using ##KTB <section_name> (beginning of the section) and ##KTE <section_name> (end of the section)
  • Times given are total elapsed times, not used times.
  • The output will include the « Main » time, which is the overall elapsed time of the script.
  • It will also output unaccounted time, which is time spent in the « Main » section outside the functions or user-defined sections.
  • Unaccounted time also includes the ksh_timer overhead induced by the calculation functions.
  • ksh_timer supports the execution of both: ksh and ksh93 scripts.
  • Usage: ksh_timer [-D] [-c] [-?] [-s] [script name arguments ...]
    • -D puts ksh_timer in debug mode.
    • -c retains the raw output file (ksh_timer.<script_name>.<pid>.out). Normally, this is deleted after execution.
    • -s [script name arguments ...] script file name and script required arguments.
    • -? print usage.

Important notice

This interface (ksh_timer) is provided as a convenience to users. The information contained in this article explains about the usage and functions of ksh_timer with a sample program and the tool are provided as is, with no warranty or support.

The tool has been tested on IBM® AIX® 5.3,6.1 and 7.1 releases. ksh_timer might be used with other operating systems, and to achieve this, the ksh_timer_c executable must be rebuild for that operating system using the source code provided in the Installation section of this article.

Overview

When starting, the ksh_timer reads the input script provided on the command line and builds the following three files (source file, timer file, and exec file) from it.

  • The source file contains the original function definitions, and it will be sourced in the exec file.
  • The timer file contains wrapper functions that includes timing code and calls to the original functions included in the source file. The timer file is also sourced in the exec file. In the following example, the original function f1 is renamed as f1_orig in the source file, and f1 in the timer file has a timing code embracing the f1_orig function so that we can get the time spent in the original f1 function.
  • The exec file sources the source file and the timer file and contains the original main code and the timer code for any user-defined sections.

When these files have been built, ksh_timer runs the built exec file. While running the original code, it computes the elapsed times from functions and user-defined sections, and writes these times in the output file. When execution is completed, the output file is parsed and function names, indentation, number of iterations and minimum, maximum, average and total times for these functions or sections are computed and displayed on the screen.

  • Using the following input script sample: ksh_timer.test_pres

#! /usr/bin/ksh
f1()
{
echo "hello"
}
#Main
##KTB user_defined_section
sleep 1
f1
##KTE user_defined_section
sleep 2
f1

  • source file: Contains the original function definitions

f1_orig()
{
echo "hello"
}

  • timer file: Contains wrapper functions that include timing code and calls to original functions

function f1
{
time1f1=`/home/albl/ksh_timer/ksh_timer_c`
ksh_timer_add_func f1
f1_orig $*
f1_orig_rc=$?
time2f1=`/home/albl/ksh_timer/ksh_timer_c`
let " time3f1 = $time2f1 - $time1f1"
print "$indent1:$indent2:$indent3:$indent4:$indent5:$time3f1" >&9
ksh_timer_remove_func f1
return $f1_orig_rc
}

  • exec file: Contains the original code and timer code for any user-defined sections

. ./ksh_timer.test_pres.413914.source
. ./ksh_timer.test_pres.413914.timer
time1user_defined_section=`/home/albl/ksh_timer/ksh_timer_c`
ksh_timer_add_func user_defined_section
sleep 1
f1
time2user_defined_section=`/home/albl/ksh_timer/ksh_timer_c`
let "time3user_defined_section=$time2user_defined_section-$time1user_defined_section"
print "$indent1:$indent2:$indent3:$indent4:$indent5:$time3user_defined_section" >&9
ksh_timer_remove_func user_defined_section
sleep 2
f1

  • Running the sample gives the following output:

$ ./ksh_timer -s ./sample
----------------------Start of sample output--------------------------------
hello
hello
----------------------End of sample output--------------------------------
------------------------------------------------------------------------------------------
|    Function   |     Minimum       |     Maximum       |   Average  |       Total       |
|               +-------------------+-------------------+------------+-------------------|
|   or Section  |iter.#|   time     |iter.#|   time     |   time     |#iter.|   time     |
|---------------+------+------------+------+------------+------------+------+------------|
|Main           |                                                           |0m03.092834s|
|---------------+------+------------+------+------------+------------+------+------------|
|-user_defined|     1|0m01.027853s|     1|0m01.027853s|0m01.027853s|     1|0m01.027853s|
|--f1           |     1|0m00.003143s|     1|0m00.003143s|0m00.003143s|     1|0m00.003143s|
|-f1            |     1|0m00.002652s|     1|0m00.002652s|0m00.002652s|     1|0m00.002652s|
|---------------------------------------------------------------------------+------------|
|-Unaccounted   |                                                           |0m02.062329s|
------------------------------------------------------------------------------------------

So as we can see, the user_defined_section was called one time, and the f1 function was called one time inside the user_defined_section and one time in the main section of the script. user_defined_section took a little more than one second, which is mainly the time for the sleep 1 plus the time of f1 functions. Unaccounted is about two seconds, that is mainly the time for the sleep 2 that is outside of any section or function, plus the overhead needed by the ksh_timer needed to calculate the times.

The timer code for user-defined sections is kept inline with the execution code to keep the ability to use arguments passed to the shell script inside those sections. The output of ksh_timer will be sent to the screen in an easily readable table format (examples are given later). If you choose to send the output to a file, the output for each iteration will be in the following format: 

Main:indent1:…:indent9:>time_spent<

(Output for indent 1 to 9 will either be the name of the function being called, or empty if the function depth does not go that deep). For example:

Main:user_defined_section:f1:::::::3143

(We spent 3143 microseconds in f1 function, which was called by user_defined, which in turn was called from the main section)

Installing ksh_timer

  • You can download ksh_timer from the Download section.
  • To install, extract the ksh_timer.tar file in to any directory.
  • You may want to edit your original script that you are timing to add user-defined sections with « ##KTB <section_name> » and « ##KTE <section_name> definitions.
  • To execute, run ./ksh_timer –s <your_script>
  • Output will be sent to the screen; if –c is specified, raw data output will be sent to a file called ksh_timer.<script name>.<PID>.out
  • If running on a non AIX system, the ksh_timer_c code need to be rebuilt from the following ksh_timer_c.c source code:

#include <stdio.h>
#include <sys/time.h>
main()
{
struct timeval Tp;
gettimeofday(&Tp,NULL);
printf("%lld\n",(unsigned long long)((Tp.tv_sec*1000000)+Tp.tv_usec));
}

Usage examples

Imagine you have the following script named script_test_vmm, and you want to evaluate the time that vmm_test2 takes when it is called after each call to rmss. You also want to evaluate the time it takes for each rmss. 

#! /usr/bin/ksh
integer i=0
rmss -c 950
while [[ $i -lt 3 ]]
  do
  /tmp/ksh_timer/test_vmm2
  i=i+1
  done

rmss -c 1450
i=0
while [[ $i -lt 3 ]]
  do
  /tmp/ksh_timer/test_vmm2
  i=i+1
  done

  • Step 1: Edit your script_test_vmm script and add the user-defined sections using appropriate ##KTB and matching ##KTE to delimit your user-defined sections, as shown in the following code:

#! /usr/bin/ksh
integer i=0
##KTB rmss950
rmss -c 950
while [[ $i -lt 3 ]]
  do
##KTB vmm_test2
  /tmp/ksh_timer/test_vmm2
  i=i+1
##KTE vmm_test2
  done
##KTE rmss950
##KTB rmss1450
rmss -c 1450
i=0
while [[ $i -lt 3 ]]
  do
##KTB vmm_test2
  /tmp/ksh_timer/test_vmm2
  i=i+1
##KTE vmm_test2
  done
##KTE rmss1450

  • Step 2: Run the previous script using ksh_timer -s script_test_vmm.

----------------------Start of script_test_vmm output--------------------------------
Simulated memory size changed to 950 Mb.
Simulated memory size changed to 1450 Mb.
----------------------End of script_test_vmm output--------------------------------
------------------------------------------------------------------------------------------
|    Function   |     Minimum       |     Maximum       | Average    |     Total         |
|               +-------------------+-------------------+------------+-------------------|
|   or Section  |iter.#|   time     |iter.#|   time     |  time      |#iter.|  time      |
|---------------+------+------------+------+------------+------------+------+------------|
|Main           |                                                           |1m36.578814s|
|---------------+------+------------+------+------------+------------+------+------------|
|-rmss950      |     1|1m02.120269s|     1|1m02.120269s|1m02.120269s|     1|1m02.120269s|
|--vmm_test2   |     3|0m16.813174s|     1|0m23.461610s|0m20.654322s|     3|1m01.962968s|
|-rmss1450     |     1|0m34.416279s|     1|0m34.416279s|0m34.416279s|     1|0m34.416279s|
|--vmm_test2   |     2|0m11.382110s|     3|0m11.427596s|0m11.402585s|     3|0m34.207757s|
|---------------+-----------------------------------------------------------+------------|
|-Unaccounted   |                                                           |0m00.042266s|
------------------------------------------------------------------------------------------

As another example, we ran ksh_timer on the mksysb script. The mksysb script was edited to add a user-defined section named backup_files_in_list. We can see in the following output that not only the backup_files_in_list section was timed, but also any function defined in the mksysb script. Looking at the output, we can easily find that the maximum time spent by the mksysb script is in backup_files_in_list, consuming 1m33.029798s out of 1m49.140307s for the entire script. 

# ksh_timer -s ./mksysb -i /dev/null
----------------------Start of mksysb output--------------------------------
Creating information file (/image.data) for rootvg.
Creating list of files to back up
Backing up 56510 files........
56510 of 56510 files backed up (100%)0512-038 mksysb: Backup Completed Successfully.
----------------------End of mksysb output--------------------------------
------------------------------------------------------------------------------------------
|    Function   |    Minimum        |    Maximum        |    Average |     Total         |
|               +-------------------+-------------------+------------+-------------------|
|   or Section  |iter.#|  time      |iter.#|  time      |  time      |#iter.|  time      |
|---------------+------+------------+------+------------+------------+------+------------|
|Main           |                                                           |1m49.140307s|
|---------------+------+------------+------+------------+------------+------+------------|
|-set_up_environ|     1|0m00.048720s|     1|0m00.048720s|0m00.048720s|     1|0m00.048720s|
|--fail_if_wpar |     1|0m00.005507s|     1|0m00.005507s|0m00.005507s|     1|0m00.005507s|
|--getoptions   |     1|0m00.012926s|     1|0m00.012926s|0m00.012926s|     1|0m00.012926s|
|-create_temp_di|     1|0m00.007239s|     1|0m00.007239s|0m00.007239s|     1|0m00.007239s|
|-if_rootvg     |     1|0m00.153775s|     1|0m00.153775s|0m00.153775s|     1|0m00.153775s|
|--tddupdate    |     1|0m00.070964s|     1|0m00.070964s|0m00.070964s|     1|0m00.070964s|
|--Get_Rootvg_IS|     1|0m00.042464s|     1|0m00.042464s|0m00.042464s|     1|0m00.042464s|
|--tsddupdate   |     1|0m00.027835s|     1|0m00.027835s|0m00.027835s|     1|0m00.027835s|
|-if_device     |     1|0m00.014855s|     1|0m00.014855s|0m00.014855s|     1|0m00.014855s|
|-if_image_data |     1|0m05.132797s|     1|0m05.132797s|0m05.132797s|     1|0m05.132797s|
|-make_backup_da|     1|0m00.350696s|     1|0m00.350696s|0m00.350696s|     1|0m00.350696s|
|--get_backup_si|     1|0m00.031814s|     1|0m00.031814s|0m00.031814s|     1|0m00.031814s|
|---get_stanza_d|     1|0m00.019862s|     1|0m00.019862s|0m00.019862s|     1|0m00.019862s|
|-run_the_exclud|     1|0m05.697004s|     1|0m05.697004s|0m05.697004s|     1|0m05.697004s|
|-backup_files|     1|1m33.029798s|     1|1m33.029798s|1m33.029798s|     1|1m33.029798s|
|--kill_pid     |     1|0m02.015270s|     2|0m02.020543s|0m02.017906s|     2|0m04.035813s|
|-done_backup   |     1|0m00.016388s|     1|0m00.016388s|0m00.016388s|     1|0m00.016388s|
|--kill_pid     |     1|0m02.015329s|     1|0m02.015329s|0m02.015329s|     1|0m02.015329s|
|---------------------------------------------------------------------------+------------|
|-Unaccounted   |                                                           |0m04.689035s|
------------------------------------------------------------------------------------------

  • Using that second example, you can also easily find if you have repeating calls to a function or a section, or if any call is taking longer than the others. Here we see, for example, setcmd was called 44 times from init_pos_cmds and we can see that maximum, minimum, and average times are quite constant.

The third example using the result of ksh_timer –s ./rpm_share –i shows the use of the indentation in ksh_timer and various information that we can find on the output. For example, here we can find that:

  • setcmd is called in from two other functions: 44 times from init_pos_cmd and 5 times from init_sys_vars.
  • Checking the minimum, maximum, and average times, we can see that there is not much delta upon different iterations of setcmd, either it is called from init_pos_cmd or from init_sys_vars

# ksh_timer –s ./rpm_share –i …
-----------------Start of rpm_share output--------------------------------
-----------------End of rpm_share output--------------------------------
------------------------------------------------------------------------------------------
|    Function   |    Minimum        |     Maximum       |  Average   |       Total       |
|               +-------------------+-------------------+------------+-------------------|
|   or Section  |iter.#|  time      |iter.#|  time      |  time      |#iter.|  time      |
|---------------+------+------------+------+------------+------------+------+------------|
|Main           |                                                           |0m01.506875s|
|---------------+------+------------+------+------------+------------+------+------------|
|-init_baselib  |     1|0m00.366488s|     1|0m00.366488s|0m00.366488s|     1|0m00.366488s|
|--init_pos_cmd |     1|0m00.252172s|     1|0m00.252172s|0m00.252172s|     1|0m00.252172s|
|---setcmd    |    9|0m00.002762s|  5|0m00.002922s|0m00.002825s|44|0m00.124313s|
|--init_sys_vars|     1|0m00.056660s|     1|0m00.056660s|0m00.056660s|     1|0m00.056660s|
|---setcmd    |    5|0m00.002860s|  2|0m00.002929s|0m00.002879s| 5|0m00.014397s|
|---init_libinst|     1|0m00.014667s|     1|0m00.014667s|0m00.014667s|     1|0m00.014667s|
|----inc        |     1|0m00.008601s|     1|0m00.008601s|0m00.008601s|     1|0m00.008601s|
|-----isnum     |     1|0m00.002853s|     1|0m00.002853s|0m00.002853s|     1|0m00.002853s|
|--ck_exp_fs    |     1|0m00.035973s|     1|0m00.035973s|0m00.035973s|     1|0m00.035973s|
|---isYorN      |     1|0m00.002837s|     1|0m00.002837s|0m00.002837s|     1|0m00.002837s|
|---whichfs     |     1|0m00.004191s|     1|0m00.004191s|0m00.004191s|     1|0m00.004191s|
|---getfsfree   |     1|0m00.009434s|     1|0m00.009434s|0m00.009434s|     1|0m00.009434s|
|----isnum      |     1|0m00.002462s|     1|0m00.002462s|0m00.002462s|     1|0m00.002462s|
|---isnum       |     1|0m00.002952s|     1|0m00.002952s|0m00.002952s|     1|0m00.002952s|
|--check_dir    |     1|0m00.002905s|     1|0m00.002905s|0m00.002905s|     1|0m00.002905s|
|-ck_exp_fs     |     1|0m00.036059s|     2|0m00.036169s|0m00.036114s|     2|0m00.072228s|
|--isYorN       |     2|0m00.002875s|     1|0m00.002881s|0m00.002878s|     2|0m00.005756s|
|--whichfs      |     2|0m00.004239s|     1|0m00.004263s|0m00.004251s|     2|0m00.008502s|
|--getfsfree    |     1|0m00.009377s|     2|0m00.009382s|0m00.009379s|     2|0m00.018759s|
|---isnum       |     2|0m00.002425s|     1|0m00.002444s|0m00.002434s|     2|0m00.004869s|
|--isnum        |     2|0m00.003008s|     1|0m00.003030s|0m00.003019s|     2|0m00.006038s|
|-set_time_token|     1|0m00.009403s|     1|0m00.009403s|0m00.009403s|     1|0m00.009403s|
…snip…
|--check_fdup_sp|     1|0m00.098203s|     1|0m00.098203s|0m00.098203s|     1|0m00.098203s|
|---getfsize    |     1|0m00.018850s|     1|0m00.018850s|0m00.018850s|     1|0m00.018850s|
|----check_file |     1|0m00.002347s|     1|0m00.002347s|0m00.002347s|     1|0m00.002347s|
|----isnum      |     1|0m00.002366s|     1|0m00.002366s|0m00.002366s|     1|0m00.002366s|
|---whichfs     |     1|0m00.004378s|     1|0m00.004378s|0m00.004378s|     1|0m00.004378s|
|---addbuf      |     1|0m00.021044s|     1|0m00.021044s|0m00.021044s|     1|0m00.021044s|
|----isnum      |     3|0m00.002948s|     2|0m00.002962s|0m00.002956s|     3|0m00.008868s|
|---ck_exp_fs   |     1|0m00.036967s|     1|0m00.036967s|0m00.036967s|     1|0m00.036967s|
|----isYorN     |     1|0m00.002998s|     1|0m00.002998s|0m00.002998s|     1|0m00.002998s|
|----whichfs    |     1|0m00.004340s|     1|0m00.004340s|0m00.004340s|     1|0m00.004340s|
|----getfsfree  |     1|0m00.009691s|     1|0m00.009691s|0m00.009691s|     1|0m00.009691s|
|-----isnum     |     1|0m00.002514s|     1|0m00.002514s|0m00.002514s|     1|0m00.002514s|
|----isnum      |     1|0m00.002964s|     1|0m00.002964s|0m00.002964s|     1|0m00.002964s|
|--cleanup      |     2|0m00.002960s|     1|0m00.007511s|0m00.005235s|     2|0m00.010471s|
|---------------------------------------------------------------------------+------------|
|-Unaccounted   |                                                           |0m00.141934s|
------------------------------------------------------------------------------------------

Troubleshooting

If any problems are found using the ksh_timer tool, then you need to run:

  • ./ksh_timer –D –c –s <your_script> <script.debug.out 2>&1
  • Send the following files to the author :
    • script.debug.out
    • <your_script>
    • The csv file: ksh_timer. <your_script>.<pid>.out

Conclusion

ksh_timer is an easy, simple, and customizable tool that can be used to evaluate the time spent on a script. Running a first pass without modifying the script can already give an idea on the most consuming functions used by the script. If the script does not use functions, or most of the time is spent on the main section of the script, then the user can edit the script and create user-defined sections in the main or even within a function to track down up to one line detail, where the maximum time is spent. The ksh_timer output analysis can show the parts of the code in the user shell script where it spent most of the time. If that part of the script runs another shell script, the user might need to change that code to call that script using ksh_timer to time it. If the called executable is not a shell script, the user needs to use other available tools to time it.


Back to top

Download

DescriptionNameSizeDownload method
ksh_timer toolksh_timer.tar30 KBHTTP

Information about download methods


Resources

Learn

Get products and technologies

  • Evaluate IBM products in the way that suits you best: Download a product trial, try a product online, use a product in a cloud environment, or spend a few hours in the SOA Sandbox learning how to implement Service Oriented Architecture efficiently.

Discuss

About the author

Photo of Alexandre Blancke

Alexandre Blancke is an IBM AIX Development Support Specialist on AIX. He is currently supporting commands (including ksh), libraries, and security on AIX. He has 22 years of experience in administering and supporting the AIX operating system and is recognized as an IBM Certified Product Services Professional.

Close [x]

Report abuse help

Report abuse

Thank you. This entry has been flagged for moderator attention.

Close [x]

Report abuse help

Report abuse

Report abuse submission failed. Please try again later.

Close [x]

developerWorks: Sign in


Need an IBM ID?
Forgot your IBM ID?


Forgot your password?
Change your password

By clicking Submit, you agree to the developerWorks terms of use.

 

The first time you sign into developerWorks, a profile is created for you. Select information in your profile (name, country/region, and company) is displayed to the public and will accompany any content you post. You may update your IBM account at any time.

All information submitted is secure.

Close [x]

Choose your display name

The first time you sign in to developerWorks, a profile is created for you, so you need to choose a display name. Your display name accompanies the content you post on developerWorks.

Please choose a display name between 3-31 characters. Your display name must be unique in the developerWorks community and should not be your email address for privacy reasons.

(Must be between 3 – 31 characters.)

By clicking Submit, you agree to the developerWorks terms of use.

 

All information submitted is secure.

Rate this article

Comments

Back to top

static.content.url=http://www.ibm.com/developerworks/js/artrating/
SITE_ID=1
Zone=AIX and UNIX, Open source
ArticleID=846653
ArticleTitle=ksh_timer
publish-date=11282012

Table of contents

Dig deeper into AIX and UNIX on developerWorks

IBM SmartCloud trial. No charge.

IBM PureSystems on a kaleideoscope background

Unleash the power of hybrid cloud computing today!

Public and private solutions in one trial.

Special offers

On demand demos: An easy way to watch and learn

Get recognized! W Author Program

Cloud Computing resources for IT professionals

Trial software offers

Share this page:

  • Close [x]

Follow developerWorks:

  • Close [x]