1The following are examples of sh_flowtime.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_flowtime.d 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 21 ^C 22 23As each function is entered, the third column is indented by 2 spaces. This 24shows which function is calling who - the output above begins by showing that 25func_a() began, and then called func_b(). 26 27The DELTA(us) column is interpreted as follows, 28 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 33 34And so the above output shows that each sleep command is taking around 1.0 35seconds to execute. 36 37If the output looks shuffled, check the CPU "C" and "TIME" columns, and 38post sort based on TIME if necessary. 39 40See Notes/ALLflow_notes.txt for important notes about reading flow outputs. 41 42 43 44The following traces the firefox start script. 45 46# sh_flowtime.d 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 128 129Points of latency during startup are visible in the output. For more details, 130see Examples/sh_flowinfo_example.txt. 131 132