How to time how long a bash alias took to execute (solved... maybe?)

Question

I have a few alias' on my Dreadnaught embedded Linux system, some of them have a reasonably long list of jobs to do. I'm trying to improve the efficiency of these task, and trying to time how long each permutation took, so I can confirm which is the quickest permutation.

I've built my scripts up in parts, and found each part worked... but not when they were put together. I'll put the attempts at the end of the question so they don't flood the question out....

However, after hours trying to figure out why it appeared to work in parts but not as a whole, I've discovered that The command substitution is evaluated when you define the alias, not when you execute the it.

How can I create an alias that times itself for several tasks (calls to other alias', calls to system).

I tried using functions instead; equally unsuccessfully.

I tried time, but it doesn't like getting alias' passed to it; and my alias' call many other alias' and system calls, so it's not practical to unpack them.

Is there any way to create a bash alias (or other method that can be called from bash?) that times itself and/or other processes?

Update - possible solution, but looking for any better suggestions?

As I often find, writing out a question on SO makes me carefully explain it, which somehow triggers my head into thinking about alternatives I've not thought of previously. I've just written a bash script that calls the tasks - because it's not using alias' for the time records, it's calling the time functions directly:

#!/bin/bash

echo "== Task 1 Start =="
timerstart1=$(eval 'date +%s')
TimerStartstr1=$(eval 'date -d@$((timerstart1))')
echo "Task 1 started at   $timerstart1 = $TimerStartstr1"

myTask1

timerend1=$(eval 'date +%s')
TimerEndstr1=$(eval 'date -d@$timerend1')
echo "Task 1 completed at $timerend1 = $TimerEndstr1"
duration1=$(($timerend1 - $timerstart1))
echo "=========== Task 1 Complete, took $duration1 =================="


echo "== Task 2 Start =="
timerstart2=$(eval 'date +%s')
TimerStartstr2=$(eval 'date -d@$((timerstart2))')
echo "Task 2 started at   $timerstart2 = $TimerStartstr2"

MyTask2

timerend2=$(eval 'date +%s')
TimerEndstr2=$(eval 'date -d@$timerend2')
echo "Task 2 completed at $timerend2 = $TimerEndstr2"
duration2=$(($timerend2 - $timerstart2))
echo "=========== Task 2 Complete, took $duration2 =================="

echo "Speed improvement = $(($duration1 - $duration2))"

And, for some bonus schadenfreude: my "improved" Task2 actually took longer than the original - 83 seconds vs 70 seconds!

Here's the construction of the job in bits that (mostly) seemed to work on their own:

[user@Dreadnaught log]$ echo ==Start==; timerstart=$(eval 'date +%s'); TimerStartstr=$(eval 'date -d@$((timerstart))'); echo Started at \ \ $timerstart = $TimerStartstr;
==Start==
Started at   1710780061 = Mon Mar 18 16:41:01 GMT 2024
[user@Dreadnaught log]$ timerend=$(eval 'date +%s'); TimerEndstr=$(eval 'date -d@$timerend'); echo Completed at $timerend = $TimerEndstr;
Completed at 1710780075 = Mon Mar 18 16:41:15 GMT 2024
[user@Dreadnaught log]$ echo =========== TestTimerTask Complete, took $(($timerend - $timerstart)) ==================
=========== TestTimerTask Complete, took 14 ==================
[user@Dreadnaught log]$ alias timertest="echo ==Start==; timerstart=$(eval 'date +%s'); TimerStartstr=$(eval 'date -d@$((timerstart))'); echo Started at \ \ $timerstart = $TimerStartstr; read -p 'Waiting for input' >/dev/tty; timerend=$(eval 'date +%s'); TimerEndstr=$(eval 'date -d@$timerend'); echo Completed at $timerend = $TimerEndstr; echo =========== TestTimerTask Complete, took $(($timerend - $timerstart)) =================="
[user@Dreadnaught log]$ timertest
==Start==
-ash: Mar: not found
Started at   1710780061 = Mon Mar 18 16:41:01 GMT 2024
Waiting for input
-ash: Mar: not found
Completed at 1710780075 = Mon Mar 18 16:41:15 GMT 2024
=========== TestTimerTask Complete, took 14 ==================
[user@Dreadnaught log]$ timertest
==Start==
-ash: Mar: not found
Started at   1710780061 = Mon Mar 18 16:41:01 GMT 2024
Waiting for input
-ash: Mar: not found
Completed at 1710780075 = Mon Mar 18 16:41:15 GMT 2024
=========== TestTimerTask Complete, took 14 ==================
[user@Dreadnaught log]$ alias timertest="echo ==Start==; timerstart=$(eval 'date +%s'); TimerStartstr=$(eval 'date -d@$((timerstart))'); echo Started at \ \ $timerstart = $TimerStartstr; sleep 2; timerend=$(eval 'date +%s'); TimerEndstr=$(eval 'date -d@$timerend'); echo Completed at $timerend = $TimerEndstr; echo =========== TestTimerTask Complete, took $(($timerend - $timerstart)) =================="
[user@Dreadnaught log]$ timertest
==Start==
-ash: Mar: not found
Started at   1710780100 = Mon Mar 18 16:41:01 GMT 2024
-ash: Mar: not found
Completed at 1710780101 = Mon Mar 18 16:41:15 GMT 2024
=========== TestTimerTask Complete, took 1 ==================
[user@Dreadnaught log]$


[user@Dreadnaught log]$ alias timerstart="f(){ timerstart=$(eval 'date +%s'); TimerStartstr=$(eval 'date -d@$((timerstart))'); echo Started at \ \ $timerstart = $TimerStartstr; unset -f f; };f"
[user@Dreadnaught log]$ alias timerend="f(){ timerend=$(eval 'date +%s'); TimerEndstr=$(eval 'date -d@$((timerend))'); echo Finished at \ \ $timerend = $TimerEndstr; unset -f f; };f; echo =========== TestTimerTask Complete, took $(($timerend - $timerstart)) =================="
[user@Dreadnaught log]$ alias timertest="timerstart; read -p 'Waiting for input' >/dev/tty; timerend"
[user@Dreadnaught log]$ timertest
-ash: Mar: not found
Started at   1710780677 = Mon Mar 18 16:41:01 GMT 2024
Waiting for input
-ash: Mar: not found
Finished at   1710780677 = Mon Mar 18 16:41:15 GMT 2024
=========== TestTimerTask Complete, took 0 ==================
[user@Dreadnaught log]$

Answer 1

It sounds like you're using aliases when you should be using functions and have a few other issues such as calling eval for no apparent reason. I THINK this is what you're trying to do:

$ cat tst.sh
#!/usr/bin/env bash

myTask1() { sleep 3; }
myTask2() { sleep 5; }

timertest() {
    local begSecs endSecs

    printf -v begSecs '%(%s)T'
    printf '%s Started at  %d = %(%Y-%m-%d %H:%M:%S)T\n' "$*" "$begSecs" >&2

    "$@"

    printf -v endSecs '%(%s)T'
    printf '%s Finished at  %d = %(%Y-%m-%d %H:%M:%S)T\n' "$*" "$endSecs" >&2

    printf '=========== %s Complete, took %d ==================\n' "$*" "$(( endSecs - begSecs ))" >&2
}

timertest myTask1

timertest myTask2

$ ./tst.sh
myTask1 Started at  1710787312 = 2024-03-18 13:41:52
myTask1 Finished at  1710787315 = 2024-03-18 13:41:55
=========== myTask1 Complete, took 3 ==================
myTask2 Started at  1710787315 = 2024-03-18 13:41:55
myTask2 Finished at  1710787320 = 2024-03-18 13:42:00
=========== myTask2 Complete, took 5 ==================

Answer 2

The link you reference clearly says the alias in the example evaluates at define time because it was done in double quotes, not single quotes. Mind your quoting... but what you want is still a function.

Also, bash has a built-in $SECONDS variable for how long the script has been running in seconds. You could always use that.

This does work with an alias -

$: alias myAlias='sleep $((RANDOM%10))'
$: date; t=$SECONDS; myAlias; echo "myAlias took $((SECONDS-t)) secs"; date
Thu Mar 21 09:42:24 CDT 2024
myAlias took 4 secs
Thu Mar 21 09:42:28 CDT 2024

But if you have any recent version of bash, the printf '%(%s)T' method gives you the actual date and time with formatting options, without having to spawn a subshell for date. (See Ed's solution.)

You also could just use time on a function or a script, but for an alias you need to make sure it's well-behaved and structured accordingly...

$: alias myAlias='date;sleep $((RANDOM%5));date'
$: time myAlias # oops! time only checked the first call to date
Thu Mar 21 09:47:35 CDT 2024

real    0m0.061s
user    0m0.000s
sys     0m0.046s
Thu Mar 21 09:47:38 CDT 2024

$: alias myAlias='{ date;sleep $((RANDOM%5));date; }' 
$: time myAlias  # this works, but who writes aliases like this? 
Thu Mar 21 09:47:59 CDT 2024
Thu Mar 21 09:48:02 CDT 2024

real    0m3.194s
user    0m0.000s
sys     0m0.152s

$: myTask1(){ date;sleep $((RANDOM%5));date; } # make it a function
$: time myTask1 # works as expected... but see below
Thu Mar 21 09:51:50 CDT 2024
Thu Mar 21 09:51:54 CDT 2024

real    0m4.192s
user    0m0.000s
sys     0m0.153s

That outputs to stderr, but if using the bash builtin it can be oddly hard to catch, so you might want to wrap it in curlies to manage the I/O, such as if trying to assign to a variable.

This ends up making some strange looking code for what was otherwise a pretty simple thing...

$: time myTask1 | awk '/^real/{print $2}' # stderr bypasses normal pipe

real    0m3.247s
user    0m0.030s
sys     0m0.325s

$: time myTask1 | awk '/^real/{print $2}' # usual fix doesn't work!

real    0m4.249s
user    0m0.015s
sys     0m0.277s

$: { time myTask1; } 2>&1 | awk '/^real/{print $2}' # but this does
0m3.212s
$: read t < <( { time myTask1; } 2>&1 | awk '/^real/{print $2}' ) # seems a bit much
$: echo $t # but it does get the job done...
0m4.314s

$: t=( $( { time myTask1; } 3>&2 2>&1 1>&3  ) ) # this shell-game works...
Thu Mar 21 10:09:23 CDT 2024
Thu Mar 21 10:09:24 CDT 2024
$: printf "%s\t%s\n" "${t[@]}"       # it's all in the array
real    0m1.187s
user    0m0.015s
sys     0m0.168s
$: echo ${t[1]}                      # wall-clock time is 2nd element
0m1.187s

$: [[ "$( { time myTask1; } 2>&1 )" =~ real[[:space:]]+([^[:space:]]+) ]] && 
> echo ${BASH_REMATCH[1]} # there's always a regex...
0m3.186s

All of these seem to make it much harder than it should be.
They have the advantage of sub-second timing, and automatic conversion to minutes and possibly hours if needed, but if those things aren't worth it, then again I'd go back to Ed's solution, with the caveat that it works fine for scripts and functions, but not aliases or some built-in's (though most built-in's have analogs which are probably in your $PATH.) This is yet another reason to prefer functions over aliases for all but the most simple tasks.

$: timertest which printf
which printf Started at  1711034697 = 2024-03-21 10:24:57
/usr/bin/printf
which printf Finished at  1711034697 = 2024-03-21 10:24:57
=========== which printf Complete, took 0 ==================

$: timertest time echo
time echo Started at  1711034728 = 2024-03-21 10:25:28
bash: time: command not found
time echo Finished at  1711034728 = 2024-03-21 10:25:28
=========== time echo Complete, took 0 ==================

Using full path to the the time program (not the builtin) makes catching stderr easier, but timing a function a little trickier... and as you can see above, my local system does not have a time analog in my $PATH.

Hope the discussion helps someone, and I expect to learn something useful from the comments. :)