Search code examples
c++optimizationprofilinggprof

Confusing gprof output

I ran gprof on a C++ program that took 16.637s, according to time(), and I got this for the first line of output:

%   cumulative   self              self     total           
time   seconds   seconds    calls   s/call   s/call  name    
31.07      0.32     0.32  5498021     0.00     0.00  [whatever]

Why does it list 31.07% of time if it only took .32 seconds? Is this a per-call time? (Wouldn't that be self s/call?)

This is my first time using gprof, so please be kind :)

Edit: by scrolling down, it appears that gprof only thinks my program takes 1.03 seconds. Why might it be getting it so wrong?

Solution

  • The bottleneck turned out to be in file I/O (see Is std::ifstream significantly slower than FILE?). I switched to reading the entire file in a buffer and it sped up enormously.

    The problem here was that gprof doesn't appear to generate accurate profiling when waiting for file I/O (see http://www.regatta.cs.msu.su/doc/usr/share/man/info/ru_RU/a_doc_lib/cmds/aixcmds2/gprof.htm). In fact, seekg and tellg were not even on the profiling list, and they were the bottleneck!