Bugzilla Bug 90090

When using the performance analyzer gprof, I found that it was giving values
for the time spent in functions (and total time) that exceeded the true running
time of the program.  In the example I will provide, gprof over-reports the
execution time by a factor of 10.

Reproducible: Always
Steps to Reproduce:
1. gcc -pg test.c
2. time ./a.out
3. gprof

Actual Results:  
The program took 19.9 seconds to run on my Pentium III, but gprof reported that
the running time was 196.19 seconds.


Gentoo Base System version 1.4.16
Portage 2.0.51.19 (default-linux/x86/2005.0, gcc-3.3.5-20050130,
glibc-2.3.4.20041102-r1,uclibc-0.9.26-r7,uclibc-0.9.27-r0, 2.6.10-gentoo-r6
i686)
=================================================================
System uname: 2.6.10-gentoo-r6 i686 Pentium III (Coppermine)
Python:              dev-lang/python-2.3.4-r1 [2.3.4 (#1, Feb  8 2005,
14:06:28)]
distcc 2.16 i686-pc-linux-gnu (protocols 1 and 2) (default port 3632)
[disabled]
ccache version 2.3 [enabled]
dev-lang/python:     2.3.4-r1
sys-devel/autoconf:  2.59-r6, 2.13
sys-devel/automake:  1.7.9-r1, 1.8.5-r3, 1.5, 1.4_p6, 1.6.3, 1.9.4
sys-devel/binutils:  2.15.92.0.2-r7
sys-devel/libtool:   1.5.14
virtual/os-headers:  2.6.8.1-r2
ACCEPT_KEYWORDS="x86"
AUTOCLEAN="yes"
CFLAGS="-O3 -march=pentium3 -fomit-frame-pointer"
CHOST="i686-pc-linux-gnu"
CONFIG_PROTECT="/etc /usr/kde/2/share/config /usr/kde/3/share/config
/usr/lib/X11/xkb /usr/lib/mozilla/defaults/pref /usr/share/config
/usr/share/texmf/dvipdfm/config/ /usr/share/texmf/dvips/config/
/usr/share/texmf/tex/generic/config/ /usr/share/texmf/tex/platex/config/
/usr/share/texmf/xdvi/ /var/qmail/control"
CONFIG_PROTECT_MASK="/etc/gconf /etc/terminfo /etc/env.d"
CXXFLAGS="-O3 -march=pentium3 -fomit-frame-pointer"
DISTDIR="/usr/portage/distfiles"
FEATURES="autoaddcvs autoconfig ccache distlocks sandbox sfperms strict
userpriv
usersandbox"
MAKEOPTS="-j2"
PKGDIR="/usr/portage/packages"
PORTAGE_TMPDIR="/var/tmp"
PORTDIR="/usr/portage"
SYNC="rsync://rsync.gentoo.org/gentoo-portage"
USE="x86 X alsa apm avi bitmap-fonts cdparanoia cdr crypt curl dv dvd dvdread
emboss encode esd foomaticdb fortran gif gphoto2 gtk gtk2 imagemagick imlib
java
jpeg junit libg++ libwww mbox mikmod mmx mozdevelop mozilla moznomail mp3 mpeg
ncurses network nodrm ogg oggvorbis pam pdflib perl png python qt quicktime
readline real rtc samba scanner sdl spell sse ssl tcltk tiff truetype
truetype-fonts type1-fonts usb v4l v4l2 vorbis xmms xv zlib"
Unset:  ASFLAGS, CBUILD, CTARGET, LANG, LC_ALL, LDFLAGS, LINGUAS,
PORTDIR_OVERLAY

Created an attachment (id=56961) [details]
simple program to test gprof

Compile with "gcc -pg test.c"

Created an attachment (id=56962) [details]
raw profile data

Created an attachment (id=56963) [details]
text output of gprof

try with binutils-2.15.97 ?

OK, I tried binutils-2.15.97, but I got the same results.  I installed it,
changed the links in /usr/i686-pc-linux-gnu/{bin,lib}, recompiled the test
program, ran it, and got approximately the same numbers as before.

