13

I have a script which measures how long some command executes.

It needs the "real" time command, meaning, a binary for example in /usr/bin/time (as the bash-built-in doesn't have the -fflag).

Below, a simplified script which can be debugged:

#!/bin/bash

TIMESEC=$(echo blah | ( /usr/bin/time -f %e grep blah >/dev/null ) 2>&1 | awk -F. '{print $1}')

echo ABC--$TIMESEC--DEF

if [ "$TIMESEC" -eq 0 ] ; then
   echo "we are here!"
fi

Save as "test.sh" and execute:

$ bash test.sh
ABC--0--DEF
we are here!

So it worked.

Now, let's try to debug this by adding "-x" to bash command line:

$ bash -x test.sh
++ echo blah
++ awk -F. '{print $1}'
+ TIMESEC='++ /usr/bin/time -f %e grep blah
0'
+ echo ABC--++ /usr/bin/time -f %e grep blah 0--DEF
ABC--++ /usr/bin/time -f %e grep blah 0--DEF
+ '[' '++ /usr/bin/time -f %e grep blah
0' -eq 0 ']'
test.sh: line 10: [: ++ /usr/bin/time -f %e grep blah
0: integer expression expected

Why does this script break when we're using "-x", and works fine without it?

  • 1
    Heh. It looks like with -x on, that the $() construct is getting the -x output included as part of its resulting value. Don't know if that is "expected" behavior or a bug though... Or maybe it is the subshell () inside that is actually giving the -x output. – Jeff Y Dec 22 '15 at 12:08
  • Aside: Setting BASH_XTRACEFD lets you redirect set -x output to somewhere it's less trouble. – Charles Duffy Dec 22 '15 at 22:04
21

The problem is this line:

TIMESEC=$(echo blah | ( /usr/bin/time -f %e grep blah >/dev/null ) 2>&1 | awk -F. '{print $1}')

where you are redirecting the standard error to match the standard output. bash is writing its trace-messages to the standard error, and is (for instance) using its built-in echo along with other shell constructs all in the bash process.

If you change it to something like

TIMESEC=$(echo blah | sh -c "( /usr/bin/time -f %e grep blah >/dev/null )" 2>&1 | awk -F. '{print $1}')

it will work around that problem, and perhaps be an acceptable compromise between tracing and working:

++ awk -F. '{print $1}'
++ sh -c '( /usr/bin/time -f %e grep blah >/dev/null )'
++ echo blah
+ TIMESEC=0                 
+ echo ABC--0--DEF
ABC--0--DEF
+ '[' 0 -eq 0 ']'
+ echo 'we are here!'
we are here!
7

you can also just drop the subshell. apparently it is the nested shells which wind up upsetting one another:

TIMESEC=$(
    echo blah |
    /usr/bin/time -f %e grep blah 2>&1 >/dev/null |
    awk -F. '{print $1}'
)

If you do:


...| ( subshell ) 2>pipe | ...

... you wind up with the subshell launched to handle that section of the pipeline hosting the subshell within. Because the shell without redirects even the debug output of the subshell within (as it would also do for any other kind of { compound command; } >redirect you might choose to use) to its section of the pipeline you wind up mixing streams. It has to do with the order of redirection.

Instead, if you simply first redirect only the error output of the commands you're attempting gauge, and let the host shell's output make it to stderr, you don't wind up with the same problem.

and so...


... | command 2>pipe 1>/dev/null | ...

...the host shell is free to continue writing its stderr where it pleases while only redirecting the output of the commands which it calls into the pipe.


bash -x time.sh
+++ echo blah
+++ /usr/bin/time -f %e grep blah
+++ awk -F. '{print $1}'
++ TIMESEC=0
++ echo ABC--0--DEF
ABC--0--DEF
++ '[' 0 -eq 0 ']'
++ echo 'we are here!'
we are here!

For that matter...


TIMESEC=$(
    echo blah |
    /usr/bin/time -f %e grep blah 2>&1 >/dev/null
)
printf %s\\n "ABC--${TIMESEC%%.*}--DEF"
if [ "${TIMESEC%%.*}" -eq 0 ] ; then
   echo "we are here!"
fi

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.