Bash: how to wrap a command to measure its elapsed time?

Question

How to wrap a command to measure its elapsed time?

Currently I do it using eval:

do_cmd_named()
{
  local name=$1
  local cmd=$2

  echo "$name"
  local start_time=$(date +%s)
  eval "$cmd 2>&1"
  local exit_status=$?
  local end_time=$(date +%s)
  local elapsed_time_sec=$((end_time-start_time))
  local elapsed_time_min_sec=$(date -ud "@$elapsed_time_sec" +'%M:%S')
  if [[ $exit_status -ne 0 ]]
  then
    echo "$name failed with exit status $exit_status (elapsed time $elapsed_time_min_sec)"
    return $exit_status
  else
    echo "$name done (elapsed time $elapsed_time_min_sec)"
  fi
}

job()
{
    sleep 1
}

do_cmd_named "do job" "job"

which leads to:

do job
do job done (elapsed time 00:01)

For my cases this approach almost works. However, this approach is considered bad because it violates some rules from BashFAQ. For example, "don't put code inside variables" from BashFAQ #50 (see also BashFAQ #48).

So, the question is: how to do it correctly?

Do you want to output the elapsed time, or do you need to do more with it? Would `time` be good enough? See [How to get execution time of a script effectively?](https://unix.stackexchange.com/q/52313/86440) and [How to measure time of program execution and store that inside a variable](https://unix.stackexchange.com/q/12068/86440). — Stephen Kitt, Nov 21 '22 at 09:33
I need to (correctly) wrap each command to output, among others (e.g. some prologue / epilogue), elapsed time. I don't know how to achieve such wrapping and to satisfy "Don't put code inside variables!" rule (see BashFAQ #50). — pmor, Nov 21 '22 at 10:39
[That's an XY problem](https://meta.stackexchange.com/q/66377/270345) - you think you need to "wrap" each command, but why do you need to wrap anything at all? What goal do you think you'll accomplish by this wrapping? — muru, Nov 21 '22 at 11:10
@muru At least: 1) measuring of elapsed time, 2) checking of exit status, 3) logging command's start and finish. W/o wrapping the 1), 2), 3) need to be done manually for each command leading to code duplicates. — pmor, Nov 21 '22 at 12:27
In that case, what's the expected result for something like `cmd1 | cmd2` or `while cmd1; do cmd2; done`? 1, 2 and 3 for each of cmd1 and cmd2 or 1, 2 and 3 for the whole construct? — muru, Nov 21 '22 at 12:51
Then the question is, instead of doing this `do_cmd_named name "while cmd1; do cmd2; done"`, why not do `start_cmd name; while cmd1; do cmd2; done; end_cmd`, with a suitable `start_cmd` and `end_cmd` function? Why does it have to be the former? — muru, Nov 21 '22 at 13:26
Possible duplicate - [How can I make time measurement DRY in my bash scripts?](https://unix.stackexchange.com/a/716909/100397) — roaima, Nov 21 '22 at 13:55
@muru Re: "Why does it have to be the former?" The former has _local_ `start_time` and `end_time` making possible to measure elapsed time for nested invocations ([demo](https://onlinegdb.com/1RjbnLnaS)). — pmor, Nov 22 '22 at 08:32
@pmor you could do that by using an array into which you push the start times, like a stack. — muru, Nov 22 '22 at 08:34

glenn jackman · Accepted Answer · 2022-11-23T16:28:56.737

1

capture the command (and arguments) into an array and then you can avoid eval
use the bash builtin variable $SECONDS

do_cmd_named() {
    local name=$1
    shift
    local -a cmd=("$@")

    echo "$name"
    SECONDS=0

    "${cmd[@]}"

    local status=$?
    local elapsed_time_sec=$SECONDS

    # print messages ...
}

do_cmd_named "job name" job arg1 arg2

The issue with $SECONDS is that in case of nested invocations the $SECONDS is reset to 0.

Yes that's true.

An alternate approach is at the start of the function, capture the current value of SECONDS and do some arithmetic at the end.

An example:

rectest() {
    local n=$1 delay=$2 start=$SECONDS
    ((n == 3)) && return
    sleep $delay
    rectest $((n + 1)) $((delay + 3))
    echo "at level $n, delay is $delay and duration is $((SECONDS - start))"
}

and running it, all output appears after a 15 second duration:

$ rectest 0 2
at level 2, delay is 8 and duration is 8
at level 1, delay is 5 and duration is 13
at level 0, delay is 2 and duration is 15

edited Nov 23 '22 at 16:28

answered Nov 21 '22 at 13:53

glenn jackman

84,176
15
116
168

Thanks. How to correctly add support for redirections? Say, `job arg1 arg2` needs to write to `job.log`. Note that extra printed info (such as `echo "$name"`) needs to be on `stdout`. – pmor Nov 22 '22 at 10:31
1

We can't pass around syntax like `>`. I'd do something like `do_cmd_named -o output.log -n name job arg arg ...` and then get the function to parse the arguments using `getopts`. Search around, there are tons of examples here and on stackoverflow – glenn jackman Nov 22 '22 at 13:21
What to do in case of `arg && arg`? Put it in a string (`"arg && arg"`) or escape `&` (`arg \&\& arg`)? – pmor Nov 23 '22 at 12:15
UPD: it seems that both don't work. Does it mean that we can't pass around syntax like `&&`? The same for `|`. In `eval`-based approach `"arg1 && arg2"` works as well as `"arg1 | arg2"`. – pmor Nov 23 '22 at 12:29
1

that is correct. bash has to parse the command line _before_ expanding variables. If you need to do that, put the code in a function or script. – glenn jackman Nov 23 '22 at 13:45
In `local -a cmd=("$@")` do we _really_ need the `-a`? – pmor Nov 23 '22 at 15:56
The issue with `$SECONDS` is that in case of nested invocations the `$SECONDS` is reset to 0. – pmor Nov 23 '22 at 16:13
"do we really need the -a?" No. – glenn jackman Nov 23 '22 at 16:19

score 0 · Answer 2 · answered Nov 21 '22 at 13:42

0

If switching to zsh is an option:

$ TIMEFMT='%J done (elapsed time: %E)'
$ time sleep 1
sleep 1 done (elapsed time: 1.00s)

answered Nov 21 '22 at 13:42

Stéphane Chazelas

522,931
91
1,010
1,501

Bash: how to wrap a command to measure its elapsed time?

2 Answers2