Instrumentation of code without editing it to debug for the slowest part of script
Few days back I had an issue where a script was getting timed out, from logs it was successful, it took 2 hours rather than 10 mins as what I thought would be enough time for it to complete. That script was pretty old and was created to work without proper logging, it just outputted log messages to stdout
.
Lets say that the script under discussion is ManagementNodeBackup.sh
#!/bin/bash echo "logging statement 1" sleep 2 echo "logging statement 2" sleep 2 echo "logging statement 3" sleep 2 echo "logging statement 4"
even though here I have wrote it as a bash script this method will work for any scripting language or a compiled binary file too.
Execution of the script may provide output like:
$ bash ManagementNodeBackup.sh logging statement 1 logging statement 2 logging statement 3 logging statement 4
After I ran the script with the decorated caused it to output:
time bash -x ManagementNodeBackup.sh 2>&1 | while IFS='' read -r line || [[ -n "$line" ]] do echo `date +%s` " $line"; done 2>&1 | tee backup.log
like this:
$ time bash -x ManagementNodeBackup.sh 2>&1 | > while IFS='' read -r line || [[ -n "$line" ]] > do > echo `date +%s` " $line"; > done 2>&1 | tee backup.log 1516711319 + echo 'logging statement 1' 1516711319 logging statement 1 1516711319 + sleep 2 1516711321 + echo 'logging statement 2' 1516711321 logging statement 2 1516711321 + sleep 2 1516711323 + echo 'logging statement 3' 1516711323 logging statement 3 1516711323 + sleep 2 1516711325 + echo 'logging statement 4' 1516711325 logging statement 4 real 0m6.016s user 0m0.011s sys 0m0.028s
Explanation:
Here I started by redirecting stderr
to stdout
in command execution like:
command 2>&1
Now for, every line which is outputted on stdout
we are going to read the line in a small bash program (i.e. while loop) and prepend date to it and print, like:
command 2>&1 | while IFS='' read -r line || [[ -n "$line" ]] do echo `date +%s` " $line"; done
Other two qualifiers, first command time
and last construct | tee
are just to add more information and capture the output into log file which can be shipped back from production environment for debugging.