1The following are examples of sh_flowinfo.d. 2 3This is a simple script to trace the flow of Bourne shell functions, 4builtins and external commands. Here it traces the example program, 5Code/Shell/func_abc.sh. 6 7 # sh_flowinfo.d 8 C PID DELTA(us) FILE:LINE TYPE -- NAME 9 0 19634 2 func_abc.sh:23 func -> func_a 10 0 19634 24 func_abc.sh:18 builtin -> echo 11 0 19634 41 func_abc.sh:- builtin <- echo 12 0 19634 5873 func_abc.sh:19 cmd -> sleep 13 0 19634 999373 func_abc.sh:- cmd <- sleep 14 0 19634 39 func_abc.sh:20 func -> func_b 15 0 19634 22 func_abc.sh:11 builtin -> echo 16 0 19634 40 func_abc.sh:- builtin <- echo 17 0 19634 4661 func_abc.sh:12 cmd -> sleep 18 0 19634 1005349 func_abc.sh:- cmd <- sleep 19 0 19634 49 func_abc.sh:13 func -> func_c 20 0 19634 22 func_abc.sh:5 builtin -> echo 21 0 19634 38 func_abc.sh:- builtin <- echo 22 0 19634 4949 func_abc.sh:6 cmd -> sleep 23 0 19634 1004817 func_abc.sh:- cmd <- sleep 24 0 19634 36 func_abc.sh:- func <- func_c 25 0 19634 14 func_abc.sh:- func <- func_b 26 0 19634 8 func_abc.sh:- func <- func_a 27 28As each function is entered, the third column is indented by 2 spaces. This 29shows which function is calling who - the output abovebegins by showing that 30func_a() began, and then called func_b(). 31 32The DELTA(us) column shows time from that line to the previous line, and 33so can be a bit tricky to read. For example, the fifth line of data output 34(skipping the header) reads as "the time from the command sleep beginning 35to ending was 999373 us, or 1.0 seconds". 36 37The LINE column shows the line in the file what was being executed. Refer 38to the source program to see what this line refers to. 39 40If the output looks shuffled, check the CPU "C" column - if it changes, 41then the output is probably shuffled. See Notes/ALLsnoop_notes.txt for 42details and suggested workarounds. 43 44See Notes/ALLflow_notes.txt for important notes about reading flow outputs. 45 46 47The following traces the firefox startup script. 48 49# sh_flowinfo.d 50 C PID DELTA(us) FILE:LINE TYPE -- NAME 51 0 156789 1 firefox:- subsh -> pid 156790 52 0 156789 20 firefox:- subsh <- = 0 53 0 156789 31651 firefox:- subsh -> pid 156791 54 0 156789 20 firefox:- subsh <- = 0 55 0 156789 10502 firefox:109 builtin -> test 56 0 156789 59 firefox:- builtin <- test 57 0 156789 3804 firefox:- subsh -> pid 156792 58 0 156789 21 firefox:- subsh <- = 0 59 0 156789 22029 firefox:114 builtin -> [ 60 0 156789 57 firefox:- builtin <- [ 61 0 156789 90910 firefox:- subsh -> pid 156793 62 0 156789 22 firefox:- subsh <- = 0 63 0 156789 159492 firefox:- subsh -> pid 156794 64 0 156789 22 firefox:- subsh <- = 0 65 0 156789 127 firefox:116 builtin -> cd 66 0 156789 54 firefox:- builtin <- cd 67 0 156789 209757 firefox:- subsh -> pid 156795 68 0 156789 23 firefox:- subsh <- = 0 69 0 156795 206160 firefox:- subsh -> pid 156796 70 0 156795 9 firefox:- subsh <- = 0 71 0 156789 12115 firefox:118 builtin -> [ 72 0 156789 61 firefox:- builtin <- [ 73 0 156789 200529 firefox:- subsh -> pid 156797 74 0 156789 24 firefox:- subsh <- = 0 75 0 156789 136 firefox:123 builtin -> [ 76 0 156789 58 firefox:- builtin <- [ 77 0 156789 21 firefox:124 builtin -> cd 78 0 156789 19 firefox:- builtin <- cd 79 0 156798 175 firefox:1 builtin -> pwd 80 0 156798 65 firefox:- builtin <- pwd 81 0 156789 108835 firefox:- subsh -> pid 156798 82 0 156789 18 firefox:- subsh <- = 0 83 0 156789 119 firefox:128 builtin -> break 84 0 156789 15 firefox:- builtin <- break 85 0 156789 21 firefox:131 builtin -> cd 86 0 156789 26 firefox:- builtin <- cd 87 0 156789 61 firefox:133 builtin -> [ 88 0 156789 9 firefox:- builtin <- [ 89 0 156789 73508 firefox:147 builtin -> [ 90 0 156789 25 firefox:- builtin <- [ 91 0 156800 184 firefox:1 builtin -> echo 92 0 156800 175 firefox:- builtin <- echo 93 0 156789 15966 firefox:- subsh -> pid 156799 94 0 156789 22 firefox:- subsh <- = 0 95 0 156799 12091 firefox:- subsh -> pid 156800 96 0 156799 10 firefox:- subsh <- = 0 97 0 156802 178 firefox:1 builtin -> echo 98 0 156802 167 firefox:- builtin <- echo 99 0 156789 13822 firefox:- subsh -> pid 156801 100 0 156789 18 firefox:- subsh <- = 0 101 0 156801 81683 firefox:- subsh -> pid 156802 102 0 156801 21 firefox:- subsh <- = 0 103 0 156789 78324 firefox:158 builtin -> [ 104 0 156789 37 firefox:- builtin <- [ 105 0 156789 54 firefox:194 builtin -> export 106 0 156789 9 firefox:- builtin <- export 107 0 156789 26 firefox:197 func -> moz_pis_startstop_scripts 108 0 156789 61 firefox:62 builtin -> export 109 0 156789 9 firefox:- builtin <- export 110 0 156789 413 firefox:67 builtin -> [ 111 0 156789 34 firefox:- builtin <- [ 112 0 156789 40 firefox:69 builtin -> . 113 0 156789 20833 firefox:18 func -> moz_spc_verbose_echo 114 0 156789 26 firefox:15 builtin -> : 115 0 156789 16 firefox:- builtin <- : 116 0 156789 15 firefox:- func <- moz_spc_verbose_echo 117 0 156789 105106 firefox:- subsh -> pid 156803 118 0 156789 22 firefox:- subsh <- = 0 119 0 156789 129 firefox:19 builtin -> [ 120 0 156789 17 firefox:- builtin <- [ 121 0 156789 33 firefox:20 func -> moz_spc_verbose_echo 122 0 156789 14 firefox:15 builtin -> : 123 0 156789 7 firefox:- builtin <- : 124 0 156789 9 firefox:- func <- moz_spc_verbose_echo 125 0 156789 21 firefox:23 builtin -> [ 126 0 156789 8 firefox:- builtin <- [ 127 0 156789 16 firefox:26 builtin -> [ 128 0 156789 8 firefox:- builtin <- [ 129 0 156789 24 firefox:29 builtin -> [ 130 0 156789 43 firefox:- builtin <- [ 131 0 156789 77 firefox:36 func -> moz_spc_verbose_echo 132 0 156789 9 firefox:15 builtin -> : 133 0 156789 8 firefox:- builtin <- : 134 0 156789 8 firefox:- func <- moz_spc_verbose_echo 135 0 156789 158947 firefox:- subsh -> pid 156804 136 0 156789 22 firefox:- subsh <- = 0 137 0 156789 210112 firefox:- subsh -> pid 156805 138 0 156789 22 firefox:- subsh <- = 0 139 0 156805 205500 firefox:- subsh -> pid 156806 140 0 156805 10 firefox:- subsh <- = 0 141 0 156805 200987 firefox:- subsh -> pid 156807 142 0 156805 20 firefox:- subsh <- = 0 143 0 156789 363564 firefox:40 func -> moz_spc_verbose_echo 144 0 156789 26 firefox:15 builtin -> : 145 0 156789 17 firefox:- builtin <- : 146 0 156789 15 firefox:- func <- moz_spc_verbose_echo 147 0 156809 234 firefox:1 builtin -> [ 148 0 156809 70 firefox:- builtin <- [ 149 0 156789 46950 firefox:- subsh -> pid 156808 150 0 156789 22 firefox:- subsh <- = 0 151 0 156808 42371 firefox:- subsh -> pid 156809 152 0 156808 10 firefox:- subsh <- = 0 153 0 156789 27278 firefox:43 builtin -> [ 154 0 156789 26 firefox:- builtin <- [ 155 0 156789 62 firefox:44 func -> moz_spc_verbose_echo 156 0 156789 15 firefox:15 builtin -> : 157 0 156789 8 firefox:- builtin <- : 158 0 156789 10 firefox:- func <- moz_spc_verbose_echo 159 0 156789 30 firefox:67 func -> moz_spc_verbose_echo 160 0 156789 9 firefox:15 builtin -> : 161 0 156789 8 firefox:- builtin <- : 162 0 156789 7 firefox:- func <- moz_spc_verbose_echo 163 0 156789 8 firefox:- builtin <- . 164 0 156789 28 firefox:67 builtin -> [ 165 0 156789 31 firefox:- builtin <- [ 166 0 156789 8 firefox:- func <- moz_pis_startstop_scripts 167 0 156789 97 firefox:199 builtin -> [ 168 0 156789 35 firefox:- builtin <- [ 169 0 156789 29 firefox:205 builtin -> [ 170 0 156789 9 firefox:- builtin <- [ 171 0 156789 72519 firefox:209 cmd -> /usr/lib/firefox/run-mozilla.sh 172 0 156810 1 run-mozilla.sh:- subsh -> pid 156811 173 0 156810 15 run-mozilla.sh:- subsh <- = 0 174 0 156810 129474 run-mozilla.sh:- subsh -> pid 156812 175 0 156810 24 run-mozilla.sh:- subsh <- = 0 176 0 156810 743 run-mozilla.sh:258 builtin -> [ 177 0 156810 28 run-mozilla.sh:- builtin <- [ 178 0 156810 212 run-mozilla.sh:275 builtin -> break 179 0 156810 10 run-mozilla.sh:- builtin <- break 180 0 156810 31 run-mozilla.sh:283 builtin -> [ 181 0 156810 10 run-mozilla.sh:- builtin <- [ 182 0 156810 16 run-mozilla.sh:286 builtin -> shift 183 0 156810 9 run-mozilla.sh:- builtin <- shift 184 0 156810 55 run-mozilla.sh:291 builtin -> [ 185 0 156810 9 run-mozilla.sh:- builtin <- [ 186 0 156810 36 run-mozilla.sh:317 builtin -> [ 187 0 156810 34 run-mozilla.sh:- builtin <- [ 188 0 156810 37 run-mozilla.sh:327 builtin -> [ 189 0 156810 9 run-mozilla.sh:- builtin <- [ 190 0 156810 142 run-mozilla.sh:362 builtin -> [ 191 0 156810 9 run-mozilla.sh:- builtin <- [ 192 0 156810 26 run-mozilla.sh:366 builtin -> export 193 0 156810 9 run-mozilla.sh:- builtin <- export 194 0 156810 37 run-mozilla.sh:369 builtin -> [ 195 0 156810 9 run-mozilla.sh:- builtin <- [ 196 0 156810 18 run-mozilla.sh:371 builtin -> [ 197 0 156810 19 run-mozilla.sh:- builtin <- [ 198 0 156810 112 run-mozilla.sh:379 builtin -> [ 199 0 156810 10 run-mozilla.sh:- builtin <- [ 200 0 156810 23 run-mozilla.sh:418 builtin -> export 201 0 156810 9 run-mozilla.sh:- builtin <- export 202 0 156810 45 run-mozilla.sh:419 builtin -> export 203 0 156810 10 run-mozilla.sh:- builtin <- export 204 0 156810 27 run-mozilla.sh:421 builtin -> [ 205 0 156810 9 run-mozilla.sh:- builtin <- [ 206 0 156810 29 run-mozilla.sh:425 func -> moz_run_program 207 0 156810 32 run-mozilla.sh:137 builtin -> [ 208 0 156810 25 run-mozilla.sh:- builtin <- [ 209 0 156810 20 run-mozilla.sh:145 func -> moz_test_binary 210 0 156810 17 run-mozilla.sh:97 builtin -> [ 211 0 156810 23 run-mozilla.sh:- builtin <- [ 212 0 156810 15 run-mozilla.sh:99 builtin -> [ 213 0 156810 26 run-mozilla.sh:- builtin <- [ 214 0 156810 13 run-mozilla.sh:101 builtin -> return 215 0 156810 9 run-mozilla.sh:- builtin <- return 216 0 156810 11 run-mozilla.sh:- func <- moz_test_binary 217 0 156810 18 run-mozilla.sh:146 builtin -> [ 218 0 156810 9 run-mozilla.sh:- builtin <- [ 219 0 156814 185 run-mozilla.sh:1 builtin -> type 220 0 156814 118188 run-mozilla.sh:- builtin <- type 221 0 156810 167284 run-mozilla.sh:- subsh -> pid 156813 222 0 156810 23 run-mozilla.sh:- subsh <- = 0 223 0 156813 162135 run-mozilla.sh:- subsh -> pid 156814 224 0 156813 12 run-mozilla.sh:- subsh <- = 0 225 0 156813 200125 run-mozilla.sh:- subsh -> pid 156815 226 0 156813 22 run-mozilla.sh:- subsh <- = 0 227 0 156810 203465 run-mozilla.sh:152 builtin -> [ 228 0 156810 51 run-mozilla.sh:- builtin <- [ 229 0 156810 21 run-mozilla.sh:156 builtin -> [ 230 0 156810 9 run-mozilla.sh:- builtin <- [ 231 0 156810 15 run-mozilla.sh:159 builtin -> [ 232 0 156810 14 run-mozilla.sh:- builtin <- [ 233 0 156810 65752 run-mozilla.sh:- subsh -> pid 156816 234 0 156810 24 run-mozilla.sh:- subsh <- = 0 235 0 156816 251788 run-mozilla.sh:- subsh -> pid 156817 236 0 156816 22 run-mozilla.sh:- subsh <- = 0 237 0 156810 299677 run-mozilla.sh:167 cmd -> /usr/lib/firefox/firefox-bin 238 0 156810 5124906 run-mozilla.sh:- cmd <- /usr/lib/firefox/firefox-bin 239 0 156789 5993798 firefox:- cmd <- /usr/lib/firefox/run-mozilla.sh 240 241Now latencies can investigated by line number. 242 243