1 The following are examples of pl_flowtime.d. 2 3 This is a simple script to trace the flow of Perl subroutines (functions). 4 Here it traces the example program, Code/Perl/func_abc.pl. 5 6 # pl_flowtime.d 7 C TIME(us) FILE DELTA(us) -- SUB 8 0 4201460363351 func_abc.pl 2 -> func_a 9 0 4201461370041 func_abc.pl 1006689 -> func_b 10 0 4201462380038 func_abc.pl 1009997 -> func_c 11 0 4201463390094 func_abc.pl 1010055 <- func_c 12 0 4201463390117 func_abc.pl 23 <- func_b 13 0 4201463390126 func_abc.pl 8 <- func_a 14 ^C 15 16 As each subroutine is entered, the third column is indented by 2 spaces. This 17 shows which subroutine is calling who - the output above begins by showing that 18 func_a() began, and then called func_b(). 19 20 The DELTA(us) column shows time from that line to the previous line, and 21 so can be a bit tricky to read. For example, the second line of data output 22 (skipping the header) reads as "the time from func_a() beginning to 23 func_b() beginning was 1006689 us, or 1.01 seconds". 24 25 If the output looks shuffled, check the CPU "C" and "TIME" columns, and 26 post sort based on TIME if necessary. 27 28 See Notes/ALLflow_notes.txt for important notes about reading flow outputs. 29 30 31 32 The following traces a Perl network interface statistics tool, "nicstat" 33 version 0.99, 34 35 # pl_flowtime.d 36 C TIME(us) FILE DELTA(us) -- SUB 37 0 4201691465151 nicstat 2 -> BEGIN 38 0 4201691465593 strict.pm 441 -> bits 39 0 4201691465625 strict.pm 32 <- bits 40 0 4201691465655 strict.pm 29 -> import 41 0 4201691465676 strict.pm 21 <- import 42 0 4201691465684 nicstat 7 <- BEGIN 43 0 4201691465710 nicstat 25 -> BEGIN 44 0 4201691468038 Exporter.pm 2328 -> import 45 0 4201691468121 Exporter.pm 82 <- import 46 0 4201691468133 nicstat 12 <- BEGIN 47 0 4201691468160 nicstat 26 -> BEGIN 48 0 4201691468367 Kstat.pm 207 -> BEGIN 49 0 4201691468378 strict.pm 10 -> import 50 0 4201691468388 strict.pm 10 <- import 51 0 4201691468396 Kstat.pm 8 <- BEGIN 52 0 4201691468419 Kstat.pm 23 -> BEGIN 53 0 4201691468612 DynaLoader.pm 192 -> BEGIN 54 0 4201691468685 vars.pm 73 -> BEGIN 55 0 4201691468694 vars.pm 8 <- BEGIN 56 0 4201691468727 vars.pm 33 -> BEGIN 57 0 4201691469199 warnings.pm 471 -> BEGIN 58 0 4201691469863 warnings.pm 663 <- BEGIN 59 0 4201691471965 register.pm 2102 -> import 60 0 4201691471986 register.pm 21 -> mkMask 61 0 4201691472000 register.pm 13 <- mkMask 62 0 4201691472052 register.pm 52 -> mkMask 63 0 4201691472063 register.pm 10 <- mkMask 64 0 4201691472074 register.pm 10 <- import 65 0 4201691472081 vars.pm 7 <- BEGIN 66 0 4201691472109 vars.pm 28 -> BEGIN 67 0 4201691472118 strict.pm 8 -> import 68 0 4201691472126 strict.pm 8 -> bits 69 0 4201691472139 strict.pm 12 <- bits 70 0 4201691472148 strict.pm 9 <- import 71 0 4201691472155 vars.pm 7 <- BEGIN 72 0 4201691472450 vars.pm 294 -> import 73 0 4201691472501 vars.pm 51 <- import 74 0 4201691472509 DynaLoader.pm 7 <- BEGIN 75 0 4201691472557 DynaLoader.pm 48 -> BEGIN 76 0 4201691472650 Config.pm 92 -> BEGIN 77 0 4201691472658 strict.pm 8 -> import 78 0 4201691472667 strict.pm 8 <- import 79 0 4201691472675 Config.pm 7 <- BEGIN 80 0 4201691472809 Config.pm 133 -> BEGIN 81 0 4201691472817 strict.pm 8 -> unimport 82 0 4201691472825 strict.pm 8 -> bits 83 0 4201691472852 strict.pm 26 <- bits 84 0 4201691472868 strict.pm 16 <- unimport 85 0 4201691472876 Config.pm 7 <- BEGIN 86 0 4201691473222 Config.pm 345 -> TIEHASH 87 0 4201691473231 Config.pm 9 <- TIEHASH 88 0 4201691473275 Config.pm 43 -> import 89 0 4201691473292 Config.pm 17 <- import 90 0 4201691473301 DynaLoader.pm 8 <- BEGIN 91 0 4201691474650 AutoLoader.pm 1349 -> BEGIN 92 0 4201691474661 strict.pm 10 -> import 93 0 4201691474670 strict.pm 9 <- import 94 0 4201691474679 AutoLoader.pm 8 <- BEGIN 95 0 4201691474701 AutoLoader.pm 21 -> BEGIN 96 0 4201691474709 AutoLoader.pm 8 <- BEGIN 97 0 4201691474797 AutoLoader.pm 88 -> BEGIN 98 0 4201691474810 AutoLoader.pm 12 <- BEGIN 99 0 4201691475186 AutoLoader.pm 376 -> BEGIN 100 0 4201691475195 strict.pm 9 -> unimport 101 0 4201691475203 strict.pm 7 -> bits 102 0 4201691475214 strict.pm 10 <- bits 103 0 4201691475223 strict.pm 8 <- unimport 104 0 4201691475230 AutoLoader.pm 7 <- BEGIN 105 0 4201691475435 AutoLoader.pm 204 -> BEGIN 106 0 4201691475444 strict.pm 8 -> unimport 107 0 4201691475451 strict.pm 7 -> bits 108 0 4201691475462 strict.pm 10 <- bits 109 0 4201691475470 strict.pm 8 <- unimport 110 0 4201691475478 AutoLoader.pm 7 <- BEGIN 111 0 4201691475697 AutoLoader.pm 219 -> BEGIN 112 0 4201691475706 strict.pm 8 -> unimport 113 0 4201691475714 strict.pm 7 -> bits 114 0 4201691475724 strict.pm 10 <- bits 115 0 4201691475732 strict.pm 8 <- unimport 116 0 4201691475739 AutoLoader.pm 7 <- BEGIN 117 0 4201691475842 Config.pm 102 -> FETCH 118 0 4201691475854 Config.pm 11 <- FETCH 119 0 4201691475870 Config.pm 15 -> FETCH 120 0 4201691475879 Config.pm 9 <- FETCH 121 0 4201691475890 Config.pm 10 -> FETCH 122 0 4201691475898 Config.pm 8 <- FETCH 123 0 4201691475909 Config.pm 10 -> FETCH 124 0 4201691475917 Config.pm 8 <- FETCH 125 0 4201691476012 Kstat.pm 94 <- BEGIN 126 0 4201691476041 Kstat.pm 29 -> BEGIN 127 0 4201691476051 vars.pm 9 -> import 128 0 4201691476084 vars.pm 32 <- import 129 0 4201691476091 Kstat.pm 7 <- BEGIN 130 0 4201691476147 DynaLoader.pm 56 -> bootstrap 131 0 4201691476373 DynaLoader.pm 225 -> dl_load_flags 132 0 4201691476383 DynaLoader.pm 9 <- dl_load_flags 133 0 4201691476813 DynaLoader.pm 430 <- bootstrap 134 0 4201691476837 nicstat 23 <- BEGIN 135 0 4201691483648 Std.pm 6811 -> getopts 136 0 4201691483697 Exporter.pm 49 -> import 137 0 4201691483737 Exporter.pm 39 <- import 138 0 4201691483756 Std.pm 19 <- getopts 139 0 4201691483780 nicstat 24 -> find_nets 140 0 4201691539198 nicstat 55418 <- find_nets 141 0 4201691539610 nicstat 411 -> fetch_net_data 142 0 4201691583290 nicstat 43679 <- fetch_net_data 143 0 4201691583781 nicstat 491 -> print_neat 144 0 4201691583930 nicstat 149 <- print_neat 145 0 4201691583996 nicstat 65 -> print_neat 146 0 4201691584165 nicstat 169 <- print_neat 147 0 4201691584174 nicstat 9 -> print_neat 148 0 4201691584298 nicstat 124 <- print_neat 149 0 4201691584308 nicstat 9 -> print_neat 150 0 4201691584432 nicstat 124 <- print_neat 151 0 4201691584473 nicstat 41 -> print_neat 152 0 4201691584597 nicstat 123 <- print_neat 153 0 4201691584607 nicstat 9 -> print_neat 154 0 4201691584730 nicstat 123 <- print_neat 155 0 4201691585091 nicstat 361 -> print_neat 156 0 4201691585217 nicstat 125 <- print_neat 157 0 4201691585226 nicstat 9 -> print_neat 158 0 4201691585379 nicstat 152 <- print_neat 159 0 4201691585389 nicstat 9 -> print_neat 160 0 4201691585512 nicstat 123 <- print_neat 161 0 4201691585521 nicstat 9 -> print_neat 162 0 4201691585644 nicstat 123 <- print_neat 163 0 4201691585653 nicstat 9 -> print_neat 164 0 4201691585825 nicstat 171 <- print_neat 165 0 4201691585834 nicstat 9 -> print_neat 166 0 4201691585988 nicstat 154 <- print_neat 167 0 4201691586274 nicstat 285 -> print_neat 168 0 4201691586434 nicstat 160 <- print_neat 169 0 4201691586443 nicstat 9 -> print_neat 170 0 4201691586567 nicstat 123 <- print_neat 171 0 4201691586576 nicstat 9 -> print_neat 172 0 4201691586731 nicstat 154 <- print_neat 173 0 4201691586740 nicstat 8 -> print_neat 174 0 4201691586892 nicstat 151 <- print_neat 175 0 4201691586901 nicstat 9 -> print_neat 176 0 4201691587025 nicstat 123 <- print_neat 177 0 4201691587034 nicstat 9 -> print_neat 178 0 4201691587157 nicstat 123 <- print_neat 179 0 4201691590909 Config.pm 3751 -> DESTROY 180 0 4201691590938 Config.pm 29 <- DESTROY 181 182 After initialising Perl libraries and modules, the "nicstat" program ran, 183 the output matching what was expected from the source. 184 185 The DELTA column shows that most time is spent in the find_nets() and 186 fetch_nets_data() subroutines, with 55.4 ms and 44.7 ms of elapsed 187 function time respectively. Those particular times were easy to interpret, 188 since there were no child subroutines called, and the delta spanned 189 the subroutine entry to its return. 190 191 Some times get trickier to comprehend. The 2nd last line with a DELTA time 192 of 3751 us, means "the time from the print_neat() subroutine completing 193 to the DESTROY() subroutine starting, took 3751 us.". What is happening 194 during this time? It is hard to say based on this output - since it isn't 195 time within a function, rather it is time that Perl spent processing the 196 main program. Since we have the last function called, we may guess where 197 the program was at; or we could enhance this script to trace Perl engine 198 internals as well (and/or syscalls). 199 200
Indexes created Mon Apr 20 00:23:12 UTC 2026