Re: gprof - output

[Ian Lance Taylor <ian at wasabisystems dot com>]

Rajesh Munavalli <munavallirv@ornl.gov> writes:

> Does gprof list the time taken by the std::string functions?.

It depends upon how you compiled the program.  gprof can only list the
functions which were actually compiled with -pg.  It also can only
list the functions which were not inlined.  In the case of C++, if you
did not explicitly compile the library with profiling, this can be a
slightly tricky matter to determine.  Some template functions will be
compiled with your program, and some will be invoked from the library.

When I look at your program, logic tells me that the std::string
functions take a lot of the time required to execute testStr.  If they
were inlined into testStr, they would be counted as part of the time
required for testStr.  If they were not inlined into testStr, but were
compiled into the same object file, then they should appear in the
profiling list.  If they were not inlined into testStr, but were
linked in from the C++ library, then they would not appear in the
profiling list and their time would not be counted.

On i386 GNU/Linux using gcc 3.3.2 and gprof 2.14.90.0.6, compiling the
program with -O2, I get this in the profiling information:

 96.66     14.18    14.18      100   141.80   141.80  testStr()
  3.34     14.67     0.49      100     4.90     4.90  testChar()

Compiling with no optimization options, I get this:

 78.37      3.66     3.66      100    36.60    36.60  testChar()
 21.63      4.67     1.01      100    10.10    10.10  testStr()

I conclude that you most likely compiled with no optimization options,
although you neglected to say.

When I look at the assembler code generated for testStr with no
optimization options, I see two loops calling
    std::string::operator+=(char const*)
That function is not compiled into the program, and when linked comes
from the shared libstdc++ library, which was not compiled with
profiling information.  When execution enters the shared library,
gprof no longer knows how to account for it.

Thinking about this a bit further than I did before, the profil
function which is called when profiling starts specifies the address
space to which profiling should be supplied when using the profiling
timer.  A shared library will not fall into that address space, and
therefore profiling ticks which occur while the function is executing
within the shared library will not be counted.

If I link with -static, to force the shared library functions to be in
the same address space even though they were not compiled with -pg,
then at least I do see some information on them in the profile.

 %   cumulative   self              self     total
 time   seconds   seconds    calls   s/call   s/call  name
 29.47     13.68    13.68                             strlen
 28.33     26.83    13.15                             memcpy
  8.77     30.90     4.07                             std::string::_M_mutate(unsigned int, unsigned int, unsigned int)
  7.78     34.51     3.61      100     0.04     0.04  testChar()
  6.40     37.48     2.97                             std::string& std::string::_M_replace_safe<char const*>(__gnu_cxx::__normal_iterator<char*, std::string>, __gnu_cxx::__normal_iterator<char*, std::string>, char const*, char const*)
  6.01     40.27     2.79                             std::string::append(char const*, unsigned int)
  4.20     42.22     1.95                             std::string::operator+=(char const*)
  3.71     43.94     1.72                             std::string::_M_iend() const
  3.06     45.36     1.42                             std::string::_M_ibegin() const
  2.11     46.34     0.98      100     0.01     0.01  testStr()
...

As you can see the profiling timer now picks up the library functions
for basic timing information, although since they were not compiled
with -pg there is no information on the number of times they were
called, etc.

I apologize for my initial misleading answer.

Ian