2

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

My request:

Searching for something lighter...

  • This could be some pieces of small script, using in order to modernize my pieces of .

  • Even dynamic! I could imagine a tool using NCurses, with a progress bar, some display and some keyboard control, like a kind of video viewer: Start, Stop, Next step, ...

F. Hauri - Give Up GitHub
  • 64,122
  • 17
  • 116
  • 137
  • Good stuff! I'd be surprized if there is a commonly available tools as you have created. (I hadn't heard of `scriptreplay`, when did that appear?). Just wrap them as functions and add to your toolbox as you discover new needs? Good luck to all. – shellter Sep 25 '19 at 13:42
  • `scriptreplay` is along `script`, a very old tool.... see https://joeyh.name/code/scriptreplay/ – F. Hauri - Give Up GitHub Sep 25 '19 at 14:40
  • Unfortunately, asking for tool recommendations is explicitly disallowed on Stack Overflow. Please review [What topics should I avoid asking about.](/help/dont-ask) – tripleee Feb 01 '22 at 11:15
  • @tripleee, I agree for the principle, however, I'm not ***asking subjective questions*** about choosing over many alternatives, I'm searching for a way of doing **regular** and **precise** job. – F. Hauri - Give Up GitHub Feb 01 '22 at 16:55
  • If you want to look "finely" then seconds are too long and you should use microtime. Else you have to execute a task let's say 1000 times to calculate the average time. – David Feb 05 '22 at 02:31
  • 1
    @David Where did you read the word *seconds* in my post? If you try `script` and `scriptreplay`, timing file are in microseconds. Using [tag:bash]. variable `$EPOCHREALTIME` show time in nanoseconds... And yes, I often use `time for i in {1..100000};do someCommandToTest;done` or so... – F. Hauri - Give Up GitHub Feb 05 '22 at 14:50
  • Oh sorry @F.Hauri I saw the time in the output of `ls -a` and somehow mistook it as the time you're measuring. – David Feb 06 '22 at 01:54

1 Answers1

1

Here is a 1st try, based

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 would be welcome!

More featured version on my website:

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.

Yet another script

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"]'
F. Hauri - Give Up GitHub
  • 64,122
  • 17
  • 116
  • 137