This is the mail archive of the
gcc@gcc.gnu.org
mailing list for the GCC project.
Re: Gprof can account for less than 1/3 of execution time?!?!
- From: Jon Turner <jon dot turner at wustl dot edu>
- To: "gcc at gcc dot gnu dot org" <gcc at gcc dot gnu dot org>, Dave Korn <dave dot korn dot cygwin at googlemail dot com>
- Date: Mon, 22 Feb 2010 15:23:52 -0600
- Subject: Re: Gprof can account for less than 1/3 of execution time?!?!
Ok, this is not as simple as I would like to make it,
but hopefully it's simple enough. I've placed a tar file at
www.arl.wustl.edu/~jst/gprof-tarfile
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.
The basic test, with my results appears below.
% time maxFlo
20.356u 0.001s 0:20.38 99.8% 0+0k 0+0io 0pf+0w
Note, that's 20 seconds of user time. Now for gprof,
% maxFlo
% gprof maxFlo | more
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
18.87 1.17 1.17 27649 0.00 0.00 shortPath::findPath()
18.39 2.31 1.14 58654752 0.00 0.00 flograph::res(int, int) const
13.87 3.17 0.86 61391904 0.00 0.00 graph::mate(int, int) const
12.18 3.93 0.76 55889952 0.00 0.00 graph::next(int, int) const
6.29 4.32 0.39 61391904 0.00 0.00 graph::left(int) const
5.65 4.67 0.35 65055289 0.00 0.00 graph::term(int) const
5.16 4.99 0.32 61391904 0.00 0.00 digraph::tail(int) const
4.03 5.24 0.25 70488952 0.00 0.00 graph::n() const
3.63 5.46 0.23 9232153 0.00 0.00 list::operator&=(int)
2.10 5.59 0.13 9165337 0.00 0.00 list::operator<<=(int)
1.94 5.71 0.12 58654752 0.00 0.00 graph::m() const
1.45 5.80 0.09 27649 0.00 0.00 list::makeSpace()
1.29 5.88 0.08 9165337 0.00 0.00 list::operator[](int) const
1.21 5.96 0.08 9165337 0.00 0.00 graph::first(int) const
0.81 6.01 0.05 2737152 0.00 0.00 flograph::addFlow(int, int, int)
0.81 6.06 0.05 27648 0.00 0.00 augPath::augment()
0.65 6.10 0.04 2737152 0.00 0.00 min(int, int)
0.48 6.13 0.03 15466777 0.00 0.00 flograph::src() const
0.48 6.16 0.03 fatal(char*)
0.24 6.17 0.02 operator<<(std::ostream&, list const&)
0.16 6.18 0.01 9287496 0.00 0.00 flograph::snk() const
0.16 6.19 0.01 9165338 0.00 0.00 list::empty() const
0.16 6.20 0.01 list::clear()
0.00 6.20 0.00 27649 0.00 0.00 list::freeSpace()
0.00 6.20 0.00 27649 0.00 0.00 list::list(int)
0.00 6.20 0.00 27649 0.00 0.00 list::~list()
0.00 6.20 0.00 1140 0.00 0.00 digraph::join(int, int)
0.00 6.20 0.00 1140 0.00 0.00 flograph::changeCap(int, int)
0.00 6.20 0.00 1 0.00 0.00 global constructors keyed to _Z7badCasei
0.00 6.20 0.00 1 0.00 0.00 global constructors keyed to _ZN4list9makeSpaceEv
0.00 6.20 0.00 1 0.00 0.00 global constructors keyed to _ZN4misc6cflushERSic
0.00 6.20 0.00 1 0.00 0.00 global constructors keyed to _ZN5graph9makeSpaceEv
0.00 6.20 0.00 1 0.00 0.00 global constructors keyed to _ZN7augPathC2ER8flographRi
0.00 6.20 0.00 1 0.00 0.00 global constructors keyed to _ZN7digraph9makeSpaceEv
0.00 6.20 0.00 1 0.00 0.00 global constructors keyed to _ZN8flograph9makeSpaceEv
0.00 6.20 0.00 1 0.00 0.00 global constructors keyed to _ZN9shortPathC2ER8flograph
Ri
0.00 6.20 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)
0.00 6.20 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)
0.00 6.20 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)
0.00 6.20 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)
0.00 6.20 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)
0.00 6.20 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)
0.00 6.20 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)
0.00 6.20 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)
0.00 6.20 0.00 1 0.00 0.00 badCase(int)
0.00 6.20 0.00 1 0.00 0.00 graph::makeSpace()
0.00 6.20 0.00 1 0.00 0.00 graph::graph(int, int)
0.00 6.20 0.00 1 0.00 0.00 augPath::augPath(flograph&, int&)
0.00 6.20 0.00 1 0.00 0.00 augPath::~augPath()
0.00 6.20 0.00 1 0.00 0.00 digraph::makeSpace()
0.00 6.20 0.00 1 0.00 0.00 digraph::digraph(int, int)
0.00 6.20 0.00 1 0.00 0.00 flograph::makeSpace()
0.00 6.20 0.00 1 0.00 0.00 flograph::flograph(int, int, int, int)
0.00 6.20 0.00 1 0.00 6.15 shortPath::shortPath(flograph&, int&)
0.00 6.20 0.00 1 0.00 0.00 shortPath::~shortPath()
I cut this off after gprof displayed the flat profile. The important thing
to note is that the cumulative seconds reported by gprof never exceeds 6.2
seconds.
Here's some basic cpu info.
% more /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 15
model : 2
model name : Intel(R) Pentium(R) 4 CPU 2.40GHz
stepping : 9
cpu MHz : 2394.152
cache size : 512 KB
fdiv_bug : no
hlt_bug : no
f00f_bug : no
coma_bug : no
fpu : yes
fpu_exception : yes
cpuid level : 2
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fx
sr sse sse2 ss ht tm pbe up cid xtpr
bogomips : 4790.27
clflush size : 64
Any insight or advice will be much appreciated.
Jon