1

Suppose I have a program foo which prints to both stderr and stdout. I want to be able to time it and tee the output to a log file.

Program Description

I can call foo as follows: 

user$ time ./foo

This gives (for example) output on two streams:

stdout:

stdout says hi

stderr:

stderr says hi

Combining stderr and stdout

I can combine them easily enough to standard output using BASH I/O redirection:

user$ ./foo 2>&1

This gives the following output:

stdout:

stdout says hi
stderr says hi

stderr: (empty!)

Using tee

I can capture the combined output of the program using tee:

user$ ./foo 2>&1 | tee log.txt

stdout:

stdout says hi
stderr says hi

stderr: (empty!)

log.txt:

stdout says hi
stderr says hi

Capturing Timing using time

I can time the execution of my program using BASH's builtin time command while combining stdout and stderr:

user$ time ./foo 2>&1

stdout:

stdout says hi
stderr says hi

stderr:: 

real    0m0.017s
user    0m0.003s
sys     0m0.004s

I can capture the output of the time command as described here and redirect it to a file: 

user$ ( time ./foo ) > log.txt

stdout: (empty!)

stderr:

stderr says hi

real    0m0.017s
user    0m0.003s
sys     0m0.004s

log.txt: stdout says hi

Combining I/O, Capturing time's output, AND piping to tee

How can this be done? I'm imagining something like the following: 

( time ./foo 2&>1 ) | tee log.txt

stdout: (empty!)

stdout says hi
stderr says hi

real    0m0.017s
user    0m0.003s
sys     0m0.004s

stderr: (empty!)

log.txt:

stdout says hi
stderr says hi

real    0m0.017s
user    0m0.003s
sys     0m0.004s

Doing the following works, except when I Ctrl-C (SIGINT) out of the program prematurely. 

( time ./foo ) 2&>1 | tee log.txt

How can I get it to work when I Ctrl-C as well?

jvriesem
  • 1,859
  • 3
  • 18
  • 40
  • Your link suggests using `(time ls) &> file`, which would have worked in your case, too. So why did you leave out the `&`? (That is `(time ...) |& tee ...`) – rici May 30 '18 at 19:37
  • @rici: Good suggestion. That syntax didn't work for me when using `GNU bash version 3.2.57(1)-release` (remote computer I can't update BASH on), though it *does* appear to work for `GNU bash, version 4.4.19(1)-release` (I can and have updated BASH). I'll see if my sysadmins can update BASH on the remote machine, but I'm still interested in a solution. – jvriesem May 30 '18 at 19:51
  • 1
    Part of what's tricky with piping to `tee`, by the way, is that ctrl+c sends a SIGINT to the whole process group -- so it shuts down `tee` at the same time as it shuts down the subshell running `time`, meaning you can't guarantee (ie. it's dependent on the outcome of a race) whether `tee` is actually able to flush that shell's output. – Charles Duffy May 30 '18 at 20:29

1 Answers1

1
myfunc() { echo stdout; echo stderr >&2; sleep 3; }
{ time myfunc; } > >(tee log.txt) 2>&1

...emits content including time metadata to log.txt, even when cancelled with Ctrl+C.

See Write tcpdump output to compressed / gziped file for a more-in-depth discussion of the same problem, including an answer intended for scripts as opposed to interactive interpreters.

For the program foo in your example, you could do the following: 

{ time ./foo; } > >(tee log.txt) 2>&1
Charles Duffy
  • 280,126
  • 43
  • 390
  • 441
  • @jvriesem, ...re: edit, I'd expect you could just `time ./foo`, vs needing the function (which was added just for testability purposes) and to `time myfunc`; is that not the case? – Charles Duffy May 30 '18 at 21:10
  • Sure enough! `{ time myfunc; } > >(tee log.txt) 2>&1` seems sufficient. Thank you! (Edited the answer.) – jvriesem May 30 '18 at 22:19