Are you implying by your question that it works for you with 2.15.97?

no, i'm not implying anything

ive never used gprof

I noticed this problem when using kernel 2.6.10.  Today I ran the test program
under kernel 2.4.28, and gprof gave the correct result.  When I booted back into
2.6.10, and ran gprof on the already generated gmon.out, it still gave the
correct result.  So, I speculate that the problem may actually be in the
profiling code generated by gcc.  Perhaps the sampling frequency is different in
the 2.6 kernels.

the HZ is diff between 2.4 and 2.6 ... iirc, it changed by a factor of 10 from
100 in 2.4 to 1000 in 2.6

Adding to SpanKY's comment #8, that isn't entirely correct.  The timer is
different depending upon the arch.  To see what it is set to type:

grep HZ /usr/src/linux/include/asm-*/param.h

and you can see that the i386 is still 100Hz, whereas the x86-64 is 1000Hz, and
the alpha and ia64 have it set at 1024Hz for the most part.  Sometimes it sets
itself differently (like simulating an ia64 is 32Hz) though.  Is this value
exported in /proc somewhere?

yes, HZ is arch-specific, but considering the reporter is running on x86 and
the
x86 HZ changed by a factor of 10 from 1000 to 100 between 2.4 to 2.6, i dont
see
why other archs matter

Created an attachment (id=63661) [details]
Patch to return failure on interval < 2 usec or unknown failure.

