2

I have a simple C code with many function calls, which I profiled using gprof. 

%   cumulative   self              self     total           
 time   seconds  seconds    calls   s/call   s/call  name    
71.93    907.85   907.85   201280     0.00     0.00  ForceCalcs
 2.61   1237.18    33.00     1258     0.03     1.00  Heap
 1.53   1256.45    19.28     1258     0.02     0.02  AdjustSP
 0.01   1261.61     0.07     1258     0.00     0.00  Boundary
 0.00   1261.61     0.00      100     0.00     0.00  Profile
 0.00   1261.61     0.00        2     0.00     0.00  MakeMap
 0.00   1261.61     0.00        1     0.00     0.18  Initialize

I have omitted some other function calls from the list just for clarity. This is why the percentages don't add up to 100. To compare the results, I compiled it with -O3 command and profiled it again with gprof. The flat profile obtained is like :

% Each sample counts as 0.01 seconds.
% (--- means nothing mentioned)
%   cumulative   self              self     total 
 time   seconds  seconds    calls  ms/call  ms/call  name
73.66    460.88   460.88   201280     2.29     2.29  ForceCalc
 1.65    620.85    10.30    ---       ---      ---   Heap
 0.47    623.80     2.95    ---       ---      ---   AdjustSP
 0.00    626.10     0.01     1258     0.01     0.01  Boundary
 0.00    626.10     0.00        1     0.00     0.00  MakeMap

But now I cannot make much sense as to what optimizations have taken place in my code. For example

  1. The calls to Initialize() and profile() have no corresponding entry in later profile
  2. There are no mentioned calls or msec/call for Heap() and AdjustSP() in the later profile. (This is what I wanted to show by the --- )

Can someone please explain the meaning of above 2 observations. I think it has got something to do with inline but am not sure.

Doug Lipinski
  • 4,591
  • 16
  • 25
  • 1
    Yes, it is probably the effect of -O3 inlining some functions, difficult to say without the code, if it is short enough, can you include it in the question ? (or at least the code of Heap() and AdjustSP()) ? – BrunoLevy Aug 31 '15 at 06:57
  • 4
    Either way, your code is spending more than 70% of its time in the ForceCalc function (and this is "self time" so it isn't spending any of this time in subroutines called by ForceCalc.) As a practical matter any substantial speedup that can be achieved would have to come from speeding up ForceCalc or calling it less often. – Brian Borchers Sep 01 '15 at 02:12
  • You can see whether calls have been inlined by comparing the generated assembly code output for -O0 and -O3. You can get the assembly dump either by using objdump -d on the object files of the code or compiling with gcc -S. The flag -fverbose-asm will make it easier to read the assembly dump by adding some extra annotations to it. – Daniel Shapero Sep 01 '15 at 05:37
  • As Brian said, most of the time is spent in ForceCalc. gprof will not tell you where in that function. The stack-sampling method many people use will tell you where and why the time is spent. Note, it is not a process of measuring. Since 7/10 of the time is in ForceCalc, you will see the problem after very few samples (2 or 3). If you're interested, here's why. – Mike Dunlavey Oct 02 '15 at 14:44

1 Answers1

3

Two things that may help understanding what's going on:

1) the output of gprof is sometimes hard to parse

There is a tool that helps obtaining a graphical representation called gprof2dot (used as follows in combination with dot):

gprof executable | gprof2dot.py | dot -T pdf > profile.pdf

where

2) use a system-wide profiler in conjunction with gprof

For instance, under Linux, you can use zoom: http://freshmeat.sourceforge.net/projects/zoomprofiler

It is freely available.

Mike Dunlavey
  • 1,023
  • 2
  • 9
  • 10
BrunoLevy
  • 2,315
  • 12
  • 22