"gprof" do not works anymore since longs time

[kas1e]

As we found lately "gprof" is not working for a long time on machines which support performance monitor in the kernel (like for example pegasos2). "gmoun.out" file creates fine for both clib2 and newlib builds when we specify -pg, but then when we tried to use our gprof on it shows us nothing at all, while the same test cases show a lot on linux/win32 versions.

There are test cases :

//test_gprof.c
#include<stdio.h>

void new_func1(void);

void func1(void)
{
    printf("\n Inside func1 \n");
    int i = 0;

    for(;i<0xffffffff;i++);
    new_func1();

    return;
}

static void func2(void)
{
    printf("\n Inside func2 \n");
    int i = 0;

    for(;i<0xffffffaa;i++);
    return;
}

int main(void)
{
    printf("\n Inside main()\n");
    int i = 0;

    for(;i<0xffffff;i++);
    func1();
    func2();

    return 0;
}

And second file:

//test_gprof_new.c
#include<stdio.h>

void new_func1(void)
{
    printf("\n Inside new_func1()\n");
    int i = 0;

    for(;i<0xffffffee;i++);

    return;
}

So we compile it as:

ppc-amigaos-gcc -mcrt=clib2 -Wall -pg test_gprof.c test_gprof_new.c -o test_gprof

Running it, have the output, but when we use ppc-amigaos-gprof.exe on it it show us just "no time accumulated" nothing under "granularity" , and at the end of output just "Index by function name" and no list of functinons. On the win32/cygwin for example, the same test gives us:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls   s/call   s/call  name
 34.40     15.32    15.32        2     7.66    14.98  func1
 32.87     29.96    14.64        1    14.64    14.64  new_func1
 32.60     44.48    14.52                             func2
  0.13     44.54     0.06                             main


granularity: each sample hit covers 4 byte(s) for 0.02% of 44.54 seconds

index % time    self  children    called     name
                                                 <spontaneous>
[1]     67.4    0.06   29.96                 main [1]
               15.32   14.64       2/2           func1 [2]
-----------------------------------------------
               15.32   14.64       2/2           main [1]
[2]     67.3   15.32   14.64       2         func1 [2]
               14.64    0.00       1/1           new_func1 [3]
-----------------------------------------------
               14.64    0.00       1/1           func1 [2]
[3]     32.9   14.64    0.00       1         new_func1 [3]
-----------------------------------------------
                                                 <spontaneous>
[4]     32.6   14.52    0.00                 func2 [4]
-----------------------------------------------

Index by function name

   [2] func1                   [1] main
   [4] func2                   [3] new_func1

So something got broken on our side.

Another intersting moment which probably can help us out a little is that newlib compilation of such test case just can't be done. See:

