• Uncategorized

About bash : Use-PS0-and-PS1-to-display-execution-time-of-each-bash-command

Question Detail

It seems that by executing code in PS0 and PS1 variables (which are eval’ed before and after a prompt command is run, as I understand) it should be possible to record time of each running command and display it in the prompt. Something like that:

[email protected] ~/tmp
$ sleep 1

[email protected] ~/tmp 1.01s
$

However, I quickly got stuck with recording time in PS0, since something like this doesn’t work:

PS0='$(START=$(date +%s.%N))'

As I understand, START assignment happens in a sub-shell, so it is not visible in the outer shell. How would you approach this?

Question Answer

I was looking for a solution to a different problem and came upon this question, and decided that sounds like a cool feature to have. Using @Scheff’s excellent answer as a base in addition to the solutions I developed for my other problem, I came up with a more elegant and full featured solution.

First, I created a few functions that read/write the time to/from memory. Writing to the shared memory folder prevents disk access and does not persist on reboot if the files are not cleaned for some reason

function roundseconds (){
  # rounds a number to 3 decimal places
  echo m=$1";h=0.5;scale=4;t=1000;if(m<0) h=-0.5;a=m*t+h;scale=3;a/t;" | bc
}

function bash_getstarttime (){
  # places the epoch time in ns into shared memory
  date +%s.%N >"/dev/shm/${USER}.bashtime.${1}"
}

function bash_getstoptime (){
  # reads stored epoch time and subtracts from current
  local endtime=$(date +%s.%N)
  local starttime=$(cat /dev/shm/${USER}.bashtime.${1})
  roundseconds $(echo $(eval echo "$endtime - $starttime") | bc)
}

The input to the bash_ functions is the bash PID

Those functions and the following are added to the ~/.bashrc file

ROOTPID=$BASHPID
bash_getstarttime $ROOTPID

These create the initial time value and store the bash PID as a different variable that can be passed to a function. Then you add the functions to PS0 and PS1

PS0='$(bash_getstarttime $ROOTPID) etc..'
PS1='\[\033[36m\] Execution time $(bash_getstoptime $ROOTPID)s\n'
PS1="$PS1"'and your normal PS1 here'

Now it will generate the time in PS0 prior to processing terminal input, and generate the time again in PS1 after processing terminal input, then calculate the difference and add to PS1. And finally, this code cleans up the stored time when the terminal exits:

function runonexit (){
  rm /dev/shm/${USER}.bashtime.${ROOTPID}
}

trap runonexit EXIT

Putting it all together, plus some additional code being tested, and it looks like this:

The important parts are the execution time in ms, and the user.bashtime files for all active terminal PIDs stored in shared memory. The PID is also shown right after the terminal input, as I added display of it to PS0, and you can see the bashtime files added and removed.

PS0='$(bash_getstarttime $ROOTPID) $ROOTPID experiments \[\033[00m\]\n'

As @tc said, using arithmetic expansion allows you to assign variables during the expansion of PS0 and PS1. Newer bash versions also allow PS* style expansion so you don’t even need a subshell to get the current time. With bash 4.4:

# PS0 extracts a substring of length 0 from PS1; as a side-effect it causes
# the current time as epoch seconds to PS0time (no visible output in this case)
PS0='\[${PS1:$((PS0time=\D{%s}, PS1calc=1, 0)):0}\]'
# PS1 uses the same trick to calculate the time elapsed since PS0 was output.
# It also expands the previous command's exit status ($?), the current time
# and directory ($PWD rather than \w, which shortens your home directory path
# prefix to "~") on the next line, and finally the actual prompt: '[email protected]> '
PS1='\nSeconds: $((PS1calc ? \D{%s}-$PS0time : 0)) Status: $?\n\D{%T} ${PWD:PS1calc=0}\n\[email protected]\h> '

(The %N date directive does not seem to be implemented as part of \D{...} expansion with bash 4.4. This is a pity since we only have a resolution in single second units.)

Since PS0 is only evaluated and printed if there is a command to execute, the PS1calc flag is set to 1 to do the time difference (following the command) in PS1 expansion or not (PS1calc being 0 means PS0 was not previously expanded and so didn’t re-evaluate PS1time). PS1 then resets PS1calc to 0. In this way an empty line (just hitting return) doesn’t accumulate seconds between return key presses.

One nice thing about this method is that there is no output when you have set -x active. No subshells or temporary files in sight: everything is done within the bash process itself.

I took this as puzzle and want to show the result of my puzzling:

First I fiddled with time measurement. The date +%s.%N (which I didn’t realize before) was where I started from. Unfortunately, it seems that bashs arithmetic evaluation seems not to support floating points. Thus, I chosed something else:

$ START=$(date +%s.%N)

$ awk 'BEGIN { printf("%fs", '$(date +%s.%N)' - '$START') }' /dev/null
8.059526s

$

This is sufficient to compute the time difference.

Next, I confirmed what you already described: sub-shell invocation prevents usage of shell variables. Thus, I thought about where else I could store the start time which is global for sub-shells but local enough to be used in multiple interactive shells concurrently. My solution are temp. files (in /tmp). To provide a unique name I came up with this pattern: /tmp/$USER.START.$BASHPID.

$ date +%s.%N >/tmp/$USER.START.$BASHPID ; \
> awk 'BEGIN { printf("%fs", '$(date +%s.%N)' - '$(cat /tmp/$USER.START.$BASHPID)') }' /dev/null
cat: /tmp/ds32737.START.11756: No such file or directory
awk: cmd. line:1: BEGIN { printf("%fs", 1491297723.111219300 - ) }
awk: cmd. line:1:                                              ^ syntax error

