Functions defined with the gcc ifunc __attribute__ are called twice

[claudiubalogh]

> uftrace --version
uftrace v0.9.4-237-g9502 ( x86_64 tui perf sched )
> g++ --version
g++ (SUSE Linux) 7.4.0

The code pasted at the end and built with g++ (SUSE Linux) 7.4.0 works correctly when run independently:

> ./test-ifunc
enter value:5
5: avx called

However, when run from uftrace it seems the function is called one more time, with an undefined argument value:

> uftrace record test-ifunc
enter value:7
7: avx called
6300349: avx called

GCC function attribute "ifunc" is defined here: https://gcc.gnu.org/onlinedocs/gcc-7.4.0/gcc/Common-Function-Attributes.html#Common-Function-Attributes

Build with: g++ -pg test-ifunc.cpp -o test-ifunc

#include <iostream>

using namespace std;

void fn_ref(uint32_t c) {
  std::cout << c << ": ref called\n";
}

void fn_sse(uint32_t c) {
  std::cout << c << ": sse called\n";
}

void fn_avx(uint32_t c) {
  std::cout << c << ": avx called\n";
}

extern "C" auto resolve_fn() -> void (*)(uint32_t) {
  __builtin_cpu_init();
  if (__builtin_cpu_supports("avx2") && __builtin_cpu_supports("fma")) {
    return fn_avx;
  } else if (__builtin_cpu_supports("sse4.1")) {
    return fn_sse;
  }
  return fn_ref;
}

void fn(uint32_t) __attribute__ ((ifunc ("resolve_fn")));

int main(int argc, char** argv) {
  uint32_t c;
  cout << "enter value:";
  cin >> c;
  fn(c);
}

[honggyukim]

@claudiubalogh Thanks for reporting this bug. I can reproduce the same problem with the following simpler example.

$ cat ifunc.c
#include <stdio.h>

void bar(void)
{
    printf("[%s]\n", __func__);
}

typedef void(*callback)(void);

callback resolve_foo()
{
    printf("[%s]\n", __func__);
    return bar;
}

void foo(void) __attribute__ ((ifunc("resolve_foo")));

int main()
{
    printf("[%s]\n", __func__);
    foo();
    return 0;
}

The compiled binary works fine but it gets crashed with uftrace as follows.

$ gcc -pg ifunc.c

$ ./a.out
[resolve_foo]
[main]
[bar]

$ uftrace record a.out
[resolve_foo]
WARN: child terminated by signal: 11: Segmentation fault

The gdb information is as follows.

$ gdb -q -ex=r --args uftrace record a.out
    ...
[resolve_foo]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".

Thread 2.1 "a.out" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff7fc6800 (LWP 45478)]
0x00007ffff7b93e8f in __mcount_entry (parent_loc=0x9, child=140737349666389, regs=0x7fffffffd9b8) at /home/honggyu/work/uftrace/libmcount/mcount.c:1341
1341            rstack->parent_ip  = *parent_loc;

The problem is that parent_loc is an invalid value.

(gdb) p parent_loc
$1 = (unsigned long *) 0x9

The backtrace shows that there is no parent function that invoked mcount(). It may be because ifunc("resolve_foo") calls before main but without its parent.

(gdb) bt
#0  0x00007ffff7b93e8f in __mcount_entry (parent_loc=0x9, child=140737349666389, regs=0x7fffffffd9b8) at /home/honggyu/work/uftrace/libmcount/mcount.c:1341
#1  0x00007ffff7b93f85 in mcount_entry (parent_loc=0x9, child=140737349666389, regs=0x7fffffffd9b8) at /home/honggyu/work/uftrace/libmcount/mcount.c:1367
#2  0x00007ffff7bbc4bb in mcount () at /home/honggyu/work/uftrace/arch/x86_64/mcount.S:61
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

To avoid this problem, I tried --estimate-return as well, but it also gets crashed.

$ uftrace record -e a.out
[resolve_foo]
WARN: Segmentation fault: address not mapped (addr: 0x9)
WARN: Backtrace from uftrace v0.9.4-237-g9502 ( x86_64 dwarf python luajit tui perf sched dynamic )
WARN: =====================================
WARN: [0] (__cxa_atexit[400550] <= <4004ed>[4004ed])

Please report this bug to https://github.com/namhyung/uftrace/issues.

WARN: child terminated by signal: 11: Segmentation fault

We may have to change the code as follows to avoid this problem.