$ ppc-amigaos-gcc -Wall -pg test_gprof.c test_gprof_new.c -o test_gprof
/usr/local/amiga/ppc-amigaos/SDK/newlib/lib/libc.a(profile_gmon.o): In function `mongetpcs':
(.text+0x32e): undefined reference to `IElf'
/usr/local/amiga/ppc-amigaos/SDK/newlib/lib/libc.a(profile_gmon.o): In function `mongetpcs':
(.text+0x3aa): undefined reference to `IElf'
/usr/local/amiga/ppc-amigaos/SDK/newlib/lib/libc.a(profile_gmon.o): In function `mongetpcs':
(.text+0x3ea): undefined reference to `IElf'
/usr/local/amiga/ppc-amigaos/SDK/newlib/lib/libc.a(profile_gmon.o): In function `mongetpcs':
(.text+0x40e): undefined reference to `IElf'
/usr/local/amiga/ppc-amigaos/SDK/newlib/lib/libc.a(profile_gmon.o): In function `mongetpcs':
(.text+0x47e): undefined reference to `IElf'
/usr/local/amiga/ppc-amigaos/SDK/newlib/lib/libc.a(profile_gmon.o):(.text+0x536): more undefined references to `IElf' follow
collect2: error: ld returned 1 exit status

That probably mean that profile_gmon.c of libc.a need to be updated for a start.

[salass00]

The IElf undefined references will be fixed in newlib V53.77. It looks like I introduced this error by mistake when I renamed the interface variable to avoid a compiler warning for newlib V53.66 (I didn't consider that the code was using USE_INLINE so that the name has to be the same as used by the inline4 macros).

[kas1e]

@salass00
Sorry for the late reply (have issues with AdBlock disallowing me to answer/edit posts on Github, sorted now). As I wrote in beta-list: yeah, everything compiles ok with newlib 53.77 now, thanks!

@ALL
So I go further and find out what the issue is:

gmon.out produced by clib2's profiler in all SDK since SDK 53.3 (the year 2008), can't be parsed by any version of gprof (show empty fields everywhere). And reasons are internal-inbuild-to-ld ldscript, called "Default linker script, for normal executables" where since SDK 53.3 this field of the script was changed:

PROVIDE (__executable_start = 0x00000000); . = 0x00000000 + SIZEOF_HEADERS;

on

PROVIDE (__executable_start = 0x01000000); . = 0x01000000 + SIZEOF_HEADERS;

See addresses in 2 parts changed from simple zero one to 01000000 one. Once that was done, gmon.out files still continue to builds as expected, of the same file size, but content inside starts to be different, and any gprof of any version (old ones, new ones, does not matter), show only empty fields in the output.

If I manually patch "ld" binary and change there for default-executable script those 2 addresses from 01000000 to 00000000, then everything compiles fine, works fine, and any version of gprof can be used to see the correct output. I even tried it now with the latest 11.2 of GCC and the latest Binutils we have and all works fine.

Another way to make "-pg" with clib2 profiler works, it does not patch the "ld" binary, but simply provide -Ttext=0x00000000 on compiling stage, i.e.:

ppc-amigaos-gcc -mcrt=clib2 -Ttext=0x0000000 -pg -gstabs test_gprof.c test_gprof_new.c -o test_gprof_clib2 -lprofile

It also did the trick, while making the binary files be a little bit bigger.

The same issues applied to newlib of course too. The output from newlib's profiler and clib2's profiler is a bit different, though.

In newlib we have just "main, func1 and func2" in clib2 we have "main, func1, func2 , closelibraries and fini_". Not sure though if those ones should be there (i mean closelibraries and fini_). Newlib's output looks close to what Cygwin provides, while clib2 seems to go a bit deeper (which is also not bad, just different).

What is also interesting, is that if i patch "ld", then for newlib output i have in "index by function name" also _start function and func1 + main. But if i use -Ttext=0x00000000 then i didn't have _start() in output, but instead func1, func2 and new_func1 (but not main). So it can be that shifting is still wrong for newlib profiler.

In other words, we need to understand why there was a change from 0x00000000 to 0x01000000 in the first place, then, if that for real need it (i assume that need it for GDB and something else?) and if it needs it, then fix clib2 and newlib profilers so they will take into account 0x01000000 value.

[kas1e]

@ALL
I collect some more interesting information which can help us to deal with. I got an answer from Thomas and ask for some help from Frank Wille (VBCC author) if he had any idea about it, and that is what we got:

For first, Thomas thinks that the 0x01000000 switch was necessary for the shared objects support since these did add a .plt section, potentially in front of the .text (which means 0 as text base address was no longer working). And he thinks it should be enough to add the base address (0x01000000) to any sampled address it finds, because right now, when sampling, it probably just subtracts the binaries load address, so it would need to add the base address at that point too.

Also, he checked gprof implementation and find that it implements a symbol table for the binary in question. And since we need to translate from the actual LoadSeg() address to .text segment addresses, the symbol table should take care of the translation.

In other words, what Thomas means, is that we need to translate from LoadSeg() address we got by GetSectionTags to .text segment addresses (i.e. our "lowpc" which currently we set as 0). (i.e. all that we have inside of https://github.com/sodero/clib2/blob/master/library/profile_gmon.c).

Frank also says that 0x01000000 is arbitrarily chosen and has no real meaning, as the executables will be relocated to their real load address in any case. He also thinks that we have a bug with all that 0x00000000 because even Unix ELF executables will always have a non-null start address as well..

He checked the code of the clib2 profiler briefly, and he also thinks that the key is profile_gmon.c, which uses a hard-coded lowpc of 0. I.e. those "FIX me" and stuff as can be seen in comments (there lowpc set to 0 in two places, while should be just p->lowpc). He guesses that monstartup() is called with low_pc and high_pc zeroed, so mongetpcs() must be called, which fetches the start- and end-address of the first executable section (.text) from the ELF file. There is certainly reads a low_pc of 0x01000000, which is in conflict with the zero hardcoding.

I didn't understand the last part but hope it is bringing some light on how to fix it in both clib2 and newlib.

All i tried to do currently, it's take profile__mcount.c, profile_gmon.c, and profile_mcount.S, compile it manually, and made my own libprofilka.a (so not need for rebuild whole adtools) and there i tried to just change those zeros in 2 places firstly on 0x0100000 , it then says "gmon.out is not of gmon.out format", and then tries to put p->lowpc instead (as it expected to be on all other platforms), and the same fail. So something else i miss ..

@salass00
Can you check plz if newlib's profiler is the same straight copy of the clib2 profiler just with a little adaptation? I.e. did it have the same "lowpc hadrcored to zeros" code? Is so, that can explain why it fail the same.