On Mon, Feb 22, 2010 at 03:23:52PM -0600, Jon Turner wrote: > In it, you will find a directory with all the source code > needed to observe the problem for yourself. > The top level directory contains a linux executable called > maxFlo, which you should be able to run on a linux box > as is. But if you want/need to compile things yourself, > type "make clean" and "make all" in the top level > directory and you should get a fresh copy of maxFlo.
So, compiling maxFlo with no -pg option: @nightcrawler:~/src/gprof-trouble-case$ time ./maxFlo real 0m3.465s user 0m3.460s sys 0m0.000s Compiling maxFlo with -pg option: @nightcrawler:~/src/gprof-trouble-case$ time ./maxFlo real 0m9.780s user 0m9.760s sys 0m0.010s Notice that ~60% of the running time with gprof enabled is simply overhead from call counting and the like. That time isn't recorded by gprof. That alone accounts for your report about gprof ignoring 2/3 of the execution time. Checking to see whether maxFlo is a dynamic executable (since you claimed earlier that you were statically linking your program): @nightcrawler:~/src/gprof-trouble-case$ ldd ./maxFlo linux-vdso.so.1 => (0x00007fff2977f000) libstdc++.so.6 => /usr/lib/libstdc++.so.6 (0x00007fb422c21000) libm.so.6 => /lib/libm.so.6 (0x00007fb42299d000) libgcc_s.so.1 => /lib/libgcc_s.so.1 (0x00007fb422786000) libc.so.6 => /lib/libc.so.6 (0x00007fb422417000) /lib64/ld-linux-x86-64.so.2 (0x00007fb422f31000) So calls to shared library functions (such as functions in libm) will not be caught by gprof. Those calls count account for a significant amount of running time of your program and gprof can't tell you about them. Inspecting the gmon.out file: @nightcrawler:~/src/gprof-trouble-case$ gprof maxFlo gmon.out Flat profile: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls s/call s/call name 16.09 0.37 0.37 27649 0.00 0.00 shortPath::findPath() 12.61 0.66 0.29 55889952 0.00 0.00 graph::next(int,int) const 11.96 0.94 0.28 61391904 0.00 0.00 graph::mate(int,int) const 10.87 1.19 0.25 58654752 0.00 0.00 flograph::res(int,int) const 10.44 1.43 0.24 _fini 6.96 1.59 0.16 65055289 0.00 0.00 graph::term(int) const 6.96 1.75 0.16 61391904 0.00 0.00 digraph::tail(int) const [...lots of stuff elided...] 0.00 2.30 0.00 1 0.00 0.00 graph gprof is telling you about 2.3 seconds of your execution time. With the factors above accounted for, that doesn't seem unreasonable. -Nathan
