How to monitor for how much time each line of stdout was the last output line in Bash for benchmarking?

Question

For example, suppose I have the script:

(echo a; sleep 1; echo b; sleep 3; echo c; sleep 2)

which outputs:

a
b
c

When running that script, possibly through a pipe, I would like to obtain something like:

1.00 a
3.00 b
2.00 c

because the line a was the last line of stdout for 1.00 seconds, before it was replaced by b as the last line.

I don't want to modify the program being run, and in my actual use case the stdout will be generated by a complex executable which I don't want to modify, e.g. QEMU booting the Linux kernel.

This would allow me to do a quick and dirty profiling of the program being run, to determine what segment is taking the longest.

Answer 1

If you're happy with a resolution of seconds, you can use this one-liner:

t=$SECONDS; (echo a; sleep 1; echo b; sleep 3; echo c; sleep 2) | while read line; do echo $((SECONDS - t)) $line; t=$SECONDS; done

If you are OK with installing node.js, this is exactly what gnomon does:

Answer 2

moreutils ts

I knew someone had written this before!

$ sudo apt-get install moreutils
$ (echo a; sleep 1; echo b; sleep 3; echo c; sleep 2; echo d; sleep 1) | ts -i
00:00:00 a
00:00:01 b
00:00:03 c
00:00:02 d
$ (echo a; sleep 1; echo b; sleep 3; echo c; sleep 2; echo d; sleep 1) | ts -i '%.s'
0.000010 a
0.983308 b
3.001129 c
2.001120 d
$ (echo a; sleep 1; echo b; sleep 3; echo c; sleep 2; echo d; sleep 1) | ts -s
00:00:00 a
00:00:01 b
00:00:04 c
00:00:06 d   
$ (echo a; sleep 1; echo b; sleep 3; echo c; sleep 2; echo d; sleep 1) | ts
Apr 13 03:10:44 a
Apr 13 03:10:45 b
Apr 13 03:10:48 c
Apr 13 03:10:50 d

If you Google instead for the related "add timestamp to stdout" there are many results:

• https://unix.stackexchange.com/questions/26728/prepending-a-timestamp-to-each-line-of-output-from-a-command
• https://serverfault.com/questions/310098/how-to-add-a-timestamp-to-bash-script-log
• Is there a Unix utility to prepend timestamps to stdin?

Bash while read

This gives it in millis:

stdouttime() (
  tp="$(date +%s%N)"
  while read line; do
    tc="$(date +%s%N)"
    echo $(((tc - tp) / 1000000))
    echo "$line"
    tp=$tc
  done
  tc="$(date +%s%N)";
  echo $(((tc - tp) / 1000000))
)
(echo a; sleep 1; echo b; sleep 3; echo c; sleep 2) | stdouttime

Sample output:

2
a
1000
b
3002
c
2002

Based on: https://serverfault.com/questions/151109/how-do-i-get-current-unix-time-in-milliseconds-using-bash