As an important step of debugging process, looking finely for times and progressions is as must have.
Using script and scriptreplay oftenly, I wonder if there exist tools for manipulating resulting files.
Sample (From How to profile a bash shell script slow startup?):
script -t script.log 2>script.tim -c 'bash -x -c "
for ((i=3;i--;));do sleep .1;done
for ((i=2;i--;)) ;do
tar -cf /tmp/test.tar -C / bin
gzip /tmp/test.tar
rm /tmp/test.tar.gz
done
"'
Then there are two files:
-rw-r--r-- 1 user user 472 Sep 25 10:44 script.log
-rw-r--r-- 1 user user 213 Sep 25 10:44 script.tim
And I could replay the script by:
scriptreplay --timing script.tim --typescript script.log 10
with 10 as execution time divisor to make replay 10x quicker, or
scriptreplay --timing script.tim --typescript script.log .1
to make replay 10x slower.
I wonder if there exist tools like:
Well, from there:
cut -d \ -f1 <script.tim | xargs | tr \ + | bc
3.616809
will output overall execution time or if there is too much lines:
cut -d \ -f1 <script.tim | xargs | tr \ + | bc | xargs | tr \ + | bc
3.616809
and
cut -d \ -f2 <script.tim | xargs | tr \ + | bc
366
sed '1d;$d' script.log |wc -c
367
to check overall script ouptut size. (sed drop 1st and last lines of log, who contain: Script started on Wed Sep 25 14:40:20 2019 and Script done on Wed Sep 25 14:40:23 2019.)
Then, computing log size (pointer) at some time:
perl -e 'my ($l,$t,$p)=(0,0,0); # line totTime pos
open FH,"<".$ARGV[0] || die;
while (<FH>) {
my ($d,$n)=split" "; # duration numBytes
$l++;
$t+=$d;
$p+=$n;
$t>=${ARGV[1]} && do {
print $l." ".$p."\n";
exit 0;
};
};' script.tim 1.2
12 216
Line 12 in timingfile (head -n 12) and byte position 216 in typescript file (head -c 216).
Or if I'm searching for time elapsed upto some string:
grep -ob 'tar.*test' script.log
217:tar -cf /tmp/test
320:tar -cf /tmp/test
perl -e 'my ($l,$t,$p)=(0,0,0);open FH,"<".$ARGV[0] || die;while (<FH>) {
my ($d,$n)=split" ";$l++;$t+=$d;$p+=$n;$p>=${ARGV[1]} && do {
print $l." ".$p."\n";exit 0;};};' script.tim 217
17 228
head -n 17 script.tim | cut -d \ -f1 | xargs | tr \ + | bc
1.091276
Searching for something lighter...
Used for debugging purpose script is very usefull! Under bash, you could use some tricks.
My samples here are based on the two files script.log and script.log created by first script on this post (Sample from How to profile a bash shell script slow startup?), run on a raspberry pi:
Overall execution time
Instead of forking many times to xargs | tr \ + | bc | you could be confident about the ability of bash to manage very long arithmetic line:
elaps=00000$(($(sed 's/ .*$/+/;s/\.//;s/^0*//' script.tim)0))
TZ=UTC printf '%(%T)T.%s\n' $((10#${elaps::-6})) ${elaps: -6}
00:01:38.595605
Or, if you expect very long execution time, for adding number of days simply:
TZ=UTC printf '%dd%(%T)T.%s\n' \
$((10#${elaps::-8}/864)) $((10#${elaps::-6})) ${elaps: -6}
0d00:01:38.595605
Browsing for errors. As script will create a dedicated terminal, all commands that colorize his output by default (when not piped), will print errors in red, by prefixing his output by \E[31m, \E[31;1m, \E[1;31m or something similar.
Unfortunately, there are no colored errors in the sample file... I use this on very long live-build process. I run my script by:
printf -v filenam 'mklive-%(%F-%H%M)T' -1
script -t $filenam.log 2>$filenam.tm -c myLiveBuild.sh
Then browsing log file for red highlighted line could be done by:
less -r $'+/\[([0-9;]+;|)31([0-9;]+;|)m' $filenam.log
This trick could be used with the two following scripts.
This use (require) xterm and run replay script output in a new terminal with same size than script was runned in. Interaction are really minimalist.
Here are two options:
-t Do timelaps by using builtin read so able to be accelerated by hitting Return.-w To submit a word or string to search for. Progression will be stopped until you press Return.#!/bin/bash
export LANG=C LANGUAGE=C
die() { echo >&2 "$0 ERR: $@";exit 1;}
doTime=false
while getopts "tw:" opt;do case $opt in
t ) doTime=true;;
w ) searchFor=${OPTARG};;
esac;done
shift $((OPTIND-1))
exec {log}<"$1" || die "Can't open logfile '$1'."
exec {tim}<"$2" || die "Can't open timing file '$2'-"
IFS='' read -ru $log line || die "error reading logfile."
sTerm=${line#*TERM=\"} sTerm=${sTerm%%\"*}
sCols=${line#*COLUMNS=\"} sCols=${sCols%%\"*}
sLnes=${line#*LINES=\"} sLnes=${sLnes%%\"*}
[ "$sTerm" ] || die "No TERM var found."
((sCols * sLnes)) || die "No valid size"
exec {term}<> >(:)
xterm -fs 11 -geom ${sCols}x$sLnes -T ScripReplay -S00/$term &
XTPid=$!
read -u $term -t 1 XTWinId
declare -i TTime=0 TChar=0
while read -u $tim time chars;do
IFS='' read -d '' -rn $chars -u $log str
printf >&$term '%s' "$str"
TTime+=10#${time/.} TChar+=chars
ttm=00000$TTime
printf "\rCrt %12.6f, %3d chars - Tot: %12.6f %11d\n" $time $chars \
${ttm::-6}.${ttm: -6} $TChar
[ "$searchFor" ] &&
case $str in *$searchFor* ) read -p "Found: '$searchFor'. " _;;esac
$doTime && read -t $time _
done
exec {tim}<&-
exec {log}<&-
read -pDone.\ _
exec {term}>&-
kill $XTPid
Same in python would be welcome!
Here: scriptReplay.sh.txt, scriptReplay.sh.
Script Replay based debugging tool Command line optional arguments: -h Show this. -t Reproduce delays between outputs ('$doTime', default false) -d DIVISOR Integer divisor of delay [-t] ('$divisor', default 10) -w STRING Stop output when STRING found, wait for user interaction -n Don't wait when STRING found Interactive interface: Once run, ${0##*/} will open another xterm window to show console dialog as recorded by script. While running, interaction in first console could be: [t] Toggle reproducing time delays between outputs [d] Enter a new INTEGER for divisor [s] Enter a new STRING to search for [q] Quit.
Here is a small and fast solution (using bc):
#!/bin/bash
coproc exec bc
echo >&${COPROC[1]} t=0.0
{
declare -i Tlen=0
read -u $lg hl
echo HEAD $hl
while read -u $tm tim chrs ;do
echo "t+=$tim;t" >&${COPROC[1]}
read -u ${COPROC[0]} Ttim
Tlen+=$chrs
LANG=C IFS='' read -d '' -u $lg -rn $chrs str
printf '%10.6f %-4d|%12.6f %12d: %s\n' $tim $chrs $Ttim $Tlen "${str@Q}"
done
while read -u $lg str ;do
echo "TAIL: ${str@Q}"
done
} {lg}<"$1" {tm}<"$2"
Run on script.log and script.tim produced by 1st command in this post will render on my raspberry-pi:
$ ./quickReplay.sh script.{log,tim}
HEAD Script started on 2022-04-07 14:37:19+02:00 [TERM="xterm" TTY="/dev/pts/0" COLUMNS="80" LINES="24"]
0.083946 11 | 0.083946 11: '+ (( i=3 ))'
0.001231 2 | 0.085177 13: $'\r\n'
0.001951 11 | 0.087128 24: '+ (( i-- ))'
0.001023 2 | 0.088151 26: $'\r\n'
0.001947 10 | 0.090098 36: '+ sleep .1'
0.001412 2 | 0.091510 38: $'\r\n'
0.123944 9 | 0.215454 47: '+ (( 1 ))'
0.005763 2 | 0.221217 49: $'\r\n'
0.001559 11 | 0.222776 60: '+ (( i-- ))'
0.001027 2 | 0.223803 62: $'\r\n'
0.001908 10 | 0.225711 72: '+ sleep .1'
0.001256 2 | 0.226967 74: $'\r\n'
0.126024 9 | 0.352991 83: '+ (( 1 ))'
0.001316 2 | 0.354307 85: $'\r\n'
0.001804 11 | 0.356111 96: '+ (( i-- ))'
0.001076 2 | 0.357187 98: $'\r\n'
0.002086 10 | 0.359273 108: '+ sleep .1'
0.002059 2 | 0.361332 110: $'\r\n'
0.125725 9 | 0.487057 119: '+ (( 1 ))'
0.001147 2 | 0.488204 121: $'\r\n'
0.001768 11 | 0.489972 132: '+ (( i-- ))'
0.001346 2 | 0.491318 134: $'\r\n'
0.002247 11 | 0.493565 145: '+ (( i=2 ))'
0.007743 2 | 0.501308 147: $'\r\n'
0.001628 11 | 0.502936 158: '+ (( i-- ))'
0.000259 2 | 0.503195 160: $'\r\n'
0.000810 32 | 0.504005 192: '+ tar -cf /tmp/test.tar -C / bin'
0.001128 2 | 0.505133 194: $'\r\n'
1.336998 20 | 1.842131 214: '+ gzip /tmp/test.tar'
0.001093 2 | 1.843224 216: $'\r\n'
34.593442 23 | 36.436666 239: $'+ rm /tmp/test.tar.gz\r\n'
0.041637 9 | 36.478303 248: '+ (( 1 ))'
0.001435 2 | 36.479738 250: $'\r\n'
0.001617 11 | 36.481355 261: '+ (( i-- ))'
0.010704 2 | 36.492059 263: $'\r\n'
0.001931 32 | 36.493990 295: '+ tar -cf /tmp/test.tar -C / bin'
0.001085 2 | 36.495075 297: $'\r\n'
0.737705 20 | 37.232780 317: '+ gzip /tmp/test.tar'
0.001179 2 | 37.233959 319: $'\r\n'
35.705253 21 | 72.939212 340: '+ rm /tmp/test.tar.gz'
0.001160 2 | 72.940372 342: $'\r\n'
0.053247 9 | 72.993619 351: '+ (( 1 ))'
0.001170 2 | 72.994789 353: $'\r\n'
0.002150 11 | 72.996939 364: '+ (( i-- ))'
0.001353 2 | 72.998292 366: $'\r\n'
TAIL: ''
TAIL: 'Script done on 2022-04-07 14:38:32+02:00 [COMMAND_EXIT_CODE="0"]'