$

Damn! Again I’m trapped in the sub-shell issue. To come around this, I defined another variable:

$ INTERACTIVE_BASHPID=$BASHPID

$ date +%s.%N >/tmp/$USER.START.$INTERACTIVE_BASHPID ; \
> awk 'BEGIN { printf("%fs", '$(date +%s.%N)' - '$(cat /tmp/$USER.START.$INTERACTIVE_BASHPID)') }' /dev/null
0.075319s

$

Next step: fiddle this together with PS0 and PS1. In a similar puzzle (SO: How to change bash prompt color based on exit code of last command?), I already mastered the “quoting hell”. Thus, I should be able to do it again:

$ PS0='$(date +%s.%N >"/tmp/${USER}.START.${INTERACTIVE_BASHPID}")'

$ PS1='$(awk "BEGIN { printf(\"%fs\", "$(date +%s.%N)" - "$(cat /tmp/$USER.START.$INTERACTIVE_BASHPID)") }" /dev/null)'"$PS1"
0.118550s
$

Ahh. It starts to work. Thus, there is only one issue – to find the right start-up script for the initialization of INTERACTIVE_BASHPID. I found ~/.bashrc which seems to be the right one for this, and which I already used in the past for some other personal customizations.

So, putting it all together – these are the lines I added to my ~/.bashrc:

# command duration puzzle
INTERACTIVE_BASHPID=$BASHPID
date +%s.%N >"/tmp/${USER}.START.${INTERACTIVE_BASHPID}"
PS0='$(date +%s.%N >"/tmp/${USER}.START.${INTERACTIVE_BASHPID}")'
PS1='$(awk "BEGIN { printf(\"%fs\", "$(date +%s.%N)" - "$(cat /tmp/$USER.START.$INTERACTIVE_BASHPID)") }" /dev/null)'"$PS1"

The 3rd line (the date command) has been added to solve another issue. Comment it out and start a new interactive bash to find out why.

A snapshot of my cygwin xterm with bash where I added the above lines to ./~bashrc:

Notes:

  1. I consider this rather as solution to a puzzle than a “serious productive” solution. I’m sure that this kind of time measurement consumes itself a lot of time. The time command might provide a better solution: SE: How to get execution time of a script effectively?. However, this was a nice lecture for practicing the bash…

  2. Don’t forget that this code pollutes your /tmp directory with a growing number of small files. Either clean-up the /tmp from time to time or add the appropriate commands for clean-up (e.g. to ~/.bash_logout).

Arithmetic expansion runs in the current process and can assign to variables. It also produces output, which you can consume with something like \e[$((...,0))m (to output \e[0m) or ${t:0:$((...,0))} (to output nothing, which is presumably better). 64-bit integer support in Bash supports will count POSIX nanoseconds until the year 2262.

$ PS0='${t:0:$((t=$(date +%s%N),0))}'
$ PS1='$((( t )) && printf %d.%09ds $((t=$(date +%s%N)-t,t/1000000000)) $((t%1000000000)))${t:0:$((t=0))}\n$ '
0.053282161s
$ sleep 1
1.064178281s
$ 

$ 

PS0 is not evaluated for empty commands, which leaves a blank line (I’m not sure if you can conditionally print the \n without breaking things). You can work around that by switching to PROMPT_COMMAND instead (which also saves a fork):

$ PS0='${t:0:$((t=$(date +%s%N),0))}'
$ PROMPT_COMMAND='(( t )) && printf %d.%09ds\\n $((t=$(date +%s%N)-t,t/1000000000)) $((t%1000000000)); t=0'
0.041584565s
$ sleep 1
1.077152833s
$ 
$ 

That said, if you do not require sub-second precision, I would suggest using $SECONDS instead (which is also more likely to return a sensible answer if something sets the time).

As correctly stated in the question, PS0 runs inside a sub-shell which makes it unusable for this purpose of setting the start time.

Instead, one can use the history command with epoch seconds %s and the built-in variable $EPOCHSECONDS to calculate when the command finished by leveraging only $PROMPT_COMMAND.

# Save start time before executing command (does not work due to PS0 sub-shell)
# preexec() {
#   STARTTIME=$EPOCHSECONDS
# }
# PS0=preexec

# Save end time, without duplicating commands when pressing Enter on an empty line
precmd() {
    local st=$(HISTTIMEFORMAT='%s ' history 1 | awk '{print $2}');
    if [[ -z "$STARTTIME" || (-n "$STARTTIME" && "$STARTTIME" -ne "$st") ]]; then
        ENDTIME=$EPOCHSECONDS
        STARTTIME=$st
    else
        ENDTIME=0
    fi
}

__timeit() {
    precmd;
    if ((ENDTIME - STARTTIME >= 0)); then
        printf 'Command took %d seconds.\n' "$((ENDTIME - STARTTIME))";
    fi

    # Do not forget your:
    #     - OSC 0 (set title)
    #     - OSC 777 (notification in gnome-terminal, urxvt; note, this one has preexec and precmd as OSC 777 features)
    #     - OSC 99 (notification in kitty)
    #     - OSC 7 (set url) - out of scope for this question
}

export PROMPT_COMMAND=__timeit

Note: If you have ignoredups in your $HISTCONTROL, then this will not report back for a command that is re-run.

You may also like...

Leave a Reply

Your email address will not be published.

This site uses Akismet to reduce spam. Learn how your comment data is processed.