1*c29d5175SchristosThe following are examples of pl_flowinfo.d. 2*c29d5175Schristos 3*c29d5175SchristosThis is a simple script to trace the flow of Perl subroutines (functions). 4*c29d5175SchristosHere it traces the example program, Code/Perl/func_abc.pl. 5*c29d5175Schristos 6*c29d5175Schristos # pl_flowinfo.d 7*c29d5175Schristos C PID DELTA(us) FILE:LINE TYPE -- SUB 8*c29d5175Schristos 0 305127 2 func_abc.pl:15 sub -> func_a 9*c29d5175Schristos 0 305127 1008776 func_abc.pl:9 sub -> func_b 10*c29d5175Schristos 0 305127 1010019 func_abc.pl:4 sub -> func_c 11*c29d5175Schristos 0 305127 1009979 func_abc.pl:4 sub <- func_c 12*c29d5175Schristos 0 305127 26 func_abc.pl:9 sub <- func_b 13*c29d5175Schristos 0 305127 9 func_abc.pl:15 sub <- func_a 14*c29d5175Schristos ^C 15*c29d5175Schristos 16*c29d5175SchristosAs each subroutine is entered, the third column is indented by 2 spaces. This 17*c29d5175Schristosshows which subroutine is calling who - the output abovebegins by showing that 18*c29d5175Schristosfunc_a() began, and then called func_b(). 19*c29d5175Schristos 20*c29d5175SchristosThe DELTA(us) column shows time from that line to the previous line, and 21*c29d5175Schristosso can be a bit tricky to read. For example, the second line of data output 22*c29d5175Schristos(skipping the header) reads as "the time from func_a() beginning to 23*c29d5175Schristosfunc_b() beginning was 1008776 us, or 1.01 seconds". 24*c29d5175Schristos 25*c29d5175SchristosThe LINE column shows the line in the file what was being executed. Refer 26*c29d5175Schristosto the source program to see what this line refers to. 27*c29d5175Schristos 28*c29d5175SchristosIf the output looks shuffled, check the CPU "C" column - if it changes, 29*c29d5175Schristosthen the output is probably shuffled. See Notes/ALLsnoop_notes.txt for 30*c29d5175Schristosdetails and suggested workarounds. 31*c29d5175Schristos 32*c29d5175SchristosSee Notes/ALLflow_notes.txt for important notes about reading flow outputs. 33*c29d5175Schristos 34*c29d5175Schristos 35*c29d5175Schristos 36*c29d5175SchristosThe following traces a Perl network interface statistics tool, "nicstat" 37*c29d5175Schristosversion 0.99, 38*c29d5175Schristos 39*c29d5175Schristos# pl_flowinfo.d 40*c29d5175SchristosC PID DELTA(us) FILE:LINE TYPE -- SUB 41*c29d5175Schristos0 305132 2 nicstat:83 sub -> BEGIN 42*c29d5175Schristos0 305132 444 strict.pm:12 sub -> bits 43*c29d5175Schristos0 305132 34 strict.pm:12 sub <- bits 44*c29d5175Schristos0 305132 32 strict.pm:28 sub -> import 45*c29d5175Schristos0 305132 22 strict.pm:28 sub <- import 46*c29d5175Schristos0 305132 8 nicstat:83 sub <- BEGIN 47*c29d5175Schristos0 305132 26 nicstat:84 sub -> BEGIN 48*c29d5175Schristos0 305132 2339 Exporter.pm:30 sub -> import 49*c29d5175Schristos0 305132 83 Exporter.pm:30 sub <- import 50*c29d5175Schristos0 305132 14 nicstat:84 sub <- BEGIN 51*c29d5175Schristos0 305132 27 nicstat:85 sub -> BEGIN 52*c29d5175Schristos0 305132 205 Kstat.pm:34 sub -> BEGIN 53*c29d5175Schristos0 305132 11 strict.pm:28 sub -> import 54*c29d5175Schristos0 305132 11 strict.pm:28 sub <- import 55*c29d5175Schristos0 305132 8 Kstat.pm:34 sub <- BEGIN 56*c29d5175Schristos0 305132 23 Kstat.pm:35 sub -> BEGIN 57*c29d5175Schristos0 305132 187 DynaLoader.pm:18 sub -> BEGIN 58*c29d5175Schristos0 305132 73 vars.pm:3 sub -> BEGIN 59*c29d5175Schristos0 305132 9 vars.pm:3 sub <- BEGIN 60*c29d5175Schristos0 305132 34 vars.pm:7 sub -> BEGIN 61*c29d5175Schristos0 305132 470 warnings.pm:134 sub -> BEGIN 62*c29d5175Schristos0 305132 598 warnings.pm:134 sub <- BEGIN 63*c29d5175Schristos0 305132 2151 register.pm:37 sub -> import 64*c29d5175Schristos0 305132 23 register.pm:28 sub -> mkMask 65*c29d5175Schristos0 305132 13 register.pm:28 sub <- mkMask 66*c29d5175Schristos0 305132 53 register.pm:28 sub -> mkMask 67*c29d5175Schristos0 305132 11 register.pm:28 sub <- mkMask 68*c29d5175Schristos0 305132 11 register.pm:37 sub <- import 69*c29d5175Schristos0 305132 8 vars.pm:7 sub <- BEGIN 70*c29d5175Schristos0 305132 28 vars.pm:8 sub -> BEGIN 71*c29d5175Schristos0 305132 9 strict.pm:28 sub -> import 72*c29d5175Schristos0 305132 8 strict.pm:12 sub -> bits 73*c29d5175Schristos0 305132 13 strict.pm:12 sub <- bits 74*c29d5175Schristos0 305132 9 strict.pm:28 sub <- import 75*c29d5175Schristos0 305132 8 vars.pm:8 sub <- BEGIN 76*c29d5175Schristos0 305132 294 vars.pm:11 sub -> import 77*c29d5175Schristos0 305132 52 vars.pm:11 sub <- import 78*c29d5175Schristos0 305132 8 DynaLoader.pm:18 sub <- BEGIN 79*c29d5175Schristos0 305132 48 DynaLoader.pm:25 sub -> BEGIN 80*c29d5175Schristos0 305132 97 Config.pm:5 sub -> BEGIN 81*c29d5175Schristos0 305132 9 strict.pm:28 sub -> import 82*c29d5175Schristos0 305132 9 strict.pm:28 sub <- import 83*c29d5175Schristos0 305132 8 Config.pm:5 sub <- BEGIN 84*c29d5175Schristos0 305132 134 Config.pm:31 sub -> BEGIN 85*c29d5175Schristos0 305132 9 strict.pm:33 sub -> unimport 86*c29d5175Schristos0 305132 8 strict.pm:12 sub -> bits 87*c29d5175Schristos0 305132 11 strict.pm:12 sub <- bits 88*c29d5175Schristos0 305132 16 strict.pm:33 sub <- unimport 89*c29d5175Schristos0 305132 8 Config.pm:31 sub <- BEGIN 90*c29d5175Schristos0 305132 343 Config.pm:60 sub -> TIEHASH 91*c29d5175Schristos0 305132 10 Config.pm:60 sub <- TIEHASH 92*c29d5175Schristos0 305132 44 Config.pm:25 sub -> import 93*c29d5175Schristos0 305132 18 Config.pm:25 sub <- import 94*c29d5175Schristos0 305132 9 DynaLoader.pm:25 sub <- BEGIN 95*c29d5175Schristos0 305132 1301 AutoLoader.pm:3 sub -> BEGIN 96*c29d5175Schristos0 305132 11 strict.pm:28 sub -> import 97*c29d5175Schristos0 305132 10 strict.pm:28 sub <- import 98*c29d5175Schristos0 305132 9 AutoLoader.pm:3 sub <- BEGIN 99*c29d5175Schristos0 305132 22 AutoLoader.pm:4 sub -> BEGIN 100*c29d5175Schristos0 305132 9 AutoLoader.pm:4 sub <- BEGIN 101*c29d5175Schristos0 305132 89 AutoLoader.pm:14 sub -> BEGIN 102*c29d5175Schristos0 305132 13 AutoLoader.pm:14 sub <- BEGIN 103*c29d5175Schristos0 305132 375 AutoLoader.pm:95 sub -> BEGIN 104*c29d5175Schristos0 305132 9 strict.pm:33 sub -> unimport 105*c29d5175Schristos0 305132 8 strict.pm:12 sub -> bits 106*c29d5175Schristos0 305132 11 strict.pm:12 sub <- bits 107*c29d5175Schristos0 305132 9 strict.pm:33 sub <- unimport 108*c29d5175Schristos0 305132 8 AutoLoader.pm:95 sub <- BEGIN 109*c29d5175Schristos0 305132 203 AutoLoader.pm:128 sub -> BEGIN 110*c29d5175Schristos0 305132 9 strict.pm:33 sub -> unimport 111*c29d5175Schristos0 305132 8 strict.pm:12 sub -> bits 112*c29d5175Schristos0 305132 11 strict.pm:12 sub <- bits 113*c29d5175Schristos0 305132 9 strict.pm:33 sub <- unimport 114*c29d5175Schristos0 305132 8 AutoLoader.pm:128 sub <- BEGIN 115*c29d5175Schristos0 305132 220 AutoLoader.pm:173 sub -> BEGIN 116*c29d5175Schristos0 305132 9 strict.pm:33 sub -> unimport 117*c29d5175Schristos0 305132 8 strict.pm:12 sub -> bits 118*c29d5175Schristos0 305132 10 strict.pm:12 sub <- bits 119*c29d5175Schristos0 305132 9 strict.pm:33 sub <- unimport 120*c29d5175Schristos0 305132 8 AutoLoader.pm:173 sub <- BEGIN 121*c29d5175Schristos0 305132 103 Config.pm:52 sub -> FETCH 122*c29d5175Schristos0 305132 12 Config.pm:52 sub <- FETCH 123*c29d5175Schristos0 305132 16 Config.pm:52 sub -> FETCH 124*c29d5175Schristos0 305132 9 Config.pm:52 sub <- FETCH 125*c29d5175Schristos0 305132 11 Config.pm:52 sub -> FETCH 126*c29d5175Schristos0 305132 9 Config.pm:52 sub <- FETCH 127*c29d5175Schristos0 305132 11 Config.pm:52 sub -> FETCH 128*c29d5175Schristos0 305132 9 Config.pm:52 sub <- FETCH 129*c29d5175Schristos0 305132 95 Kstat.pm:35 sub <- BEGIN 130*c29d5175Schristos0 305132 29 Kstat.pm:36 sub -> BEGIN 131*c29d5175Schristos0 305132 10 vars.pm:11 sub -> import 132*c29d5175Schristos0 305132 33 vars.pm:11 sub <- import 133*c29d5175Schristos0 305132 8 Kstat.pm:36 sub <- BEGIN 134*c29d5175Schristos0 305132 56 DynaLoader.pm:133 sub -> bootstrap 135*c29d5175Schristos0 305132 314 DynaLoader.pm:48 sub -> dl_load_flags 136*c29d5175Schristos0 305132 11 DynaLoader.pm:48 sub <- dl_load_flags 137*c29d5175Schristos0 305132 1113 DynaLoader.pm:133 sub <- bootstrap 138*c29d5175Schristos0 305132 41 nicstat:85 sub <- BEGIN 139*c29d5175Schristos0 305132 6102 Std.pm:219 sub -> getopts 140*c29d5175Schristos0 305132 52 Exporter.pm:30 sub -> import 141*c29d5175Schristos0 305132 40 Exporter.pm:30 sub <- import 142*c29d5175Schristos0 305132 22 Std.pm:219 sub <- getopts 143*c29d5175Schristos0 305132 24 nicstat:264 sub -> find_nets 144*c29d5175Schristos0 305132 79662 nicstat:264 sub <- find_nets 145*c29d5175Schristos0 305132 420 nicstat:304 sub -> fetch_net_data 146*c29d5175Schristos0 305132 43871 nicstat:304 sub <- fetch_net_data 147*c29d5175Schristos0 305132 479 nicstat:372 sub -> print_neat 148*c29d5175Schristos0 305132 150 nicstat:372 sub <- print_neat 149*c29d5175Schristos0 305132 10 nicstat:372 sub -> print_neat 150*c29d5175Schristos0 305132 220 nicstat:372 sub <- print_neat 151*c29d5175Schristos0 305132 10 nicstat:372 sub -> print_neat 152*c29d5175Schristos0 305132 126 nicstat:372 sub <- print_neat 153*c29d5175Schristos0 305132 10 nicstat:372 sub -> print_neat 154*c29d5175Schristos0 305132 125 nicstat:372 sub <- print_neat 155*c29d5175Schristos0 305132 10 nicstat:372 sub -> print_neat 156*c29d5175Schristos0 305132 157 nicstat:372 sub <- print_neat 157*c29d5175Schristos0 305132 10 nicstat:372 sub -> print_neat 158*c29d5175Schristos0 305132 171 nicstat:372 sub <- print_neat 159*c29d5175Schristos0 305132 343 nicstat:372 sub -> print_neat 160*c29d5175Schristos0 305132 128 nicstat:372 sub <- print_neat 161*c29d5175Schristos0 305132 10 nicstat:372 sub -> print_neat 162*c29d5175Schristos0 305132 157 nicstat:372 sub <- print_neat 163*c29d5175Schristos0 305132 9 nicstat:372 sub -> print_neat 164*c29d5175Schristos0 305132 125 nicstat:372 sub <- print_neat 165*c29d5175Schristos0 305132 9 nicstat:372 sub -> print_neat 166*c29d5175Schristos0 305132 123 nicstat:372 sub <- print_neat 167*c29d5175Schristos0 305132 9 nicstat:372 sub -> print_neat 168*c29d5175Schristos0 305132 160 nicstat:372 sub <- print_neat 169*c29d5175Schristos0 305132 10 nicstat:372 sub -> print_neat 170*c29d5175Schristos0 305132 124 nicstat:372 sub <- print_neat 171*c29d5175Schristos0 305132 342 nicstat:372 sub -> print_neat 172*c29d5175Schristos0 305132 126 nicstat:372 sub <- print_neat 173*c29d5175Schristos0 305132 10 nicstat:372 sub -> print_neat 174*c29d5175Schristos0 305132 123 nicstat:372 sub <- print_neat 175*c29d5175Schristos0 305132 10 nicstat:372 sub -> print_neat 176*c29d5175Schristos0 305132 156 nicstat:372 sub <- print_neat 177*c29d5175Schristos0 305132 10 nicstat:372 sub -> print_neat 178*c29d5175Schristos0 305132 153 nicstat:372 sub <- print_neat 179*c29d5175Schristos0 305132 10 nicstat:372 sub -> print_neat 180*c29d5175Schristos0 305132 123 nicstat:372 sub <- print_neat 181*c29d5175Schristos0 305132 9 nicstat:372 sub -> print_neat 182*c29d5175Schristos0 305132 123 nicstat:372 sub <- print_neat 183*c29d5175Schristos0 305132 3736 Config.pm:63 sub -> DESTROY 184*c29d5175Schristos0 305132 32 Config.pm:63 sub <- DESTROY 185*c29d5175Schristos 186*c29d5175SchristosAfter initialising Perl libraries and modules, the "nicstat" program ran, 187*c29d5175Schristosthe output matching what was expected from the source. 188*c29d5175Schristos 189