A Question Regarding Timers and Output

Hi there. I am fairly new to scripting in BASH so please forgive my clumsy syntax and analogy as I try to explain what I am trying to accomplish.

I have a list of mundane functions that I currently call from a script file. What I wish to do is to accurately record into a log file the times that each step is taking to allow for some analysis and planning of resources as I utilize the script for more activity on more machines. I have been directed to look at the time function but find that it's usefulness is very limited if I wish to contain all of my data to one output file. Please see the example below of my understanding of how to utilize it.

/usr/bin/time -o 'output file path' 'command to execute'

However, what I wish to see is something more like the result from what code I was able to cobble together below.

LOGFILE=completed_work_`date +%F`.log
my_run_start_date=`date +%F`
my_run_start_time=`date +%H:%M`
    echo Run began on $my_run_start_date at $my_run_start_time >> $LOGFILE
master_start=`date +%s`
# do the work here
step_start=`date +%s` #timer start
    echo 1 Do some work here.;echo 1 This is what we did here. >> $LOGFILE
step_end=`date +%s` #timer end
    step_diff=`expr $step_end - $step_start`
    echo How long it took to do it : $step_start - $step_end = $step_diff >> $LOGFILE
# we can do this as many times as we need to
step_start=`date +%s` #timer start
    echo 2 Do some work here.;echo 2 This is what we did here. >> $LOGFILE
step_end=`date +%s` #timer end
    step_diff=`expr $step_end - $step_start`
    echo How long it took to do it : $step_start - $step_end = $step_diff >> $LOGFILE
# end of the work section
master_end=`date +%s`
master_diff=`expr $master_end - $master_start`
my_run_end_date=`date +%F`
my_run_end_time=`date +%H:%M`
    echo Run ended on $my_run_end_date at $my_run_end_time >> $LOGFILE
    echo Start=$master_start : End=$master_end >> $LOGFILE
master_time_elapsed=`expr $master_diff / 3600`
    echo Elapsed time = $master_time_elapsed hours >> $LOGFILE

Can anyone please assist me with a more concise and/or elegant approach to accomplishing this within a mixed Unix/Linux environment?

Could you show what you actually want, instead of code you don't want?

The script relies heavily on date +%s which is not valid in unix. Please describe what value you expect from this command.

Writing totally portable code for unix and Linux is extremely difficult and nigh on impossible if you start with bash on a random Linux computer with extensions to the "date" command. Please be a bit more specific about what Operating Systems and versions are involved here and what is the preferred Bourne-type Shell on each Operating System.

You have to find the lowest common denominator and work with that. If they are ALL modern computers, the current Posix standard is recommended by many posters here.

Thanks for your reply. I didn't say, "I don't want the code." The code actually works quite well. I want to know if there is a better or more elegant way to go about doing what I did in the code I listed. I've made a quick edit so it runs as it stands and gives you the example output you requested...

$ cat completed_work_2012-04-04.log

Run began on 2012-04-04 at 15:53
1 This is what we did here.
How long it took to do it : 1333569215 - 1333569215 = 0
2 This is what we did here.
How long it took to do it : 1333569215 - 1333569215 = 0
Run ended on 2012-04-04 at 15:53
Start=1333569215 : End=1333569215
Elapsed time = 0 hours

---------- Post updated at 04:19 PM ---------- Previous update was at 03:58 PM ----------

Please see the above post.

After reviewing the requirements to answer your question, the heavy lifting is all being done from Red Hat machines.

Except for not being sure of what your definition of 'modern' is, I understand what your saying and am already working from that approach.

Alright, I had a bit of a go and here are a couple of ideas you could try..

As others have noted: date '%s' is a GNU extension and does not function on many platform. Your best bet may be to use perl :

perl -e 'print time'

of which a basic version is available on many platforms these days
You could put that into a function, since you are using it a lot:

stamp(){
  perl -e 'print time'
}

The nice thing about this is, that you only need to replace the content of the function if you wish to use another method to obtain epoch time, for example with date '%s'

The other thing that you can change is to use a general redirection that also includes stderr (Or maybe at a later stage you wish to only use std err):

exec >> "$LOGFILE" 2>&1

Further I replaced backticks everywhere with $(..) and expr statement with $(( ... ))
This leads to this script:

LOGFILE=completed_work_$(date +%F).log
stamp(){
  perl -e 'print time'
}
exec >> "$LOGFILE" 2>&1
my_run_start_date=$(date +%F)
my_run_start_time=$(date +%H:%M)

echo "Run began on $my_run_start_date at $my_run_start_time"
master_start=$(stamp)
# do the work here

step_start=$(stamp) #timer start
echo 1 Do some work here.;echo 1 This is what we did here.
step_end=$(stamp)   #timer end
step_diff=$((step_end - step_start))
echo How long it took to do it : $step_start - $step_end = $step_diff

# we can do this as many times as we need to
step_start=$(stamp) #timer start
echo 2 Do some work here.;echo 2 This is what we did here.
step_end=$(stamp)   #timer end
step_diff=$((step_end - step_start))
echo How long it took to do it : $step_start - $step_end = $step_diff

