1 The following are examples of sh_flowtime.d.
3 This is a simple script to trace the flow of Bourne shell functions,
4 builtins and external commands. Here it traces the example program,
5 Code/Shell/func_abc.sh.
8 C TIME(us) FILE DELTA(us) -- NAME
9 0 3060817866026 func_abc.sh 2 -> func_a
10 0 3060817866086 func_abc.sh 60 > echo
11 0 3060818871601 func_abc.sh 1005514 | sleep
12 0 3060818871639 func_abc.sh 38 -> func_b
13 0 3060818871684 func_abc.sh 44 > echo
14 0 3060819881597 func_abc.sh 1009912 | sleep
15 0 3060819881657 func_abc.sh 60 -> func_c
16 0 3060819881717 func_abc.sh 60 > echo
17 0 3060820891613 func_abc.sh 1009896 | sleep
18 0 3060820891661 func_abc.sh 47 <- func_c
19 0 3060820891675 func_abc.sh 14 <- func_b
20 0 3060820891683 func_abc.sh 7 <- func_a
23 As each function is entered, the third column is indented by 2 spaces. This
24 shows which function is calling who - the output above begins by showing that
25 func_a() began, and then called func_b().
27 The DELTA(us) column is interpreted as follows,
29 -> previous line to the start of this function
30 <- previous line to the end of this function
31 > previous line to the end of this builtin
32 | previous line to the end of this command
34 And so the above output shows that each sleep command is taking around 1.0
37 If the output looks shuffled, check the CPU "C" and "TIME" columns, and
38 post sort based on TIME if necessary.
40 See Notes/ALLflow_notes.txt for important notes about reading flow outputs.
44 The following traces the firefox start script.
47 C TIME(us) FILE DELTA(us) -- NAME
48 0 3060994282580 firefox 2 > test
49 0 3060994286921 firefox 4341 > [
50 0 3060994286955 firefox 34 > cd
51 0 3060994287014 firefox 58 > [
52 0 3060994287059 firefox 45 > [
53 0 3060994287227 firefox 167 > [
54 0 3060994293793 firefox 2 > echo
55 0 3060994305759 firefox 2 > echo
56 0 3060994309613 firefox 22385 > [
57 0 3060994309665 firefox 52 > export
58 0 3060994309691 firefox 25 -> moz_pis_startstop_scripts
59 0 3060994309752 firefox 61 > export
60 0 3060994310199 firefox 447 > [
61 0 3060994314462 firefox 4262 -> moz_spc_verbose_echo
62 0 3060994314484 firefox 22 > :
63 0 3060994314497 firefox 12 <- moz_spc_verbose_echo
64 0 3060994322101 firefox 7604 > [
65 0 3060994322134 firefox 33 -> moz_spc_verbose_echo
66 0 3060994322147 firefox 12 > :
67 0 3060994322155 firefox 7 <- moz_spc_verbose_echo
68 0 3060994322501 firefox 345 > [
69 0 3060994322518 firefox 17 > [
70 0 3060994322578 firefox 59 > [
71 0 3060994322641 firefox 62 -> moz_spc_verbose_echo
72 0 3060994322650 firefox 9 > :
73 0 3060994322656 firefox 6 <- moz_spc_verbose_echo
74 0 3060994653794 firefox 331137 -> moz_spc_verbose_echo
75 0 3060994653826 firefox 32 > :
76 0 3060994653839 firefox 12 <- moz_spc_verbose_echo
77 0 3060994659534 firefox 2 > [
78 0 3060994667539 firefox 13699 > [
79 0 3060994667604 firefox 65 -> moz_spc_verbose_echo
80 0 3060994667617 firefox 13 > :
81 0 3060994667625 firefox 8 <- moz_spc_verbose_echo
82 0 3060994667653 firefox 27 -> moz_spc_verbose_echo
83 0 3060994667661 firefox 7 > :
84 0 3060994667668 firefox 6 <- moz_spc_verbose_echo
85 0 3060994667675 firefox 7 > .
86 0 3060994667725 firefox 49 > [
87 0 3060994667732 firefox 6 <- moz_pis_startstop_scripts
88 0 3060994667853 firefox 121 > [
89 0 3060994667881 firefox 27 > [
90 0 3060994804329 run-mozilla.sh 2 > [
91 0 3060994804524 run-mozilla.sh 194 > break
92 0 3060994804560 run-mozilla.sh 36 > [
93 0 3060994804580 run-mozilla.sh 20 > shift
94 0 3060994804649 run-mozilla.sh 68 > [
95 0 3060994804710 run-mozilla.sh 61 > [
96 0 3060994804747 run-mozilla.sh 36 > [
97 0 3060994804889 run-mozilla.sh 142 > [
98 0 3060994804915 run-mozilla.sh 26 > export
99 0 3060994804952 run-mozilla.sh 36 > [
100 0 3060994804981 run-mozilla.sh 28 > [
101 0 3060994805093 run-mozilla.sh 112 > [
102 0 3060994805116 run-mozilla.sh 22 > export
103 0 3060994805160 run-mozilla.sh 44 > export
104 0 3060994805187 run-mozilla.sh 27 > [
105 0 3060994805215 run-mozilla.sh 27 -> moz_run_program
106 0 3060994805263 run-mozilla.sh 48 > [
107 0 3060994805283 run-mozilla.sh 19 -> moz_test_binary
108 0 3060994805314 run-mozilla.sh 31 > [
109 0 3060994805346 run-mozilla.sh 31 > [
110 0 3060994805358 run-mozilla.sh 12 > return
111 0 3060994805367 run-mozilla.sh 9 <- moz_test_binary
112 0 3060994805385 run-mozilla.sh 17 > [
113 0 3060994964498 run-mozilla.sh 2 > type
114 0 3060995520942 run-mozilla.sh 715556 > [
115 0 3060995520967 run-mozilla.sh 24 > [
116 0 3060995520987 run-mozilla.sh 20 > [
117 0 3061000622172 run-mozilla.sh 5101184 | /usr/lib/firefox/firefox-bin
118 0 3061000622221 run-mozilla.sh 49 > [
119 0 3061000622252 run-mozilla.sh 30 > [
120 0 3061000622266 run-mozilla.sh 14 > [
121 0 3061000622275 run-mozilla.sh 9 <- moz_run_program
122 0 3061000623686 firefox 5955805 | /usr/lib/firefox/run-mozilla.sh
123 0 3061000623793 firefox 106 -> moz_pis_startstop_scripts
124 0 3061000623864 firefox 71 > export
125 0 3061000624108 firefox 244 > [
126 0 3061000624138 firefox 30 > [
127 0 3061000624147 firefox 8 <- moz_pis_startstop_scripts
129 Points of latency during startup are visible in the output. For more details,
130 see Examples/sh_flowinfo_example.txt.