On Mon, Jan 17, 2011 at 20:36, Bakul Shah <[email protected]> wrote:
> On Mon, 17 Jan 2011 11:56:22 EST erik quanstrom <[email protected]>
> wrote:
>> > strace tells you what system calls were made and when. To
>> > find out which functions use most time, compile with -pg and
>> > look at the gprof output once done. That 14 seconds were
>> > probably spent computing dependencies. You can convert your
>> > test.mk to a Makefile with a trivial sed script. See what
>> > bsdmake or gmake does with it time wise. {bsd,g}make have
>> > been been abused with huge Makefiles for far longer and are
>> > likely to be friendlier to them :-)
>>
>> why not just use prof, which is exactly the tool for the job?
>
> Ciprian specified plan9ports. Recipe for building a profiling
> mk on unix:
>
> cd $PLAN9/src/cmd/mk
> 9 mk clean
> CC9="gcc -pg" 9 mk all
>
> Then:
>
> mk=$PLAN9/src/cmd/mk/o.mk
> cd <source dir>
> 9 mk clean
> 9 $mk
> gproff $mk > mk.gprof
>
> This will show where time is being spent.
Actually I'm using the `mk` from
`http://swtch.com/plan9port/unix/mk-with-libs.tgz` which I'm assuming
is an extract of the `plan9port` sources. As such in order to build it
I had to resort to updating the Makefile, but I didit.
Attached is the output of running `gprof` as specified.
Thanks,
Ciprian.
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
28.11 2.24 2.24 1 2.24 2.24 clrmade
22.96 4.07 1.83 1 1.83 1.83 attribute
22.33 5.85 1.78 1 1.78 1.78 ambiguous.clone.2
20.45 7.48 1.63 1 1.63 1.63 cyclechk
2.63 7.69 0.21 __i686.get_pc_thunk.bx
1.38 7.80 0.11 1 0.11 0.11 nrep
0.50 7.84 0.04 3410974 0.00 0.00 runetochar
0.38 7.87 0.03 1040939 0.00 0.00 Bgetrune
0.25 7.89 0.02 1705487 0.00 0.00 rinsert
0.25 7.91 0.02 1456598 0.00 0.00 chartorune
0.13 7.92 0.01 1705487 0.00 0.00 runelen
0.13 7.93 0.01 1040939 0.00 0.00 Bgetc
0.13 7.94 0.01 778876 0.00 0.00 utfrune
0.13 7.95 0.01 13253 0.00 0.00 symlook
0.13 7.96 0.01 6658 0.00 0.00 stow
0.13 7.97 0.01 3319 0.00 0.00 assline
0.00 7.97 0.00 687899 0.00 0.00 nextrune
0.00 7.97 0.00 16964 0.00 0.00 Malloc
0.00 7.97 0.00 12623 0.00 0.00 insert
0.00 7.97 0.00 9281 0.00 0.00 freebuf
0.00 7.97 0.00 9281 0.00 0.00 newbuf
0.00 7.97 0.00 6708 0.00 0.00 newword
0.00 7.97 0.00 6637 0.00 0.00 shcharin
0.00 7.97 0.00 3315 0.00 0.00 mkassert
0.00 7.97 0.00 3313 0.00 0.00 addrule
0.00 7.97 0.00 3313 0.00 0.00 addrules
0.00 7.97 0.00 3312 0.00 0.00 Bungetrune
0.00 7.97 0.00 3312 0.00 0.00 newarc
0.00 7.97 0.00 3312 0.00 0.00 rcopy
0.00 7.97 0.00 2721 0.00 0.00 outofdate
0.00 7.97 0.00 923 0.00 0.00 mkmtime
0.00 7.97 0.00 923 0.00 0.00 mtime
0.00 7.97 0.00 923 0.00 0.00 timeof
0.00 7.97 0.00 75 0.00 0.00 envinsert
0.00 7.97 0.00 56 0.00 0.00 ecopy
0.00 7.97 0.00 56 0.00 0.00 setvar
0.00 7.97 0.00 8 0.00 0.00 Realloc
0.00 7.97 0.00 2 0.00 0.00 Binit
0.00 7.97 0.00 2 0.00 0.00 Binits
0.00 7.97 0.00 2 0.00 0.00 bufcpy
0.00 7.97 0.00 2 0.00 0.00 initshell
0.00 7.97 0.00 2 0.00 0.00 usage
0.00 7.97 0.00 1 0.00 0.00 Bflush
0.00 7.97 0.00 1 0.00 0.00 Bprint
0.00 7.97 0.00 1 0.00 0.00 Bvprint
0.00 7.97 0.00 1 0.00 0.00 __fmtcpy
0.00 7.97 0.00 1 0.00 0.00 __fmtdispatch
0.00 7.97 0.00 1 0.00 0.00 __fmtinstall
0.00 7.97 0.00 1 0.00 0.00 __fmtlock
0.00 7.97 0.00 1 0.00 0.00 __fmtpad
0.00 7.97 0.00 1 0.00 0.00 __fmtunlock
0.00 7.97 0.00 1 0.00 0.00 __strfmt
0.00 7.97 0.00 1 0.00 0.00 applyrules
0.00 7.97 0.00 1 0.00 0.00 catchnotes
0.00 7.97 0.00 1 0.00 0.00 dofmt
0.00 7.97 0.00 1 0.00 0.00 dorecipe
0.00 7.97 0.00 1 0.00 0.00 execinit
0.00 7.97 0.00 1 0.00 0.00 fmtlocaleinit
0.00 7.97 0.00 1 0.00 0.00 fmtstrcpy
0.00 7.97 0.00 1 0.00 0.00 fmtvprint
0.00 7.97 0.00 1 0.00 5.24 graph
0.00 7.97 0.00 1 0.00 0.00 initenv
0.00 7.97 0.00 1 0.00 0.00 ipop
0.00 7.97 0.00 1 0.00 0.00 ipush
0.00 7.97 0.00 1 0.00 7.59 mk
0.00 7.97 0.00 1 0.00 0.00 mkwaitfor
0.00 7.97 0.00 1 0.00 0.00 nproc
0.00 7.97 0.00 1 0.00 0.16 parse
0.00 7.97 0.00 1 0.00 0.00 popshell
0.00 7.97 0.00 1 0.00 0.00 pushshell
0.00 7.97 0.00 1 0.00 0.00 readenv
0.00 7.97 0.00 1 0.00 0.00 rulecnt
0.00 7.97 0.00 1 0.00 0.00 syminit
0.00 7.97 0.00 1 0.00 0.00 symtraverse
0.00 7.97 0.00 1 0.00 0.00 update
0.00 7.97 0.00 1 0.00 0.00 utflen
0.00 7.97 0.00 1 0.00 0.00 vacuous.clone.1
0.00 7.97 0.00 1 0.00 0.00 waitup
0.00 7.97 0.00 1 0.00 0.00 wdup
0.00 7.97 0.00 1 0.00 0.00 work
% the percentage of the total running time of the
time program used by this function.
cumulative a running sum of the number of seconds accounted
seconds for by this function and those listed above it.
self the number of seconds accounted for by this
seconds function alone. This is the major sort for this
listing.
calls the number of times this function was invoked, if
this function is profiled, else blank.
self the average number of milliseconds spent in this
ms/call function per call, if this function is profiled,
else blank.
total the average number of milliseconds spent in this
ms/call function and its descendents per call, if this
function is profiled, else blank.
name the name of the function. This is the minor sort
for this listing. The index shows the location of
the function in the gprof listing. If the index is
in parenthesis it shows where it would appear in
the gprof listing if it were to be printed.
Call graph (explanation follows)
granularity: each sample hit covers 4 byte(s) for 0.13% of 7.97 seconds
index % time self children called name
<spontaneous>
[1] 97.4 0.00 7.76 main [1]
0.00 7.59 1/1 mk [2]
0.00 0.16 1/1 parse [9]
0.00 0.00 1/1 execinit [27]
0.00 0.00 1/1 initenv [28]
0.00 0.00 2/6658 stow [13]
0.00 0.00 1/2 initshell [33]
0.00 0.00 2/13253 symlook [24]
0.00 0.00 4/12623 insert [43]
0.00 0.00 2/2 bufcpy [58]
0.00 0.00 2/2 usage [59]
0.00 0.00 1/9281 newbuf [45]
0.00 0.00 1/2 Binit [56]
0.00 0.00 1/1 syminit [69]
0.00 0.00 1/9281 freebuf [44]
0.00 0.00 1/1 catchnotes [61]
-----------------------------------------------
0.00 7.59 1/1 main [1]
[2] 95.3 0.00 7.59 1 mk [2]
0.00 5.24 1/1 graph [3]
2.24 0.00 1/1 clrmade [4]
0.11 0.00 1/1 nrep [10]
0.00 0.00 1/1 nproc [36]
0.00 0.00 1/1 Bprint [37]
0.00 0.00 1/1 work [75]
0.00 0.00 1/1 waitup [73]
0.00 0.00 1/3315 mkassert [47]
-----------------------------------------------
0.00 5.24 1/1 mk [2]
[3] 65.8 0.00 5.24 1 graph [3]
1.83 0.00 1/1 attribute [5]
1.78 0.00 1/1 ambiguous.clone.2 [6]
1.63 0.00 1/1 cyclechk [7]
0.00 0.00 1/1 applyrules [25]
0.00 0.00 1/1 rulecnt [68]
0.00 0.00 1/1 vacuous.clone.1 [72]
-----------------------------------------------
59824243 clrmade [4]
2.24 0.00 1/1 mk [2]
[4] 28.1 2.24 0.00 1+59824243 clrmade [4]
59824243 clrmade [4]
-----------------------------------------------
59824243 attribute [5]
1.83 0.00 1/1 graph [3]
[5] 23.0 1.83 0.00 1+59824243 attribute [5]
59824243 attribute [5]
-----------------------------------------------
59824243 ambiguous.clone.2 [6]
1.78 0.00 1/1 graph [3]
[6] 22.3 1.78 0.00 1+59824243 ambiguous.clone.2 [6]
59824243 ambiguous.clone.2 [6]
-----------------------------------------------
59824243 cyclechk [7]
1.63 0.00 1/1 graph [3]
[7] 20.5 1.63 0.00 1+59824243 cyclechk [7]
59824243 cyclechk [7]
-----------------------------------------------
<spontaneous>
[8] 2.6 0.21 0.00 __i686.get_pc_thunk.bx [8]
-----------------------------------------------
0.00 0.16 1/1 main [1]
[9] 2.1 0.00 0.16 1 parse [9]
0.01 0.05 3319/3319 assline [12]
0.01 0.04 6636/6658 stow [13]
0.00 0.02 3313/3313 addrules [20]
0.00 0.01 348972/1705487 rinsert [11]
0.01 0.00 353040/1040939 Bgetrune [15]
0.00 0.01 3323/6637 shcharin [18]
0.00 0.00 3395/1456598 chartorune [19]
0.00 0.00 1/1 pushshell [34]
0.00 0.00 10/13253 symlook [24]
0.00 0.00 5/56 setvar [30]
0.00 0.00 1/1 popshell [35]
0.00 0.00 3314/9281 newbuf [45]
0.00 0.00 3314/9281 freebuf [44]
0.00 0.00 3313/12623 insert [43]
0.00 0.00 3312/3312 Bungetrune [48]
0.00 0.00 1/1 ipush [66]
0.00 0.00 1/2 Binit [56]
0.00 0.00 1/1 ipop [65]
-----------------------------------------------
0.11 0.00 1/1 mk [2]
[10] 1.4 0.11 0.00 1 nrep [10]
0.00 0.00 1/13253 symlook [24]
-----------------------------------------------
0.00 0.01 348972/1705487 parse [9]
0.01 0.02 671935/1705487 stow [13]
0.01 0.02 684580/1705487 assline [12]
[11] 0.9 0.02 0.05 1705487 rinsert [11]
0.01 0.02 1705487/1705487 runelen [16]
0.02 0.00 1705487/3410974 runetochar [14]
-----------------------------------------------
0.01 0.05 3319/3319 parse [9]
[12] 0.8 0.01 0.05 3319 assline [12]
0.01 0.02 684580/1705487 rinsert [11]
0.00 0.03 687899/687899 nextrune [17]
0.00 0.00 3319/12623 insert [43]
-----------------------------------------------
0.00 0.00 2/6658 main [1]
0.00 0.00 2/6658 initshell [33]
0.00 0.00 18/6658 execinit [27]
0.01 0.04 6636/6658 parse [9]
[13] 0.6 0.01 0.04 6658 stow [13]
0.01 0.02 671935/1705487 rinsert [11]
0.01 0.00 675249/1456598 chartorune [19]
0.00 0.00 6659/6708 newword [46]
0.00 0.00 5966/9281 newbuf [45]
0.00 0.00 5966/12623 insert [43]
0.00 0.00 5966/9281 freebuf [44]
-----------------------------------------------
0.02 0.00 1705487/3410974 rinsert [11]
0.02 0.00 1705487/3410974 runelen [16]
[14] 0.5 0.04 0.00 3410974 runetochar [14]
-----------------------------------------------
0.01 0.00 353040/1040939 parse [9]
0.02 0.01 687899/1040939 nextrune [17]
[15] 0.5 0.03 0.01 1040939 Bgetrune [15]
0.01 0.00 1040939/1040939 Bgetc [22]
-----------------------------------------------
0.01 0.02 1705487/1705487 rinsert [11]
[16] 0.4 0.01 0.02 1705487 runelen [16]
0.02 0.00 1705487/3410974 runetochar [14]
-----------------------------------------------
0.00 0.03 687899/687899 assline [12]
[17] 0.3 0.00 0.03 687899 nextrune [17]
0.02 0.01 687899/1040939 Bgetrune [15]
-----------------------------------------------
0.00 0.00 1/6637 addrules [20]
0.00 0.01 3313/6637 addrule [21]
0.00 0.01 3323/6637 parse [9]
[18] 0.3 0.00 0.02 6637 shcharin [18]
0.01 0.00 777953/1456598 chartorune [19]
0.01 0.00 777953/778876 utfrune [23]
-----------------------------------------------
0.00 0.00 1/1456598 __fmtdispatch [41]
0.00 0.00 3395/1456598 parse [9]
0.01 0.00 675249/1456598 stow [13]
0.01 0.00 777953/1456598 shcharin [18]
[19] 0.3 0.02 0.00 1456598 chartorune [19]
-----------------------------------------------
0.00 0.02 3313/3313 parse [9]
[20] 0.2 0.00 0.02 3313 addrules [20]
0.00 0.02 3313/3313 addrule [21]
0.00 0.00 1/6637 shcharin [18]
0.00 0.00 3313/3315 mkassert [47]
0.00 0.00 1/1 wdup [74]
-----------------------------------------------
0.00 0.02 3313/3313 addrules [20]
[21] 0.2 0.00 0.02 3313 addrule [21]
0.00 0.01 3313/6637 shcharin [18]
0.00 0.00 6626/13253 symlook [24]
0.00 0.00 3313/16964 Malloc [42]
-----------------------------------------------
0.01 0.00 1040939/1040939 Bgetrune [15]
[22] 0.1 0.01 0.00 1040939 Bgetc [22]
-----------------------------------------------
0.00 0.00 923/778876 timeof [26]
0.01 0.00 777953/778876 shcharin [18]
[23] 0.1 0.01 0.00 778876 utfrune [23]
-----------------------------------------------
0.00 0.00 1/13253 nrep [10]
0.00 0.00 1/13253 nproc [36]
0.00 0.00 2/13253 main [1]
0.00 0.00 10/13253 parse [9]
0.00 0.00 18/13253 initenv [28]
0.00 0.00 56/13253 ecopy [31]
0.00 0.00 96/13253 readenv [29]
0.00 0.00 112/13253 setvar [30]
0.00 0.00 1845/13253 timeof [26]
0.00 0.00 4486/13253 applyrules [25]
0.00 0.00 6626/13253 addrule [21]
[24] 0.1 0.01 0.00 13253 symlook [24]
0.00 0.00 2700/16964 Malloc [42]
-----------------------------------------------
2639 applyrules [25]
0.00 0.00 1/1 graph [3]
[25] 0.1 0.00 0.00 1+2639 applyrules [25]
0.00 0.00 4486/13253 symlook [24]
0.00 0.00 923/923 timeof [26]
0.00 0.00 3312/3312 newarc [49]
0.00 0.00 923/16964 Malloc [42]
2639 applyrules [25]
-----------------------------------------------
0.00 0.00 923/923 applyrules [25]
[26] 0.0 0.00 0.00 923 timeof [26]
0.00 0.00 1845/13253 symlook [24]
0.00 0.00 923/778876 utfrune [23]
0.00 0.00 923/923 mtime [53]
-----------------------------------------------
0.00 0.00 1/1 main [1]
[27] 0.0 0.00 0.00 1 execinit [27]
0.00 0.00 18/6658 stow [13]
0.00 0.00 1/1 symtraverse [32]
0.00 0.00 19/75 envinsert [54]
-----------------------------------------------
0.00 0.00 1/1 main [1]
[28] 0.0 0.00 0.00 1 initenv [28]
0.00 0.00 1/1 readenv [29]
0.00 0.00 18/13253 symlook [24]
-----------------------------------------------
0.00 0.00 1/1 initenv [28]
[29] 0.0 0.00 0.00 1 readenv [29]
0.00 0.00 96/13253 symlook [24]
0.00 0.00 48/56 setvar [30]
0.00 0.00 48/6708 newword [46]
-----------------------------------------------
0.00 0.00 1/56 popshell [35]
0.00 0.00 2/56 initshell [33]
0.00 0.00 5/56 parse [9]
0.00 0.00 48/56 readenv [29]
[30] 0.0 0.00 0.00 56 setvar [30]
0.00 0.00 112/13253 symlook [24]
-----------------------------------------------
0.00 0.00 56/56 symtraverse [32]
[31] 0.0 0.00 0.00 56 ecopy [31]
0.00 0.00 56/13253 symlook [24]
0.00 0.00 56/75 envinsert [54]
-----------------------------------------------
0.00 0.00 1/1 execinit [27]
[32] 0.0 0.00 0.00 1 symtraverse [32]
0.00 0.00 56/56 ecopy [31]
-----------------------------------------------
0.00 0.00 1/2 main [1]
0.00 0.00 1/2 pushshell [34]
[33] 0.0 0.00 0.00 2 initshell [33]
0.00 0.00 2/6658 stow [13]
0.00 0.00 2/56 setvar [30]
-----------------------------------------------
0.00 0.00 1/1 parse [9]
[34] 0.0 0.00 0.00 1 pushshell [34]
0.00 0.00 1/2 initshell [33]
0.00 0.00 1/16964 Malloc [42]
-----------------------------------------------
0.00 0.00 1/1 parse [9]
[35] 0.0 0.00 0.00 1 popshell [35]
0.00 0.00 1/56 setvar [30]
-----------------------------------------------
0.00 0.00 1/1 mk [2]
[36] 0.0 0.00 0.00 1 nproc [36]
0.00 0.00 1/13253 symlook [24]
0.00 0.00 1/16964 Malloc [42]
-----------------------------------------------
0.00 0.00 1/1 mk [2]
[37] 0.0 0.00 0.00 1 Bprint [37]
0.00 0.00 1/1 Bvprint [38]
-----------------------------------------------
0.00 0.00 1/1 Bprint [37]
[38] 0.0 0.00 0.00 1 Bvprint [38]
0.00 0.00 1/1 fmtvprint [40]
0.00 0.00 1/1 fmtlocaleinit [63]
-----------------------------------------------
0.00 0.00 1/1 fmtvprint [40]
[39] 0.0 0.00 0.00 1 dofmt [39]
0.00 0.00 1/1 __fmtdispatch [41]
-----------------------------------------------
0.00 0.00 1/1 Bvprint [38]
[40] 0.0 0.00 0.00 1 fmtvprint [40]
0.00 0.00 1/1 dofmt [39]
-----------------------------------------------
0.00 0.00 1/1 dofmt [39]
[41] 0.0 0.00 0.00 1 __fmtdispatch [41]
0.00 0.00 1/1456598 chartorune [19]
0.00 0.00 1/1 __fmtlock [189]
0.00 0.00 1/1 __strfmt [192]
0.00 0.00 1/1 __fmtinstall [188]
0.00 0.00 1/1 __fmtunlock [191]
-----------------------------------------------
0.00 0.00 1/16964 ipush [66]
0.00 0.00 1/16964 rulecnt [68]
0.00 0.00 1/16964 nproc [36]
0.00 0.00 1/16964 pushshell [34]
0.00 0.00 4/16964 newbuf [45]
0.00 0.00 923/16964 applyrules [25]
0.00 0.00 2700/16964 symlook [24]
0.00 0.00 3312/16964 newarc [49]
0.00 0.00 3313/16964 addrule [21]
0.00 0.00 6708/16964 newword [46]
[42] 0.0 0.00 0.00 16964 Malloc [42]
-----------------------------------------------
0.00 0.00 4/12623 main [1]
0.00 0.00 21/12623 bufcpy [58]
0.00 0.00 3313/12623 parse [9]
0.00 0.00 3319/12623 assline [12]
0.00 0.00 5966/12623 stow [13]
[43] 0.0 0.00 0.00 12623 insert [43]
-----------------------------------------------
0.00 0.00 1/9281 main [1]
0.00 0.00 3314/9281 parse [9]
0.00 0.00 5966/9281 stow [13]
[44] 0.0 0.00 0.00 9281 freebuf [44]
-----------------------------------------------
0.00 0.00 1/9281 main [1]
0.00 0.00 3314/9281 parse [9]
0.00 0.00 5966/9281 stow [13]
[45] 0.0 0.00 0.00 9281 newbuf [45]
0.00 0.00 4/16964 Malloc [42]
-----------------------------------------------
0.00 0.00 1/6708 wdup [74]
0.00 0.00 48/6708 readenv [29]
0.00 0.00 6659/6708 stow [13]
[46] 0.0 0.00 0.00 6708 newword [46]
0.00 0.00 6708/16964 Malloc [42]
-----------------------------------------------
0.00 0.00 1/3315 mk [2]
0.00 0.00 1/3315 ipop [65]
0.00 0.00 3313/3315 addrules [20]
[47] 0.0 0.00 0.00 3315 mkassert [47]
-----------------------------------------------
0.00 0.00 3312/3312 parse [9]
[48] 0.0 0.00 0.00 3312 Bungetrune [48]
-----------------------------------------------
0.00 0.00 3312/3312 applyrules [25]
[49] 0.0 0.00 0.00 3312 newarc [49]
0.00 0.00 3312/16964 Malloc [42]
0.00 0.00 3312/3312 rcopy [50]
-----------------------------------------------
0.00 0.00 3312/3312 newarc [49]
[50] 0.0 0.00 0.00 3312 rcopy [50]
-----------------------------------------------
0.00 0.00 82/2721 update [70]
0.00 0.00 2639/2721 work [75]
[51] 0.0 0.00 0.00 2721 outofdate [51]
-----------------------------------------------
0.00 0.00 923/923 mtime [53]
[52] 0.0 0.00 0.00 923 mkmtime [52]
-----------------------------------------------
0.00 0.00 923/923 timeof [26]
[53] 0.0 0.00 0.00 923 mtime [53]
0.00 0.00 923/923 mkmtime [52]
-----------------------------------------------
0.00 0.00 19/75 execinit [27]
0.00 0.00 56/75 ecopy [31]
[54] 0.0 0.00 0.00 75 envinsert [54]
0.00 0.00 8/8 Realloc [55]
-----------------------------------------------
0.00 0.00 8/8 envinsert [54]
[55] 0.0 0.00 0.00 8 Realloc [55]
-----------------------------------------------
0.00 0.00 1/2 main [1]
0.00 0.00 1/2 parse [9]
[56] 0.0 0.00 0.00 2 Binit [56]
0.00 0.00 2/2 Binits [57]
-----------------------------------------------
0.00 0.00 2/2 Binit [56]
[57] 0.0 0.00 0.00 2 Binits [57]
-----------------------------------------------
0.00 0.00 2/2 main [1]
[58] 0.0 0.00 0.00 2 bufcpy [58]
0.00 0.00 21/12623 insert [43]
-----------------------------------------------
0.00 0.00 2/2 main [1]
[59] 0.0 0.00 0.00 2 usage [59]
-----------------------------------------------
0.00 0.00 1/1 batexit [89]
[60] 0.0 0.00 0.00 1 Bflush [60]
-----------------------------------------------
0.00 0.00 1/1 main [1]
[61] 0.0 0.00 0.00 1 catchnotes [61]
-----------------------------------------------
0.00 0.00 1/1 work [75]
[62] 0.0 0.00 0.00 1 dorecipe [62]
0.00 0.00 1/1 update [70]
-----------------------------------------------
0.00 0.00 1/1 Bvprint [38]
[63] 0.0 0.00 0.00 1 fmtlocaleinit [63]
-----------------------------------------------
0.00 0.00 1/1 __strfmt [192]
[64] 0.0 0.00 0.00 1 fmtstrcpy [64]
0.00 0.00 1/1 __fmtcpy [187]
0.00 0.00 1/1 utflen [71]
-----------------------------------------------
0.00 0.00 1/1 parse [9]
[65] 0.0 0.00 0.00 1 ipop [65]
0.00 0.00 1/3315 mkassert [47]
-----------------------------------------------
0.00 0.00 1/1 parse [9]
[66] 0.0 0.00 0.00 1 ipush [66]
0.00 0.00 1/16964 Malloc [42]
-----------------------------------------------
0.00 0.00 1/1 waitup [73]
[67] 0.0 0.00 0.00 1 mkwaitfor [67]
-----------------------------------------------
0.00 0.00 1/1 graph [3]
[68] 0.0 0.00 0.00 1 rulecnt [68]
0.00 0.00 1/16964 Malloc [42]
-----------------------------------------------
0.00 0.00 1/1 main [1]
[69] 0.0 0.00 0.00 1 syminit [69]
-----------------------------------------------
0.00 0.00 1/1 dorecipe [62]
[70] 0.0 0.00 0.00 1 update [70]
0.00 0.00 82/2721 outofdate [51]
-----------------------------------------------
0.00 0.00 1/1 fmtstrcpy [64]
[71] 0.0 0.00 0.00 1 utflen [71]
-----------------------------------------------
2639 vacuous.clone.1 [72]
0.00 0.00 1/1 graph [3]
[72] 0.0 0.00 0.00 1+2639 vacuous.clone.1 [72]
2639 vacuous.clone.1 [72]
-----------------------------------------------
0.00 0.00 1/1 mk [2]
[73] 0.0 0.00 0.00 1 waitup [73]
0.00 0.00 1/1 mkwaitfor [67]
-----------------------------------------------
0.00 0.00 1/1 addrules [20]
[74] 0.0 0.00 0.00 1 wdup [74]
0.00 0.00 1/6708 newword [46]
-----------------------------------------------
2639 work [75]
0.00 0.00 1/1 mk [2]
[75] 0.0 0.00 0.00 1+2639 work [75]
0.00 0.00 2639/2721 outofdate [51]
0.00 0.00 1/1 dorecipe [62]
2639 work [75]
-----------------------------------------------
0.00 0.00 1/1 fmtstrcpy [64]
[187] 0.0 0.00 0.00 1 __fmtcpy [187]
0.00 0.00 1/1 __fmtpad [190]
-----------------------------------------------
0.00 0.00 1/1 __fmtdispatch [41]
[188] 0.0 0.00 0.00 1 __fmtinstall [188]
-----------------------------------------------
0.00 0.00 1/1 __fmtdispatch [41]
[189] 0.0 0.00 0.00 1 __fmtlock [189]
-----------------------------------------------
0.00 0.00 1/1 __fmtcpy [187]
[190] 0.0 0.00 0.00 1 __fmtpad [190]
-----------------------------------------------
0.00 0.00 1/1 __fmtdispatch [41]
[191] 0.0 0.00 0.00 1 __fmtunlock [191]
-----------------------------------------------
0.00 0.00 1/1 __fmtdispatch [41]
[192] 0.0 0.00 0.00 1 __strfmt [192]
0.00 0.00 1/1 fmtstrcpy [64]
-----------------------------------------------
This table describes the call tree of the program, and was sorted by
the total amount of time spent in each function and its children.
Each entry in this table consists of several lines. The line with the
index number at the left hand margin lists the current function.
The lines above it list the functions that called this function,
and the lines below it list the functions this one called.
This line lists:
index A unique number given to each element of the table.
Index numbers are sorted numerically.
The index number is printed next to every function name so
it is easier to look up where the function in the table.
% time This is the percentage of the `total' time that was spent
in this function and its children. Note that due to
different viewpoints, functions excluded by options, etc,
these numbers will NOT add up to 100%.
self This is the total amount of time spent in this function.
children This is the total amount of time propagated into this
function by its children.
called This is the number of times the function was called.
If the function called itself recursively, the number
only includes non-recursive calls, and is followed by
a `+' and the number of recursive calls.
name The name of the current function. The index number is
printed after it. If the function is a member of a
cycle, the cycle number is printed between the
function's name and the index number.
For the function's parents, the fields have the following meanings:
self This is the amount of time that was propagated directly
from the function into this parent.
children This is the amount of time that was propagated from
the function's children into this parent.
called This is the number of times this parent called the
function `/' the total number of times the function
was called. Recursive calls to the function are not
included in the number after the `/'.
name This is the name of the parent. The parent's index
number is printed after it. If the parent is a
member of a cycle, the cycle number is printed between
the name and the index number.
If the parents of the function cannot be determined, the word
`<spontaneous>' is printed in the `name' field, and all the other
fields are blank.
For the function's children, the fields have the following meanings:
self This is the amount of time that was propagated directly
from the child into the function.
children This is the amount of time that was propagated from the
child's children to the function.
called This is the number of times the function called
this child `/' the total number of times the child
was called. Recursive calls by the child are not
listed in the number after the `/'.
name This is the name of the child. The child's index
number is printed after it. If the child is a
member of a cycle, the cycle number is printed
between the name and the index number.
If there are any cycles (circles) in the call graph, there is an
entry for the cycle-as-a-whole. This entry shows who called the
cycle (as parents) and the members of the cycle (as children.)
The `+' recursive calls entry shows the number of function calls that
were internal to the cycle, and the calls entry for each member shows,
for that member, how many times it was called from other members of
the cycle.
Index by function name
[60] Bflush [4] clrmade [10] nrep
[22] Bgetc [7] cyclechk (graph.c) [51] outofdate
[15] Bgetrune [39] dofmt [9] parse
[56] Binit [62] dorecipe [35] popshell
[57] Binits [31] ecopy (env.c) [34] pushshell
[37] Bprint [54] envinsert (env.c) [50] rcopy
[48] Bungetrune [27] execinit [29] readenv
[38] Bvprint [63] fmtlocaleinit [11] rinsert
[42] Malloc [64] fmtstrcpy [68] rulecnt
[55] Realloc [40] fmtvprint [16] runelen
[187] __fmtcpy [44] freebuf [14] runetochar
[41] __fmtdispatch [3] graph [30] setvar
[188] __fmtinstall (fmt.c) [28] initenv [18] shcharin (sh.c)
[189] __fmtlock [33] initshell [13] stow
[190] __fmtpad [43] insert [69] syminit
[191] __fmtunlock [65] ipop [24] symlook
[8] __i686.get_pc_thunk.bx [66] ipush [32] symtraverse
[192] __strfmt [2] mk [26] timeof
[21] addrule [47] mkassert [70] update
[20] addrules [52] mkmtime [59] usage
[6] ambiguous.clone.2 (graph.c) [67] mkwaitfor [71] utflen
[25] applyrules (graph.c) [53] mtime [23] utfrune
[12] assline [49] newarc [72] vacuous.clone.1
(graph.c)
[5] attribute (graph.c) [45] newbuf [73] waitup
[58] bufcpy [46] newword [74] wdup
[61] catchnotes [17] nextrune [75] work
[19] chartorune [36] nproc