diff --git a/libmcount/mcount.c b/libmcount/mcount.c
index 8b7d3a82..71356da3 100644
--- a/libmcount/mcount.c
+++ b/libmcount/mcount.c
@@ -1338,7 +1338,6 @@ static int __mcount_entry(unsigned long *parent_loc, unsigned long child,
        rstack->depth      = mtdp->record_idx;
        rstack->dyn_idx    = MCOUNT_INVALID_DYNIDX;
        rstack->parent_loc = parent_loc;
-       rstack->parent_ip  = *parent_loc;
        rstack->child_ip   = child;
        rstack->start_time = mcount_gettime();
        rstack->end_time   = 0;
@@ -1347,6 +1346,8 @@ static int __mcount_entry(unsigned long *parent_loc, unsigned long child,
        rstack->event_idx  = ARGBUF_SIZE;

        if (!mcount_estimate_return) {
+               rstack->parent_ip  = *parent_loc;
+
                /* hijack the return address of child */
                *parent_loc = mcount_return_fn;

diff --git a/libmcount/plthook.c b/libmcount/plthook.c
index ed917685..9c821027 100644
--- a/libmcount/plthook.c
+++ b/libmcount/plthook.c
@@ -841,7 +841,6 @@ static unsigned long __plthook_entry(unsigned long *ret_addr,
        rstack->pd         = pd;
        rstack->dyn_idx    = child_idx;
        rstack->parent_loc = ret_addr;
-       rstack->parent_ip  = *ret_addr;
        rstack->child_ip   = sym->addr;
        rstack->start_time = skip ? 0 : mcount_gettime();
        rstack->end_time   = 0;
@@ -850,6 +849,8 @@ static unsigned long __plthook_entry(unsigned long *ret_addr,
        rstack->event_idx  = ARGBUF_SIZE;

        if (!mcount_estimate_return) {
+               rstack->parent_ip  = *ret_addr;
+
                /* hijack the return address of child */
                *ret_addr = (unsigned long)plthook_return;

It doesn't make uftrace crashed, but it doesn't call bar this time and shows main at the end again.

$ uftrace --estimate-return a.out
[resolve_foo]
[main]
# DURATION     TID     FUNCTION
   0.390 us [ 46900] | __monstartup();
   0.282 us [ 46900] | __cxa_atexit();
   0.441 us [ 46900] | <4004ed>();
   0.656 us [ 46900] | mcount();
            [ 46900] | main() {
   6.101 us [ 46900] |   printf();
   6.869 us [ 46900] | } /* main */
  15.335 us [ 46900] | main();

We may have to specially handle __attribute__ ((ifunc("resolve_foo"))).

[honggyukim]

This problem doesn't happen in aarch64 Ubuntu 20.10.

$ gcc -pg ifunc.c

$ ./a.out
[resolve_foo]
[main]
[bar]

$ uftrace a.out
[resolve_foo]
[main]
[bar]
# DURATION     TID     FUNCTION
            [  2105] | main() {
   1.958 us [  2105] |   bar();
  25.750 us [  2105] | } /* main */

[honggyukim]

The above is tested after applying the workaround done in #1248.

diff --git a/arch/aarch64/mcount-arch.h b/arch/aarch64/mcount-arch.h
index 69efe521..60c2c1ba 100644
--- a/arch/aarch64/mcount-arch.h
+++ b/arch/aarch64/mcount-arch.h
@@ -31,7 +31,7 @@ struct mcount_arch_context {
        double d[ARCH_MAX_FLOAT_REGS];
 };

-#define ARCH_PLT0_SIZE  32
+#define ARCH_PLT0_SIZE  16
 #define ARCH_PLTHOOK_ADDR_OFFSET  0

 struct mcount_disasm_engine;

I also need to test it again in aarch64 Ubuntu 20.04.

[claudiubalogh]

I had the chance to test this again on OpenSuse 15.3:

> cat /etc/SUSE-brand
openSUSE
VERSION = 15.3

> uftrace --version
uftrace v0.14-7-gc7c58 ( x86_64 dwarf tui perf sched )

> gcc --version
gcc (SUSE Linux) 7.5.0

> uftrace -e a.out
[resolve_foo]
WARN: Segmentation fault: address not mapped (addr: 0x9)
WARN: Backtrace from uftrace v0.14-7-gc7c58 ( x86_64 dwarf tui perf sched )
WARN: =====================================
WARN: [0] (__cxa_atexit[400520] <= <4004da>[4004da])

Please report this bug to https://github.com/namhyung/uftrace/issues.

WARN: child terminated by signal: 11: Segmentation fault
# DURATION     TID     FUNCTION
   0.508 us [ 10628] | __monstartup();
   0.203 us [ 10628] | __cxa_atexit();
   0.203 us [ 10628] | } /* __cxa_atexit */

This bug seems to have been reported already: #1566