I have some excellent news for you - my timep
bash profiler does exactly what you want - it will give you per-command runtime (both wall-clock time and CPU time / combined user+sys time) and (so long as you pass it the -F
flag) will generate a bash native flamegraph for you that shows actual bash commands, code structure, and colors based on runtime.
timep
is extremely simple to use - download and source the timep.bash
script from the github repo (which loads the `timep function and sets up for using it), and then run
timep -F codeToProfile
And thats it - timep
handles everything, no need to change anything in the code you want to profile.
As an example, using timep to profile this test script from the timep repo (by running timep -F timep.tests.bash
) gives the following profile:
LINE.DEPTH.CMD NUMBER COMBINED WALL-CLOCK TIME COMBINED CPU TIME COMMAND
<line>.<depth>.<cmd>: ( time | cur depth % | total % ) ( time | cur depth % | total % ) (count) <command>
_________________________ ________________________________ ________________________________ ____________________________________
12.0.0: ( 0.006911s | 0.51% ) ( 0.012424s | 5.37% ) (1x) : | cat 0<&0 | cat | tee
14.0.0: ( 0.008768s | 0.65% ) ( 0.014588s | 6.31% ) (1x) printf '%s\n' {1..10} | << (SUBSHELL): 148593 >> | tee | cat
16.0.0: ( 0.000993s | 0.07% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 16.1.0: ( 0.000076s |100.00% | 0.00% ) ( 0.000090s |100.00% | 0.03% ) (1x) |-- echo
17.0.0: ( 0.002842s | 0.21% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 17.1.0: ( 0.000253s | 8.17% | 0.01% ) ( 0.000296s |100.00% | 0.12% ) (1x) |-- echo B
|-- 17.1.1: ( 0.002842s | 91.82% | 0.21% ) ( 0.000001s | 0.33% | 0.00% ) (1x) |-- << (BACKGROUND FORK) >>
19.0.0: ( 0.000069s | 0.00% ) ( 0.000083s | 0.03% ) (1x) echo 0
20.0.0: ( 0.000677s | 0.05% ) ( 0.000521s | 0.22% ) (1x) echo 1
21.0.0: ( 0.000076s | 0.00% ) ( 0.000091s | 0.03% ) (1x) << (SUBSHELL) >>
|-- 21.1.0: ( 0.000076s |100.00% | 0.00% ) ( 0.000091s |100.00% | 0.03% ) (1x) |-- echo 2
22.0.0: ( 0.000407s | 0.03% ) ( 0.000432s | 0.18% ) (1x) echo 3 (&)
23.0.0: ( 0.000745s | 0.05% ) ( 0.000452s | 0.19% ) (1x) echo 4 (&)
24.0.0: ( 0.001000s | 0.07% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 24.1.0: ( 0.000090s |100.00% | 0.00% ) ( 0.000110s |100.00% | 0.04% ) (1x) |-- echo 5
25.0.0: ( 0.000502s | 0.03% ) ( 0.000535s | 0.23% ) (1x) << (SUBSHELL) >>
|-- 25.1.0: ( 0.000502s |100.00% | 0.03% ) ( 0.000535s |100.00% | 0.23% ) (1x) |-- echo 6 (&)
26.0.0: ( 0.001885s | 0.14% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 26.1.0: ( 0.000075s |100.00% | 0.00% ) ( 0.000090s |100.00% | 0.03% ) (1x) |-- echo 7
27.0.0: ( 0.000077s | 0.00% ) ( 0.000091s | 0.03% ) (1x) << (SUBSHELL) >>
|-- 27.1.0: ( 0.000077s |100.00% | 0.00% ) ( 0.000091s |100.00% | 0.03% ) (1x) |-- echo 8
28.0.0: ( 0.002913s | 0.21% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 28.1.0: ( 0.000967s |100.00% | 0.07% ) ( 0.001353s |100.00% | 0.58% ) (1x) |-- echo 9 (&)
29.0.0: ( 0.003014s | 0.22% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 29.1.0: ( 0.000083s | 12.44% | 0.00% ) ( 0.000105s | 14.34% | 0.04% ) (1x) |-- echo 9.1
|-- 29.1.1: ( 0.000584s | 87.55% | 0.04% ) ( 0.000627s | 85.65% | 0.27% ) (1x) |-- echo 9.2 (&)
30.0.0: ( 0.002642s | 0.19% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 30.1.0: ( 0.000471s | 76.21% | 0.03% ) ( 0.000501s | 75.79% | 0.21% ) (1x) |-- echo 9.1a (&)
|-- 30.1.1: ( 0.000147s | 23.78% | 0.01% ) ( 0.000160s | 24.20% | 0.06% ) (1x) |-- echo 9.2a
31.0.0: ( 0.002324s | 0.17% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 31.1.0: ( 0.000071s | 12.63% | 0.00% ) ( 0.000086s | 14.09% | 0.03% ) (1x) |-- echo 9.1b
|-- 31.1.1: ( 0.000491s | 87.36% | 0.03% ) ( 0.000524s | 85.90% | 0.22% ) (1x) |-- echo 9.2b (&)
32.0.0: ( 0.002474s | 0.18% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 32.1.0: ( 0.000474s | 85.71% | 0.03% ) ( 0.000498s | 84.40% | 0.21% ) (1x) |-- echo 9.1c (&)
|-- 32.1.1: ( 0.000079s | 14.28% | 0.00% ) ( 0.000092s | 15.59% | 0.03% ) (1x) |-- echo 9.2c
33.0.0: ( 0.000575s | 0.04% ) ( 0.000610s | 0.26% ) (1x) << (SUBSHELL) >>
|-- 33.1.0: ( 0.000492s | 85.56% | 0.03% ) ( 0.000516s | 84.59% | 0.22% ) (1x) |-- echo 9.3 (&)
|-- 33.1.1: ( 0.000083s | 14.43% | 0.00% ) ( 0.000094s | 15.40% | 0.04% ) (1x) |-- echo 9.4
33.0.0: ( 0.008883s | 0.66% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 33.1.0: ( 0.004729s | 98.41% | 0.35% ) ( 0.005165s | 98.28% | 2.23% ) (1x) |-- echo 9.999
|-- 33.1.1: ( 0.000076s | 1.58% | 0.00% ) ( 0.000090s | 1.71% | 0.03% ) (1x) |-- echo 9.5
34.0.0: ( 0.004234s | 0.31% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 34.1.0: ( 0.001349s |100.00% | 0.10% ) ( 0.001443s |100.00% | 0.62% ) (1x) |-- echo 10 (&)
36.0.0: ( 0.000069s | 0.00% ) ( 0.000083s | 0.03% ) (1x) echo 11
37.0.0: ( 0.000752s | 0.05% ) ( 0.000438s | 0.18% ) (1x) echo 12 (&)
38.0.0: ( 0.000975s | 0.07% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 38.1.0: ( 0.000076s |100.00% | 0.00% ) ( 0.000092s |100.00% | 0.03% ) (1x) |-- echo 13
39.0.0: ( 0.000290s | 0.02% ) ( 0.000339s | 0.14% ) (1x) << (SUBSHELL) >>
|-- 39.1.0: ( 0.000290s |100.00% | 0.02% ) ( 0.000339s |100.00% | 0.14% ) (1x) |-- echo 14
41.0.0: ( 0.000132s | 0.00% ) ( 0.000160s | 0.06% ) (1x) << (FUNCTION): main.ff 15 >>
|-- 1.1.0: ( 0.000058s | 43.93% | 0.00% ) ( 0.000072s | 45.00% | 0.03% ) (1x) |-- ff 15
|-- 8.1.0: ( 0.000074s | 56.06% | 0.00% ) ( 0.000088s | 55.00% | 0.03% ) (1x) |-- echo "${*}"
42.0.0: ( 0.000263s | 0.01% ) ( 0.000314s | 0.13% ) (1x) << (FUNCTION): main.gg 16 >>
|-- 1.1.0: ( 0.000059s | 22.43% | 0.00% ) ( 0.000071s | 22.61% | 0.03% ) (1x) |-- gg 16
| 8.1.0: ( 0.000069s | 26.23% | 0.00% ) ( 0.000082s | 26.11% | 0.03% ) (1x) | echo "$*"
| 8.1.1: ( 0.000135s | 51.33% | 0.01% ) ( 0.000161s | 51.27% | 0.06% ) (1x) | << (FUNCTION): main.gg.ff "$@" >>
| |-- 1.2.0: ( 0.000058s | 42.96% | 0.00% ) ( 0.000071s | 44.09% | 0.03% ) (1x) | |-- ff "$@"
|-- |-- 8.2.0: ( 0.000077s | 57.03% | 0.00% ) ( 0.000090s | 55.90% | 0.03% ) (1x) |-- |-- echo "${*}"
44.0.0: ( 0.001767s | 0.13% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 44.1.0: ( 0.000533s |100.00% | 0.03% ) ( 0.000556s |100.00% | 0.24% ) (1x) |-- echo a (&)
45.0.0: ( 0.001520s | 0.11% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 45.1.0: ( 0.001520s |100.00% | 0.11% ) ( 0.000001s |100.00% | 0.00% ) (1x) |-- << (BACKGROUND FORK) >>
|-- |-- 45.2.0: ( 0.000127s |100.00% | 0.00% ) ( 0.000149s |100.00% | 0.06% ) (1x) |-- |-- echo b
47.0.0: ( 0.001245s | 0.09% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 47.1.0: ( 0.001245s |100.00% | 0.09% ) ( 0.000001s |100.00% | 0.00% ) (1x) |-- << (BACKGROUND FORK) >>
|-- |-- 47.2.0: ( 0.000095s |100.00% | 0.00% ) ( 0.000113s |100.00% | 0.04% ) (1x) |-- |-- echo A3
47.0.0: ( 0.001248s | 0.09% ) ( 0.001308s | 0.56% ) (1x) << (SUBSHELL) >>
|-- 47.1.0: ( 0.000557s | 44.63% | 0.04% ) ( 0.000584s | 44.64% | 0.25% ) (1x) |-- echo A2 (&)
| 47.1.1: ( 0.000596s | 47.75% | 0.04% ) ( 0.000618s | 47.24% | 0.26% ) (1x) | << (SUBSHELL) >>
| |-- 47.2.0: ( 0.000596s |100.00% | 0.04% ) ( 0.000618s |100.00% | 0.26% ) (1x) | |-- << (SUBSHELL) >>
| |-- |-- 47.3.0: ( 0.000596s |100.00% | 0.04% ) ( 0.000618s |100.00% | 0.26% ) (1x) | |-- |-- echo A5 (&)
|-- 47.1.2: ( 0.000095s | 7.61% | 0.00% ) ( 0.000106s | 8.10% | 0.04% ) (1x) |-- echo A1
47.0.1: ( 0.001398s | 0.10% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 47.1.0: ( 0.001398s |100.00% | 0.10% ) ( 0.000001s |100.00% | 0.00% ) (1x) |-- << (BACKGROUND FORK) >>
| |-- 47.2.0: ( 0.001398s |100.00% | 0.10% ) ( 0.000001s |100.00% | 0.00% ) (1x) | |-- << (BACKGROUND FORK) >>
|-- |-- |-- 47.3.0: ( 0.000112s |100.00% | 0.00% ) ( 0.000131s |100.00% | 0.05% ) (1x) |-- |-- |-- echo A4
50.0.0: ( 0.005058s | 0.37% ) ( 0.008785s | 3.80% ) (1x) cat <<EOF$'\n'foo$'\n'bar$'\n'baz$'\n'EOF | grep foo | sed 's/o/O/g' | wc -l
56.0.0: ( 0.000535s | 0.04% ) ( 0.000412s | 0.17% ) (1x) echo "today is $(date +%Y-%m-%d)"
56.0.1: ( 0.002812s | 0.21% ) ( 0.002812s | 1.21% ) (1x) << (SUBSHELL) >>
|-- 56.1.0: ( 0.002812s |100.00% | 0.21% ) ( 0.002812s |100.00% | 1.21% ) (1x) |-- date +%Y-%m-%d
57.0.0: ( 0.000762s | 0.05% ) ( 0.000643s | 0.27% ) (1x) x=$( ( echo nested; echo subshell ) | grep sub)
57.0.1: ( 0.000162s | 0.01% ) ( 0.000189s | 0.08% ) (1x) << (SUBSHELL) >>
|-- 57.1.1: ( 0.000162s |100.00% | 0.01% ) ( 0.000189s |100.00% | 0.08% ) (1x) |-- << (SUBSHELL) >>
| |-- 57.2.0: ( 0.000077s | 47.53% | 0.00% ) ( 0.000090s | 47.61% | 0.03% ) (1x) | |-- echo nested
|-- |-- 57.2.1: ( 0.000085s | 52.46% | 0.00% ) ( 0.000099s | 52.38% | 0.04% ) (1x) |-- |-- echo subshell
59.0.0: ( 0.000591s | 0.04% ) ( 0.000431s | 0.18% ) (1x) diff <(ls /) <(ls /tmp)
59.0.1: ( 0.006895s | 0.51% ) ( 0.006895s | 2.98% ) (2x) << (SUBSHELL) >>
|-- 59.1.0: ( 0.003547s |100.00% | 0.26% ) ( 0.003547s |100.00% | 1.53% ) (1x) |-- ls /
|-- 59.1.0: ( 0.003348s |100.00% | 0.25% ) ( 0.003348s |100.00% | 1.44% ) (1x) |-- ls /tmp
60.0.0: ( 0.000651s | 0.04% ) ( 0.000462s | 0.19% ) (1x) grep pattern <(sed 's/^/>>/' > /dev/null)
60.0.1: ( 0.002869s | 0.21% ) ( 0.002869s | 1.24% ) (1x) << (SUBSHELL) >>
|-- 60.1.0: ( 0.002869s |100.00% | 0.21% ) ( 0.002869s |100.00% | 1.24% ) (1x) |-- sed 's/^/>>/' > /dev/null
62.0.0: ( 0.043012s | 3.22% ) ( 0.000001s | 0.00% ) (1x) << (BACKGROUND FORK) >>
|-- 62.1.0: ( 0.000206s | 0.59% | 0.01% ) ( 0.000250s | 4.94% | 0.10% ) (3x) |-- for i in {1..3}
| 62.1.1: ( 0.000210s | 0.60% | 0.01% ) ( 0.000254s | 5.02% | 0.10% ) (3x) | echo "$i"
|-- 62.1.2: ( 0.034470s | 98.80% | 2.58% ) ( 0.004554s | 90.03% | 1.97% ) (3x) |-- sleep .01
63.0.0: ( 0.037336s | 2.79% ) ( 0.014949s | 6.46% ) (4x) read -r n <&${CO[0]}
63.0.1: ( 0.000235s | 0.01% ) ( 0.000277s | 0.11% ) (3x) printf "got %s\n" "$n"
65.0.0: ( 0.000094s | 0.00% ) ( 0.000112s | 0.04% ) (1x) let "x = 5 + 6"
66.0.0: ( 0.000101s | 0.00% ) ( 0.000117s | 0.05% ) (1x) arr=(one two three)
66.0.1: ( 0.000112s | 0.00% ) ( 0.000133s | 0.05% ) (1x) echo ${arr[@]}
67.0.0: ( 0.000092s | 0.00% ) ( 0.000111s | 0.04% ) (1x) ((i=0))
67.0.1: ( 0.000313s | 0.02% ) ( 0.000372s | 0.16% ) (4x) ((i<3))
67.0.2: ( 0.000237s | 0.01% ) ( 0.000284s | 0.12% ) (3x) echo "$i"
67.0.3: ( 0.000225s | 0.01% ) ( 0.000274s | 0.11% ) (3x) ((i++))
80.0.0: ( 0.000065s | 0.00% ) ( 0.000079s | 0.03% ) (1x) cmd="echo inside-eval"
81.0.0: ( 0.000069s | 0.00% ) ( 0.000085s | 0.03% ) (1x) eval "$cmd"
81.0.1: ( 0.000074s | 0.00% ) ( 0.000088s | 0.03% ) (1x) echo inside-eval
82.0.0: ( 0.000069s | 0.00% ) ( 0.000083s | 0.03% ) (1x) eval "eval \"$cmd\""
82.0.1: ( 0.000069s | 0.00% ) ( 0.000084s | 0.03% ) (1x) eval "echo inside-eval"
82.0.2: ( 0.000072s | 0.00% ) ( 0.000087s | 0.03% ) (1x) echo inside-eval
84.0.0: ( 0.019507s | 1.46% ) ( 0.019455s | 8.41% ) (1x) trap 'echo got USR1; sleep .01' USR1
85.0.0: ( 0.000080s | 0.00% ) ( 0.000095s | 0.04% ) (1x) kill -USR1 $BASHPID
-53.0.0: ( 0.016088s | 1.20% ) ( 0.006087s | 2.63% ) (1x) -'TRAP (USR1): echo got USR1\; sleep .01'
-48.0.0: ( 0.000075s | 0.00% ) ( 0.000089s | 0.03% ) (1x) -'TRAP (USR1): echo got USR1\; sleep .01'
86.0.0: ( 0.000074s | 0.00% ) ( 0.000089s | 0.03% ) (1x) echo after-signal
88.0.0: ( 0.001005s | 0.07% ) ( 0.000638s | 0.27% ) (1x) cat <(echo hi) <(echo bye) <(echo 1; echo 2; echo 3)
88.0.1: ( 0.000227s | 0.01% ) ( 0.000258s | 0.11% ) (1x) << (SUBSHELL) >>
|-- 88.1.0: ( 0.000227s |100.00% | 0.01% ) ( 0.000258s |100.00% | 0.11% ) (1x) |-- echo hi
88.0.2: ( 0.000118s | 0.00% ) ( 0.000139s | 0.06% ) (1x) << (SUBSHELL) >>
|-- 88.1.0: ( 0.000118s |100.00% | 0.00% ) ( 0.000139s |100.00% | 0.06% ) (1x) |-- echo bye
88.0.3: ( 0.000415s | 0.03% ) ( 0.000491s | 0.21% ) (1x) << (SUBSHELL) >>
|-- 88.1.0: ( 0.000274s | 66.02% | 0.02% ) ( 0.000322s | 65.58% | 0.13% ) (1x) |-- echo 1
| 88.1.1: ( 0.000071s | 17.10% | 0.00% ) ( 0.000085s | 17.31% | 0.03% ) (1x) | echo 2
|-- 88.1.2: ( 0.000070s | 16.86% | 0.00% ) ( 0.000084s | 17.10% | 0.03% ) (1x) |-- echo 3
90.0.0: ( 0.001466s | 0.10% ) ( 0.001541s | 0.66% ) (3x) for i in {1..3} (&)
90.0.1: ( 0.001271s | 0.09% ) ( 0.001361s | 0.58% ) (1x) << (SUBSHELL) >>
|-- 90.1.0: ( 0.001196s | 94.09% | 0.08% ) ( 0.001271s | 93.38% | 0.54% ) (1x) |-- seq 1 4
|-- 90.1.1: ( 0.000075s | 5.90% | 0.00% ) ( 0.000090s | 6.61% | 0.03% ) (1x) |-- :
90.0.1: ( 0.001415s | 0.10% ) ( 0.001505s | 0.65% ) (1x) << (SUBSHELL) >>
|-- 90.1.0: ( 0.001332s | 94.13% | 0.09% ) ( 0.001406s | 93.42% | 0.60% ) (1x) |-- seq 1 4
|-- 90.1.1: ( 0.000083s | 5.86% | 0.00% ) ( 0.000099s | 6.57% | 0.04% ) (1x) |-- :
90.0.1: ( 0.001578s | 0.11% ) ( 0.001653s | 0.71% ) (1x) << (SUBSHELL) >>
|-- 90.1.0: ( 0.001503s | 95.24% | 0.11% ) ( 0.001562s | 94.49% | 0.67% ) (1x) |-- seq 1 4
|-- 90.1.1: ( 0.000075s | 4.75% | 0.00% ) ( 0.000091s | 5.50% | 0.03% ) (1x) |-- :
91.0.0: ( 0.003792s | 0.28% ) ( 0.001403s | 0.60% ) (15x) read x
92.0.0: ( 0.004530s | 0.33% ) ( 0.003861s | 1.67% ) (12x) (( x % 2 == 0 ))
93.0.0: ( 0.000448s | 0.03% ) ( 0.000530s | 0.22% ) (6x) echo even "$x"
95.0.0: ( 0.000075s | 0.00% ) ( 0.000089s | 0.03% ) (1x) << (SUBSHELL) >>
|-- 95.1.0: ( 0.000075s |100.00% | 0.00% ) ( 0.000089s |100.00% | 0.03% ) (1x) |-- echo odd "$x"
95.0.0: ( 0.000076s | 0.00% ) ( 0.000089s | 0.03% ) (1x) << (SUBSHELL) >>
|-- 95.1.0: ( 0.000076s |100.00% | 0.00% ) ( 0.000089s |100.00% | 0.03% ) (1x) |-- echo odd "$x"
95.0.0: ( 0.000109s | 0.00% ) ( 0.000128s | 0.05% ) (1x) << (SUBSHELL) >>
|-- 95.1.0: ( 0.000109s |100.00% | 0.00% ) ( 0.000128s |100.00% | 0.05% ) (1x) |-- echo odd "$x"
95.0.0: ( 0.000162s | 0.01% ) ( 0.000188s | 0.08% ) (1x) << (SUBSHELL) >>
|-- 95.1.0: ( 0.000162s |100.00% | 0.01% ) ( 0.000188s |100.00% | 0.08% ) (1x) |-- echo odd "$x"
95.0.0: ( 0.000176s | 0.01% ) ( 0.000199s | 0.08% ) (1x) << (SUBSHELL) >>
|-- 95.1.0: ( 0.000176s |100.00% | 0.01% ) ( 0.000199s |100.00% | 0.08% ) (1x) |-- echo odd "$x"
100.0.0: ( 0.000438s | 0.03% ) ( 0.000460s | 0.19% ) (1x) sleep 1 (&)
101.0.0: ( 1.002439s | 75.04% ) ( 0.001653s | 0.71% ) (1x) wait -n $!
104.0.0: ( 0.018994s | 1.42% ) ( 0.018969s | 8.20% ) (1x) << (SUBSHELL) >>
|-- 104.1.0: ( 0.017245s | 90.79% | 1.29% ) ( 0.017204s | 90.69% | 7.44% ) (1x) |-- trap 'echo bye' EXIT
| 105.1.0: ( 0.000075s | 0.39% | 0.00% ) ( 0.000085s | 0.44% | 0.03% ) (1x) | exit
|-- -53.1.0: ( 0.001674s | 8.81% | 0.12% ) ( 0.001680s | 8.85% | 0.72% ) (1x) |-- -'TRAP (EXIT): echo bye'
109.0.0: ( 0.025747s | 1.92% ) ( 0.025759s | 11.14% ) (1x) << (SUBSHELL) >>
|-- 109.1.0: ( 0.020312s | 78.89% | 1.52% ) ( 0.020265s | 78.67% | 8.76% ) (1x) |-- trap 'echo bye' RETURN EXIT
| 110.1.0: ( 0.003594s | 13.95% | 0.26% ) ( 0.003662s | 14.21% | 1.58% ) (1x) | << (FUNCTION): main.gg 1 >>
| |-- 1.2.0: ( 0.000063s | 1.75% | 0.00% ) ( 0.000072s | 1.96% | 0.03% ) (1x) | |-- gg 1
| | 8.2.0: ( 0.000068s | 1.89% | 0.00% ) ( 0.000081s | 2.21% | 0.03% ) (1x) | | echo "$*"
| | 8.2.1: ( 0.001806s | 50.25% | 0.13% ) ( 0.001841s | 50.27% | 0.79% ) (1x) | | << (FUNCTION): main.gg.ff "$@" >>
| | |-- 1.3.0: ( 0.000059s | 3.26% | 0.00% ) ( 0.000074s | 4.01% | 0.03% ) (1x) | | |-- ff "$@"
| | |-- 8.3.0: ( 0.001747s | 96.73% | 0.13% ) ( 0.001767s | 95.98% | 0.76% ) (2x) | | |-- echo "${*}"
| |-- 8.2.2: ( 0.001657s | 46.10% | 0.12% ) ( 0.001668s | 45.54% | 0.72% ) (1x) | |-- echo "${*}"
| 111.1.0: ( 0.000076s | 0.29% | 0.00% ) ( 0.000086s | 0.33% | 0.03% ) (1x) | exit
|-- -53.1.0: ( 0.001765s | 6.85% | 0.13% ) ( 0.001746s | 6.77% | 0.75% ) (1x) |-- -'TRAP (EXIT): echo bye'
115.0.0: ( 0.038002s | 2.84% ) ( 0.038024s | 16.44% ) (1x) << (SUBSHELL) >>
|-- 115.1.0: ( 0.017389s | 45.75% | 1.30% ) ( 0.017356s | 45.64% | 7.50% ) (1x) |-- trap 'echo exit' EXIT
| 116.1.0: ( 0.015303s | 40.26% | 1.14% ) ( 0.015258s | 40.12% | 6.60% ) (1x) | trap 'echo return' RETURN
| 117.1.0: ( 0.003589s | 9.44% | 0.26% ) ( 0.003668s | 9.64% | 1.58% ) (1x) | << (FUNCTION): main.gg 1 >>
| |-- 1.2.0: ( 0.000057s | 1.58% | 0.00% ) ( 0.000071s | 1.93% | 0.03% ) (1x) | |-- gg 1
| | 8.2.0: ( 0.000081s | 2.25% | 0.00% ) ( 0.000093s | 2.53% | 0.04% ) (1x) | | echo "$*"
| | 8.2.1: ( 0.001805s | 50.29% | 0.13% ) ( 0.001852s | 50.49% | 0.80% ) (1x) | | << (FUNCTION): main.gg.ff "$@" >>
| | |-- 1.3.0: ( 0.000056s | 3.10% | 0.00% ) ( 0.000069s | 3.72% | 0.02% ) (1x) | | |-- ff "$@"
| | |-- 8.3.0: ( 0.001749s | 96.89% | 0.13% ) ( 0.001783s | 96.27% | 0.77% ) (2x) | | |-- echo "${*}"
| |-- 8.2.2: ( 0.001646s | 45.86% | 0.12% ) ( 0.001652s | 45.03% | 0.71% ) (1x) | |-- echo "${*}"
| 118.1.0: ( 0.000069s | 0.18% | 0.00% ) ( 0.000082s | 0.21% | 0.03% ) (1x) | exit
|-- -53.1.0: ( 0.001652s | 4.34% | 0.12% ) ( 0.001660s | 4.36% | 0.71% ) (1x) |-- -'TRAP (EXIT): echo exit'
123.0.0: ( 0.017856s | 1.33% ) ( 0.017835s | 7.71% ) (1x) << (SUBSHELL) >>
|-- 123.1.0: ( 0.017783s | 99.59% | 1.33% ) ( 0.017749s | 99.51% | 7.67% ) (1x) |-- trap '' RETURN EXIT
|-- 124.1.0: ( 0.000073s | 0.40% | 0.00% ) ( 0.000086s | 0.48% | 0.03% ) (1x) |-- exit
129.0.0: ( 0.014348s | 1.07% ) ( 0.014318s | 6.19% ) (1x) << (SUBSHELL) >>
|-- 129.1.0: ( 0.014272s | 99.47% | 1.06% ) ( 0.014233s | 99.40% | 6.15% ) (1x) |-- trap - EXIT
|-- 130.1.0: ( 0.000076s | 0.52% | 0.00% ) ( 0.000085s | 0.59% | 0.03% ) (1x) |-- exit
133.0.0: ( 0.000933s | 0.06% ) ( 0.001064s | 0.46% ) (1x) << (SUBSHELL) >>
|-- 133.1.0: ( 0.000213s | 22.82% | 0.01% ) ( 0.000242s | 22.74% | 0.10% ) (1x) |-- echo $BASHPID
| 133.1.1: ( 0.000720s | 77.17% | 0.05% ) ( 0.000822s | 77.25% | 0.35% ) (1x) | << (SUBSHELL) >>
| |-- 133.2.0: ( 0.000312s | 43.33% | 0.02% ) ( 0.000367s | 44.64% | 0.15% ) (1x) | |-- echo $BASHPID
| | 133.2.1: ( 0.000408s | 56.66% | 0.03% ) ( 0.000455s | 55.35% | 0.19% ) (1x) | | << (SUBSHELL) >>
| | |-- 133.3.0: ( 0.000103s | 25.24% | 0.00% ) ( 0.000102s | 22.41% | 0.04% ) (1x) | | |-- echo $BASHPID
| | | 133.3.1: ( 0.000305s | 74.75% | 0.02% ) ( 0.000353s | 77.58% | 0.15% ) (1x) | | | << (SUBSHELL) >>
|-- |-- |-- |-- 133.4.0: ( 0.000305s |100.00% | 0.02% ) ( 0.000353s |100.00% | 0.15% ) (1x) |-- |-- |-- |-- echo $BASHPID
TOTAL RUN TIME: 1.335700s
TOTAL CPU TIME: 0.231161s
and generates this flamegraph (that shows both the wall-clock time flamegraph and the CPU-time flamegraph).
Note: stack overflow doesn't support SVG images, so I've converted it to a PNG image below. the SVG image I linked (on github) has tooltips and will zoom in on clicking a box and search and things like that. the best way to ensure all the "extras" work is to download the SVG image and then open the local copy.