ustack missing stack frame second from top

[danobi]

$ sudo ./build/src/bpftrace -e 'uprobe:/lib64/libc.so.6:usleep { printf("%s\n", ustack); @[ustack(1)] = count();
 }'                                                                                                                                          
Attaching 1 probe...                                                                                                                         
                                                                                                                                             
        usleep+0                                                                                                                             
        pathBBBB()+9                                                                                                                         
        pathBBB()+9                                                                                                                          
        pathBB()+9                                                                                                                           
        pathB()+9                                                                                                                            
        main+48                                                                                                                              
        __libc_start_main+235                                                                                                                
        0x41fd89415541f689                                                                                                                   
                                                                                                                                             
                                                                                                                                             
        usleep+0                                                                                                                             
        pathAAAA()+9                                                                                                                         
        pathAAA()+9                                                                                                                          
        pathAA()+9                                                                                                                           
        pathA()+9                                                                                                                            
        main+41                                                                                                                              
        __libc_start_main+235                                                                                                                
        0x41fd89415541f689                                                                                                                   
                                                                                                                                             
^C                                                                                                                                           
                                                                                                                                             
@[                                                                                                                                           
    usleep+0
]: 2

$ cat ~/scratch/memcpy/main.cpp
#include <iostream>
#include <unistd.h>
#include <stdio.h>

__attribute__((noinline)) void do_sleep() {
  ::usleep(100000);
}

__attribute__((noinline)) void pathAAAA() {
  do_sleep();
}

__attribute__((noinline)) void pathAAA() {
  pathAAAA();
}

__attribute__((noinline)) void pathAA() {
  pathAAA();
}

__attribute__((noinline)) void pathA() {
  pathAA();
}

__attribute__((noinline)) void pathBBBB() {
  do_sleep();
}

__attribute__((noinline)) void pathBBB() {
  pathBBBB();
}

__attribute__((noinline)) void pathBB() {
  pathBBB();
}

__attribute__((noinline)) void pathB() {
  pathBB();
}

int main() {
  int i = 0;
  while (1) {
    if (i++ % 2) {
      pathA();
    } else {
      pathB();
    }
  }
}

Notice how do_sleep is missing in both stack traces.

[brendangregg]

Interesting. What does perf record show?

perf probe -x /lib64/libc.so.6 usleep
perf record -e probe_libc:usleep -a -g
perf script

[brendangregg]

Doing a manual stack walk, I can see that do_sleep() is not there:

# bpftrace -e 'uprobe:/lib/x86_64-linux-gnu/libc-2.27.so:usleep {
    printf("%s %s\n", usym(*(reg("bp") + 8)), ustack) }'
[...]
pathBBBB() 
        usleep+0
        pathBBBB()+9
        pathBBB()+9
        pathBB()+9
        pathB()+9
        main+48
        __libc_start_main+231
        0x4e6258d4c544155

perf doesn't see it either:

# perf record -e probe_libc:usleep -a -g
# perf script
[...]
sleeptest 23279 [002] 537827.906777: probe_libc:usleep: (7fb3df046820)
                  117820 usleep (/lib/x86_64-linux-gnu/libc-2.27.so)
                     7a4 pathAAAA (/home/bgregg/Lang/c/sleeptest)
                     7b0 pathAAA (/home/bgregg/Lang/c/sleeptest)
                     7bc pathAA (/home/bgregg/Lang/c/sleeptest)
                     7c8 pathA (/home/bgregg/Lang/c/sleeptest)
                     824 main (/home/bgregg/Lang/c/sleeptest)
                   21b97 __libc_start_main (/lib/x86_64-linux-gnu/libc-2.27.so)
         4e6258d4c544155 [unknown] ([unknown])

but perf does see it with DWARF:

# perf record -e probe_libc:usleep --call-graph dwarf -a
# perf script
sleeptest 23424 [007] 538023.530135: probe_libc:usleep: (7f655eda8820)
                  117820 usleep (/lib/x86_64-linux-gnu/libc-2.27.so)
                     797 do_sleep (/home/bgregg/Lang/c/sleeptest)
                     7a3 pathAAAA (/home/bgregg/Lang/c/sleeptest)
                     7af pathAAA (/home/bgregg/Lang/c/sleeptest)
                     7bb pathAA (/home/bgregg/Lang/c/sleeptest)
                     7c7 pathA (/home/bgregg/Lang/c/sleeptest)
                     823 main (/home/bgregg/Lang/c/sleeptest)
                   21b96 __libc_start_main (/lib/x86_64-linux-gnu/libc-2.27.so)
                     6a9 _start (/home/bgregg/Lang/c/sleeptest)

Hmmm.. I wouldn't have thought DWARF was necessary in this case. What's going on?

[mmarchini]

It gets weirder:

# ./bpftrace -e 'uprobe:/tmp/temp:*pathAAAA* { printf("%s\n", ustack); @[ustack(1)] = count(); }'                                                                                                                                                                                                                                                                                                                           [15:55:22] 
Attaching 1 probe...                                                                                                                                                                                                                                                                                                                                                                                                                         
                                                                                                                                                                                                                                                                                                                                                                                                                                             
        pathAAAA()+0                                                                                                                                                                                                                                                                                                                                                                                                                         
        pathAA()+9                                                                                                                                                                                                                                                                                                                                                                                                                           
        pathA()+9                                                                                                                                                                                                                                                                                                                                                                                                                            
        main+41                                                                                                                                                                                                                                                                                                                                                                                                                              
        __libc_start_main+231                                                                                                                                                                                                                                                                                                                                                                                                                
        0x4e6258d4c544155                                                                                                                                                                                                                                                                                                                                                                                                                    
                                                                                                                                                                                                                                                                                                                                                                                                                                             
                                                                                                                                                                                                                                                                                                                                                                                                                                             
        pathAAAA()+0
        pathAA()+9
        pathA()+9
        main+41
        __libc_start_main+231
        0x4e6258d4c544155


        pathAAAA()+0
        pathAA()+9
        pathA()+9
        main+41
        __libc_start_main+231
        0x4e6258d4c544155

The stack should be:

        pathAAAA()+0
        pathAAA()+9
        pathAA()+9
        pathA()+9
        main+41
        __libc_start_main+231
        0x4e6258d4c544155

I tried building the program as C instead of C++, got the same result.

Which kernel version are you on? I'm on 4.15.0-47-generic

[ajor]

Reported in BCC as well iovisor/bcc#2555

[danobi]

Ah so here's the reason:

This is because during unwinding, for the first function of func_d, the frame pointer has not been set up, so technically we still in the frame of func_c but address is pointing to the first insn of func_d, after unwinding, it will go to func_b's frame.

[jordalgo]

@danobi Can we close this?

[danobi]

Yeah. Sounds like not too much we can do here. Maybe this is soemthing that should be tracked in blaze-sym?

[ajor]

Reopening: we've got to try and fix all our wrong-results bugs. @ttreyer is working on a solution for this one in #3095