Red Hat Bugzilla – Bug 151763
gprof's estimate of runtime is way off
Last modified: 2013-07-02 23:04:33 EDT
Description of problem:
I just finished a gprof run in which I know that the actual run time of the program was not more
than 160 seconds (because this is the elapsed wall clock time). However gprof shows a breakdown
that adds up to 440 seconds. The relative times assigned to functions look plausible, but I can't say
that I have any faith in the results after noticing this...
Version-Release number of selected component (if applicable):
At least with this particular test case (a Postgres benchmark query), I consistently get gprof totals that
are nearly three times the actual wall-clock time. I'm not sure if the effect will occur on other
programs. Have you seen anything similar?
Steps to Reproduce:
1. Run a program compiled -pg, note wall clock time needed.
3. note total time claimed in gprof output.
gprof total >> wall clock
gprof total somewhat less than wall clock
This is an up-to-date FC3 system. Ping me about any specific versions you want verified.
This issue has been argued in detail, had the problem issolated, and a proposed
patch offered in the Gentoo bugzilla:
It includes test programs demonstarting the profile timing problem as well as an
elf program to quickly query the system for the setting and see the wrong one
returned. There is also a command line query to determine that your system is
wrong. The problem is the kernel loads an incorrect value into the elf header
and gprof (and others) use that value for calculations to ill effect.
The hardware platform needs to be changed to all here. It for sure effects
x86-64 & i386. Looking over the code it appears to affect many other archs. Can
anyone confirm this?
This is actually a glibc bug.
profil/sprofil call setitimer with timer.it_value.tv_sec = 0,
timer.it_value.tv_usec = 1 and then assumes that the kernel will round that up
and deliver SIGPROF every 1/_SC_CLK_TCK of a second, which (afaict) isn't
guaranteed by anything. (The only real use of _SC_CLK_TCK in Linux (and POSIX,
afaict) is as the resolution of clock_t.)
This happens to work when the value of _SC_CLK_TCK matches the kernel internal
timer granularity, but falls over when the kernel is actually operating at a
different frequency (i.e. 2.6 kernels).
Or maybe the problem is in the Linux version of __profile_frequency(), which is
assuming that the AT_CLKTCK ELF auxv value has some relation to the kernel's
confirmed in rhel4 update 1 (do I need to open a new ticket?)
Fedora Core 3 is now maintained by the Fedora Legacy project for security
updates only. If this problem is a security issue, please reopen and
reassign to the Fedora Legacy product. If it is not a security issue and
hasn't been resolved in the current FC5 updates or in the FC6 test
release, reopen and change the version to match.
Fedora Core 3 is not maintained anymore.
Setting status to "INSUFFICIENT_DATA". If you can reproduce this bug in the
current Fedora release please reopen this bug and assign it to the corresponding