Write the running time to file without capturing the program's output

Question

I want to run an application and write (append) its processing time into a file. Also, I want to see the stdout and stderr output on the shell, but don't want to write it in a file. After running the process, I'd like to see time measured.

Since I'm on Bash, one solution would be this one, but it's pretty ugly, since tail needs to parse the whole output:

function run_time {
 { local TIMEFORMAT=%R; time "${@}"; } 2>&1 | tee /dev/stderr | tail -n 1 >> run_time.txt
}

Another variant would be to use GNU time:

function run_time {
 /usr/bin/time --quiet --format '%e' --append --output=run_time.txt "${@}"
 tail -n 1 run_time.txt
}

When running the function like this, the measured time gets written into the file, of course.

run_time mycommand > target.txt

A work-around would to redirect tail's output to stderr or a sub-shell:

run_time sh -c "exec mycommand > target.txt"

And here's my question: It there a more elegant way?

• Toby Speight: It's not necessarily true that tail needs to parse the whole file to find the last line. Sufficiently advanced versions will start at the end of the file, and seek backwards. As the comment for file_lines() in GNU coreutils says, "Go backward through the file, reading 'BUFSIZ' bytes at a time (except probably the first), until we hit the start of the file or have read NUMBER newlines."

Answer 1

Kudos

It's good to see appropriate quoting and correct use of "$@" in these shell scripts. Although the samples are short, it's still good to see nice readable code.

Problems with the first approach

• All the output of the command is sent to /dev/stderr; it's not possible to pipe the output into another command, or to separate the output and error streams.
• The exit status of the command is lost, so you can't use this function as part of a conditional (if, while, &&, ||, ...).
• Only a single command can be timed, rather than a full pipeline.

Problems with the second approach

• The exit status of the command is lost.
• Only a single command can be timed (but that's always the case with an external time command, and why it's a built-in in Bash).

---

An improvement

You can retain the exit status when using GNU time, by using a process substitution as the output file:

function run_time {
 command time --quiet \
 --format '%e' \
 --output >(tee -a run_time.txt >&2) \
 "${@}"
}

Notes

• I've also used the command keyword to find the external time without hard-coding its path. You may or may not choose to follow this course.
• I've sent the time result to standard error, for consistency with the command and built-in (note that the built-in outputs to the shell's standard error, not that of the pipeline it's timing).

---

Alternative using built-in

function run_time {
 local TIMEFORMAT='%R'
 { { time "$@" 2>&3; } 2> >(tee -a run_time.txt >&2); } 3>&2
}

That's a bit hard to follow, so let's unpick it from the inside:

• { time "$@" 2>&3; }
  

  The command's standard output is unchanged (stream 1), but its stderr is redirected to stream 3; time's output will be on stream 2.

• {...} 2> >(tee ... >&2)
  

  The time output is redirected to the tee command; it writes to the file and to the enclosing stream 2 (the function's standard error stream).

• { ... } 3>2
  

  The saved standard error stream of the timed command is diverted back to the function's standard error.

This allows independent redirection of the timed command's standard output and standard error (plus timing results). The function's error status is that of the timed command.

One disadvantage is that it doesn't wait for the process substitution to exit before the function returns, so tee's output may occur unexpectedly late (e.g. after Bash has shown the next command prompt, in an interactive shell).

Answer 2

time is a Bash command that displays information on the shell standard error.

#!/bin/bash
PS4='+ ${FUNCNAME[0]}: '
set -o xtrace
exec 3>&2
runtime() ( time -p "$@" 2>&3 ) 2>runtime.log
# or runtime() { time -p "$@" 2>&3; } 2>runtime.log
runtime find "/usr"

runtime is a shell function executed in a subshell. The trick is to create a new file descriptor (fd3) that refers to the shell standard error (fd 2), then, override the subshell standard error (2>runtime.log) and redirect the error stream of the command to the shell standard error using the new file descriptor (2>&3).

prompt% cat runtime.log
+ runtime: find /usr
real 64.82
user 1.62
sys 3.67

Answer 3

Suppose the program to measure is sleep 3s. Use the time util to append the total time elapsed to run_time.txt, plus annotate-output to more clearly distinguish various IO bits (see below) along the way, and then tail -1 run_time.txt after the program being logged,:

/usr/bin/time -f '%e' -o run_time.txt -a annotate-output '+%n' sleep 3s 
tail -1 run_time.txt

Output:

 I: Started sleep 3s
 I: Finished with exitcode 0
3.02

Wrapped in a function which saves the exit code:

function run_time {
 /usr/bin/time -f '%e' -o run_time.txt -a annotate-output '+%n' "${@}"
 n=$?
 tail -1 run_time.txt
 return $n
}

What annotate-output brings is text prefixes which distinguish output types, that may then be filtered from outside the function.

---

The util annotate-output executes a specified program, while prepending every line with the current time, and I for STDIN, O for STDERR, and E for STDERR.

Example, run a shell, output a y to both STDOUT and STDERR, then finish with false to change the exit code:

annotate-output bash -c - 'yes | head -1 | tee /dev/stderr ; false'

Output:

07:44:56 I: Started bash -c - yes | head -1 | tee /dev/stderr ; false
07:44:56 O: y
07:44:56 E: y
07:44:56 I: Finished with exitcode 1

The single option annotate-output offers is a date string. This example uses ls to output a few files, (and one that doesn't exist), prefixed by seconds since 1970年01月01日 00:00:00 UTC:

annotate-output +%s ls -log /bin/bash /bin/bahshshshshs /bin/sh

Output:

1501070420 I: Started ls -og /bin/bash /bin/bahshshshshs /bin/sh
1501070420 O: -rwxr-xr-x 1 1099016 May 16 07:35 /bin/bash
1501070420 E: ls: cannot access '/bin/bahshshshshs': No such file or directory
1501070420 O: lrwxrwxrwx 1 4 Jul 28 2016 /bin/sh -> dash
1501070420 I: Finished with exitcode 2

If the date string is just a +%n, (or simply a +), no timing data will be prefixed. (See top of this answer for example.)

• Toby Speight: You have presented an alternative solution, but haven't reviewed the code. Please explain your reasoning (how your solution works and how it improves upon the original) so that everyone can learn from your thought process.
• agc: @TobySpeight, Thanks for the feedback. IMHO the OP might be better served here using an existing util, since it seems to fill the bill. Two usage examples added for context.