# end of the work section
master_end=$(stamp)
master_diff=$((master_end - master_start))
my_run_end_date=`date +%F`
my_run_end_time=`date +%H:%M`
echo "Run ended on $my_run_end_date at $my_run_end_time"
echo "Start=$master_start : End=$master_end"
master_time_elapsed=$((master_diff / 3600))
echo "Elapsed time = $master_time_elapsed hours"

There is a bit of repetition for every step. You could reduce that for example like this:

stamp(){
  perl -e 'print time'
}

timer(){
  case $1 in
    start) TS=$(stamp) ;;
    stop)  echo "How long it took to do it : $(( $(stamp) - TS )) seconds" ;;
  esac
}

LOGFILE=completed_work_$(date +%F).log

exec >> "$LOGFILE" 2>&1

echo "Run began on $(date '+%F at %H:%M')"
master_start=$(stamp)
# do the work here

timer start
echo "1 Do some work here." ;echo "1 This is what we did here."
timer stop

# we can do this as many times as we need to
timer start
echo "2 Do some work here.";echo "2 This is what we did here."
timer stop

# end of the work section
master_end=$(stamp)
master_diff=$((master_end - master_start))
master_time_elapsed=$((master_diff / 3600))
echo "Run ended on $(date '+%F at %H:%M')"
echo "Start=$master_start : End=$master_end"
echo "Elapsed time = $master_time_elapsed hours"

And so forth... Apart from the call to perl this is all POSIX shell code...

1 Like

@Tenuous
If all the systems are Red Hat Linux, shell script compatibility with unix is academic.
The date command is not part of bash but is key to your original script.
Scrutinizer's approch with Perl is much better because of modern Perl's support for date manipulation.

Beautiful! I will be diving in deeper tomorrow and will incoporate your suggestions.

---------- Post updated at 05:55 PM ---------- Previous update was at 05:53 PM ----------

@methyl it's a mish mash of alot of systems. More than 90% are Red Hat or Solaris. It's a new job for me and I am learning alot of stuff as I go. Thanks for your input though. It is invaluable to fellows such as myself.

Ow, if there is Solaris you'll probably want to use the utilities that are in /usr/xpg4/bin instead of the regular ones and try the script with this shell:

/usr/xpg4/bin/sh

Which is supposed to be a POSIX compliant shell as opposed to /bin/sh

If your happy with times down to the second why not use the bash SECONDS env var:

START=$SECONDS
echo Do some work here.;echo This is what we did here.
echo "Work took $((SECONDS-START)) secs"

$SECONDS also works in ksh and the Posix Shell.
It's the number of seconds since the Shell started.

I don't know about POSIX:

$ bash
$ echo $SECONDS
7
$ ksh
$ echo $SECONDS
5.652
$ dash
$ echo $SECONDS

$

@Scrutinizer
I see what you mean. ksh93 is giving time with decimal places, whereas older ksh gives whole seconds.
For consistency in a portable script we'd have to round the given figure (or just throw away the decimal places).

echo $SECONDS|cut -f1 -d'.'

The script should also test the first value of $SECONDS to make sure that the Shell has provided a value and exit if the Shell does not have the value (e.g. for original Bourne Shell) recommend that the script is run with a modern Shell.

Are there computers with just dash ? Does dash have any other useful variable?

yes, but also dash, which is a no-thrills POSIX compliant shell, does not offer $SECONDS, and I cannot find it in the POSIX specifications either. So I think it is a bash/ksh thing and not a POSIX shell thing. So I think this will maybe also not be present in /usr/xpg4/bin/sh and if it is then it should be considered an extension.

--
Sidenote: The decimal places to $SECONDS are available in ksh93, but I don't think we need to cut off the decimal places, since ksh93 can do full floating point arithmetic, so all it does is give us some extra precision, no?

Looks like another mistake in the Posix specification (even though all the Posix-compliant Shells I have do set $SECONDS).

The Posix specification lists $SECONDS as if it is a reserved variable but then does not describe the variable later on the page.
Environment Variables

I don't think this is a mistake by the POSIX specification.

On that page I only see $SECONDS in the table that says:

So on this page they do list $SECONDS as a reserved POSIX variable, but just that one should use that name, since it is often used by some command interpreters and applications

If a shell is POSIX compliant and it has a feature, then this does not mean it is a POSIX feature... The only exception I know for which this is almost true is dash, which tries to offer only the POSIX specification and not much else..

My interpretation of that has always been that only the variables in the 2 later sections are actually defined by POSIX - the others are just variables you should avoid declaring yourself (most of which are not listed in the later sections, not just SECONDS).

FWIW, I found another way that in practice seems to get epoch time, which is :

awk 'BEGIN {srand; print srand}'

awk needs to be POSIX compliant so on Solaris that would need to be /usr/xpg4/bin/awk.

This works because srand() uses time of day as the feed and the second time it is called it returns the previous feed. The POSIX specification does not explicitly say that srand() should use epoch time, however, and it supposedly only works in the right way because POSIX awk was based on nawk, which did it that way...

awk: Arithmetic Functions

St�phane Chazelas in news://comp.unix.shell

(there was also a method based on pax but that seems really far fetched)

ksh93, version h and up:

stamp() {
  printf '%(%s)T' now
}

no external program required...