Bug 473480 - gprof reports *incorrect* cumulative time
gprof reports *incorrect* cumulative time
Status: CLOSED WORKSFORME
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: binutils (Show other bugs)
5.0
x86_64 Linux
medium Severity medium
: rc
: ---
Assigned To: Denys Vlasenko
BaseOS QE
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-11-28 13:52 EST by Paul B.
Modified: 2008-12-18 15:26 EST (History)
2 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2008-12-18 15:26:39 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
Gentoo 90090 None None None Never

  None (edit)
Description Paul B. 2008-11-28 13:52:47 EST
Description of problem:

When profiling with gprof, reported total time is about a factor of two smaller than actual time (reported by /usr/bin/time and wall-clock).

Version-Release number of selected component (if applicable):

GNU gprof 2.17.50.0.6-2.el5
Linux qubit.internal.dwavesys.com 2.6.18-8.1.4.el5xen #1 SMP

How reproducible: Always

Steps to Reproduce:

[pbunyk@qubit src]$ cat test.c 
void f()
{
        int i;
        for (i = 0; i < 1000000000; i++);
}

int main()
{
        f(); f();
        return 0;
}
[pbunyk@qubit src]$ gcc -o test -pg test.c 
[pbunyk@qubit src]$ time ./test

real    0m5.751s
user    0m5.744s
sys     0m0.000s
[pbunyk@qubit src]$ gprof test gmon.out
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
101.33      2.92     2.92        2     1.46     1.46  f

Actual results:
gprof total time is 2.92 seconds

Expected results:
Same as 'time', 5.7 seconds

Additional info:
This bug seems to be around for a while. If gprof is no longer actively supported, what is the alternative for simple user-mode profiler? Are we all supposed to switch to oprofile, and learn how to use it, and mess with kernel modules and running some parts as root just to get consistent profiling results?
Comment 1 Roman Rakus 2008-12-04 03:24:36 EST
gprof belongs to the package binutils. And I see one small mistake. What shows you `command -v time'? Time is bash builtin, so probably the output is from this builtin and not from /usr/bin/time. This is only for information. Changing component to binutils.
Comment 2 Paul B. 2008-12-04 14:18:52 EST

(In reply to comment #1)
> gprof belongs to the package binutils. And I see one small mistake. What shows
> you `command -v time'? Time is bash builtin, so probably the output is from
> this builtin and not from /usr/bin/time. This is only for information. Changing
> component to binutils.

Yes, both explicit /usr/bin/time and bash built-in time show the same times (different format though), the example I gave indeed used built-in one.
Comment 3 Denys Vlasenko 2008-12-18 13:34:08 EST
Datapoint: works on the following hardware / release combination:

[root@nec-em6 tmp]# uname -a
Linux nec-em6.rhts.bos.redhat.com 2.6.18-127.el5 #1 SMP Mon Dec 15 21:40:51 EST 2008 x86_64 x86_64 x86_64 GNU/Linux

[root@nec-em6 tmp]# cat /etc/redhat-release
Red Hat Enterprise Linux Server release 5.3 (Tikanga)

[root@nec-em6 tmp]# rpm -qf /usr/bin/gprof
binutils-2.17.50.0.6-9.el5

[root@nec-em6 tmp]# gcc -o test -pg test.c

[root@nec-em6 tmp]# time ./test           

real    0m3.166s
user    0m3.165s
sys     0m0.001s
[root@nec-em6 tmp]# 
[root@nec-em6 tmp]# gprof test gmon.out
Flat profile:                          

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
101.27      2.91     2.91        2     1.45     1.45  f       

...

Will test earlier RHEL now...
Comment 4 Denys Vlasenko 2008-12-18 15:26:09 EST
RHEL 5 (not RHEL 5.3) also works:


[root@hp-ml370g5-01 tmp]# uname -a
Linux hp-ml370g5-01.rhts.bos.redhat.com 2.6.18-8.el5 #1 SMP Fri Jan 26 14:15:14 EST 2007 x86_64 x86_64 x86_64 GNU/Linux

[root@hp-ml370g5-01 tmp]# cat /etc/redhat-release
Red Hat Enterprise Linux Server release 5 (Tikanga)

[root@hp-ml370g5-01 tmp]# rpm -qf /usr/bin/gprof
binutils-2.17.50.0.6-2.el5

[root@hp-ml370g5-01 tmp]# gcc -o test -pg test.c

[root@hp-ml370g5-01 tmp]# time ./test
real    0m3.772s
user    0m3.770s
sys     0m0.001s

[root@hp-ml370g5-01 tmp]# gprof test gmon.out
Flat profile:                                

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
101.33      3.47     3.47        2     1.73     1.73  f       

....

Note You need to log in before you can comment on or make changes to this bug.