This code branch (in bin-utils' gprof/hertz.c) will probably never get executed
in the near future but when the interval drops < 2usec (the value currently in
the code) it will at least return failure until a nanosecond field is added to
setitimer.  This same error is also returned in the same scenario in glibc 's
prof-freq.c.

Created an attachment (id=63662) [details]
This small program will illustrate the real problem here.

The real problem is that gprof and gcc (& the -p option) generated code rely on
checking the ticks/second at runtime via the sysconf(_SC_CLK_TCK); call.  That
returns the wrong value.  I followed this issue for a couple of hours through
many different functions/packages in an attempt to generate a patch for spanky
but I have run out of time.  (Sorry Mike)  I would like to point out though
that the original post didn't specify the problem as being x86 specific and
from this info it isn't!  My x86-64 returns a 100MHz frequency and it should be
1KHz so at the risk of sounding rude *I* do think that the arch matters.

The man page for setitimer says "... dependent  on  the  system  timer 
resolution  (currently 10ms)" and should also get corrected

OK, to my knowledge I've never run gprof, just happened across this, but FWIW, 
kernel ticks are changing again in 2.6.13.  I'm running the -rcs, and there's 
now a config option for Hz; it'll be a kernel settable option, currently with 
three choices, 100/250/1000 Hz, 250 being the recommended default for a 
well-rounded desktop system. 
 
I compiled and ran tst.c, here, and I get correct readings, but that may be 
simply because they coincide with expectations, 100 Hz (which I chose because 
ticks are per-CPU interrupts, and I'm running SMP dual Opteron).  I'll have to 
recompile the kernel for 250, reboot, and see if it's still accurately 
reported. 

Some of the devs/ops in #gentoo (moreon & reisio) confirmed 100Hz clock on i386
with 2.6.x kernels using the test code.  That is what needs fixed.

if you look at sysdeps/unix/sysv/linux/getclktck.c in glibc, you can see that
glibc first checks to see if the ELF aux vec AT_CLKTCK is set and if it isnt, it
falls back to a hardcoded '100' value

the aux vec is populated by the kernel on the stack before executing an ELF as
can be seen in linux/fs/binfmt_elf.c ... it exports the value as CLOCKS_PER_SEC
which is macrod to USER_HZ in asm/param.h which on x86_64 and i386 are both set
to 100 even though the kernel HZ define is set to 1000

last i checked, torvalds is big on the 'userspace should not care about kernel
HZ' so he doesnt export that information ... as can be seen here, we get the
shaft with the wrong kernel hz value ...

we can double check this with the provided test.c, or you can run an app through
gdb and analyze the stack before the dynamic linker gets a hold of it (thereby
cutting out glibc as being the problem) ... you should find the AT_CLKTCK aux
vec exported by the kernel on the stack with the value set to 100 (on my amd64
it is at least)

so we can say the kernel sucks because they purposefully give us the wrong
value
... however, that probably wont get us anywhere because i dont think torvalds
will change his mind ;)

procps has some indepth code to grab the correct jiffies/hertz settings ...
review the old_Hertz_hack() function in proc/sysinfo.c

More Research:
I created a guess at a patch but the research below indicates that waiting a bit
for Linux to work this out itself is the best solution.

My system is currently crunching a set of data and I don't expect it to finish
for 5-6 more days so I haven't tested this but I 'think' the solution is to
patch /usr/src/linux-2.6.12-gentoo-r4/fs/binfmt_elf.c as follows:

@@ -193,7 +193,7 @@
 #endif
        NEW_AUX_ENT(AT_HWCAP, ELF_HWCAP);
        NEW_AUX_ENT(AT_PAGESZ, ELF_EXEC_PAGESIZE);
-       NEW_AUX_ENT(AT_CLKTCK, CLOCKS_PER_SEC);
+       NEW_AUX_ENT(AT_CLKTCK, HZ);
        NEW_AUX_ENT(AT_PHDR, load_addr + exec->e_phoff);
        NEW_AUX_ENT(AT_PHENT, sizeof (struct elf_phdr));
        NEW_AUX_ENT(AT_PHNUM, exec->e_phnum);

If I knew that it worked I would have attached it as a patch, but I don't.  In
adding to Duncan's comment the kernel thread of relevence is here:

http://lkml.org/lkml/2005/5/16/228

and, if after 2.6.13 comes out, the issue is still there then I will persue it
in earnest.  Thanks for the pointer to binfmt_elf.c Mike, it helped, but the
procps stuff is a work around.  If this issue is still present in 2.6.13 and the
above works then perhaps we can get Gentoo's kernel guys to add a patch to
Linux.  As it stands now there is a patch
(http://lkml.org/lkml/diff/2005/5/16/308/1) outstanding, that Linus has read and
commented on, and that has been "Signed-off-by:" two kernel-devs, that would
rework the values that the above patch fiddles with so either way we should wait
 for a new kernel version that has the above mentioned patch by Christoph Lameter.

The patch to Linux in my previous comment works!  My clock is now reported as
1000 Hz.

that doesnt really address the fact that USER_HZ would still be exported as 100
... the only thing that changes is that the factor that gprof is off by is
different ;)

adding a patch to our kernel sources isnt really a viable option seeing as how
so many people dont use kernel ebuilds

Okay, I checked Linux-2.6.13-rc3 (many new config options) and the CONFIG_HZ
option did make it into the kernel but the relevent section of code:

-       NEW_AUX_ENT(AT_CLKTCK, CLOCKS_PER_SEC);
+       NEW_AUX_ENT(AT_CLKTCK, HZ);

has not been corrected as I had hoped.  I'm pretty sure that Duncan's system
will still report 100 Hz regardless of what he sets his CONFIG_HZ to.  Anyway
using James' test code I verified that my kernel patch does cause gprof to
produce the correct output.  So gprof is now off by a factor of 1.  Or, stated
another way, it is now correct.  James, please confirm this on your i386.

Mike and I still differ in the correct solution.  I intend to try to get the
issue fixed in the kernel and Mike has informed me that I have a better chance
of selling snow cones in the arctic circle.  He's probably right.  :-}

To quickly determine if your computer is off you can enter, as a user at the
shell prompt, "LD_SHOW_AUXV=1 getconf CLK_TCK" and look for AT_CLKTCK.  If it
says 100 and you are on a 2.6.x kernel then it is most likely wrong.  For sure
on x86-64 and i386 systems.

Redhat Bug 151763 is a duplicate of this bug.

https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=151763

Affected hardware update:

AT_CLKTCK       Kernel                            Arch

100             2.6.11.11                         athlon-xp
100             2.6.12-gentoo-r1                  pentium-m
100             2.6.10-mipscvs-20050115-ip32r5k   mips64
100             ???                               r5000
100             2.6.12.2 ppc64                    4-way power5
100             2.6.12 vanilla                    athalonXP   

Just to clarify the reason that USER_HZ is exported as 100Hz is pretty simple.
I breaks userspace changing it to 1000. so many things incorrectly hard-code 100
as the hz value and because things like (lets say uptime) will show a 2hr uptime
as 20hrs.
I am currently actually investigating into the gprof stuff itself, as I dont
think the funedemental problem has anything to do with kernel-space.

It just so happens that what you see matches conveniently.

(In reply to comment #22) 
> If it says 100 and you are on a 2.6.x kernel then it is most likely wrong. 
> For sure on x86-64 and i386 systems. 
 
Well... "for sure" unless you are running a non-mainstream kernel, or > 2.6.12.  
I'm running mainstream 2.6.13-rc3, and 100 is correct, for my system, an amd64, 
so /not/ for sure wrong any more! 
 
I did check it compiled for 250 Hz, and as I was afraid after reading comment 
#16 and later #25, it still reports 100 Hz. 
 
Well... look at it this way... with > 2.6.12, you can at least set the ticks to 
match what the kernel is advertising, 100 Hz!  =8^] 
 

Is this still a problem for anyone?  Unless I'm crazy, it seems alright for me
now:

halcyon@phoenix ~ $ time ./a.out 

real    0m6.241s
user    0m5.455s
sys     0m0.069s


Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
100.72      5.06     5.06        2     2.53     2.53  f


1000Hz for the timer

Actually, I get a different problem now.  It reports only half the time spent. 
I think it is taking the time for one call to f() and calling it the time for
both, then dividing.  Output as follows:

james@jranson ~ $ time ./a.out 

real    0m6.545s
user    0m6.550s
sys     0m0.000s

james@jranson ~ $ gprof 
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
100.73      3.29     3.29        2     1.65     1.65  f

 %         the percentage of the total running time of the
time       program used by this function.

cumulative a running sum of the number of seconds accounted
 seconds   for by this function and those listed above it.

 self      the number of seconds accounted for by this
seconds    function alone.  This is the major sort for this
           listing.

calls      the number of times this function was invoked, if
           this function is profiled, else blank.

 self      the average number of milliseconds spent in this
ms/call    function per call, if this function is profiled,
           else blank.

 total     the average number of milliseconds spent in this
ms/call    function and its descendents per call, if this 
           function is profiled, else blank.

name       the name of the function.  This is the minor sort
           for this listing. The index shows the location of
           the function in the gprof listing. If the index is
           in parenthesis it shows where it would appear in
           the gprof listing if it were to be printed.


                     Call graph (explanation follows)


granularity: each sample hit covers 2 byte(s) for 0.30% of 3.29 seconds

index % time    self  children    called     name
                3.29    0.00       2/2           main [2]
[1]    100.0    3.29    0.00       2         f [1]
-----------------------------------------------
                                                 <spontaneous>
[2]    100.0    0.00    3.29                 main [2]
                3.29    0.00       2/2           f [1]
-----------------------------------------------

Portage 2.1.3.19 (default-linux/x86/2007.0/desktop, gcc-4.1.2, glibc-2.6.1-r0,
2.6.22-gentoo-r9 i686)
=================================================================
System uname: 2.6.22-gentoo-r9 i686 Intel(R) Pentium(R) 4 CPU 1300MHz
Timestamp of tree: Wed, 28 Nov 2007 21:30:01 +0000
distcc 2.18.3 i686-pc-linux-gnu (protocols 1 and 2) (default port 3632)
[disabled]
ccache version 2.4 [enabled]
app-shells/bash:     3.2_p17
dev-java/java-config: 1.3.7, 2.0.33-r1
dev-lang/python:     2.4.4-r6
dev-python/pycrypto: 2.0.1-r6
dev-util/ccache:     2.4-r7
sys-apps/baselayout: 1.12.9-r2
sys-apps/sandbox:    1.2.18.1-r2
sys-devel/autoconf:  2.13, 2.61-r1
sys-devel/automake:  1.5, 1.7.9-r1, 1.8.5-r3, 1.9.6-r2, 1.10
sys-devel/binutils:  2.18-r1
sys-devel/gcc-config: 1.3.16
sys-devel/libtool:   1.5.24
virtual/os-headers:  2.6.22-r2
ACCEPT_KEYWORDS="x86"
CBUILD="i686-pc-linux-gnu"
CFLAGS="-O2 -march=pentium4 -msse2"
CHOST="i686-pc-linux-gnu"
CONFIG_PROTECT="/etc /usr/share/X11/xkb"
CONFIG_PROTECT_MASK="/etc/env.d /etc/env.d/java/ /etc/gconf /etc/revdep-rebuild
/etc/terminfo /etc/texmf/web2c /etc/udev/rules.d"
CXXFLAGS="-O2 -march=pentium4 -msse2"
DISTDIR="/usr/portage/distfiles"
FEATURES="ccache distlocks metadata-transfer sandbox sfperms strict
unmerge-orphans userfetch userpriv usersandbox"
GENTOO_MIRRORS="http://distfiles.gentoo.org
http://distro.ibiblio.org/pub/linux/distributions/gentoo"
LINGUAS="en"
MAKEOPTS="-j2"
PKGDIR="/usr/portage/packages"
PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --compress
--force --whole-file --delete --delete-after --stats --timeout=180
--exclude=/distfiles --exclude=/local --exclude=/packages
--filter=H_**/files/digest-*"
PORTAGE_TMPDIR="/var/tmp"
PORTDIR="/usr/portage"
PORTDIR_OVERLAY=" "
SYNC="rsync://rsync.gentoo.org/gentoo-portage"
USE="X a52 aac acpi alsa bash-completion bitmap-fonts branding bzip2 cairo caps
cddb cdparanoia cdr cli cracklib crypt cscope cups dbus dri dvd dvdr dvdread
emboss encode esd evo fam firefox fortran fuse gif gtk hal iconv imagemagick
isdnlog java jpeg mad mbox midi mikmod mjpeg mmx mozbranding mozdevelop mozilla
moznocompose moznoirc moznomail mp3 mpeg mplayer msn mudflap ncurses network
nodrm nptl nptlonly nsplugin nvidia ogg opengl openmp pam pcre pdf perl png
postgres pppd python qt3 qt3support qt4 quicktime readline real reflection rtc
sdl session simplexml sockets spl sse sse2 ssl stream svg tcpd tiff truetype
truetype-fonts type1-fonts usb vorbis win32codecs wmp x86 xforms xinerama xml
xmlrpc xorg xv zlib" ALSA_CARDS="ens1371" ALSA_PCM_PLUGINS="adpcm alaw asym
copy dmix dshare dsnoop empty extplug file hooks iec958 ioplug ladspa lfloat
linear meter mulaw multi null plug rate route share shm softvol"
APACHE2_MODULES="actions alias auth_basic authn_alias authn_anon authn_dbm
authn_default authn_file authz_dbm authz_default authz_groupfile authz_host
authz_owner authz_user autoindex cache dav dav_fs dav_lock deflate dir
disk_cache env expires ext_filter file_cache filter headers include info
log_config logio mem_cache mime mime_magic negotiation rewrite setenvif speling
status unique_id userdir usertrack vhost_alias" ELIBC="glibc"
INPUT_DEVICES="keyboard mouse evdev" KERNEL="linux" LCD_DEVICES="bayrad cfontz
cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LINGUAS="en"
USERLAND="GNU" VIDEO_CARDS="radeon nvidia"
Unset:  CPPFLAGS, CTARGET, EMERGE_DEFAULT_OPTS, INSTALL_MASK, LANG, LC_ALL,
LDFLAGS, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS

Created an attachment (id=137291) [details]
The new gprof output file

This seems to be working for me.  I can't reproduce the problem, so if anyone
can, please reopen this with how to reproduce.