Broken dwarf unwinding - wrong stack pointer register value?

Hey all,

I'm on the quest to figure out why perf regularly fails to unwind (some) samples. I am seeing very strange behavior, where an apparently wrong stack pointer value is read from the register - see below for more information and the end of this (long) mail for my open questions. Any help would be greatly appreciated.

I am currently using this trivial C++ code to reproduce the issue:

```
#include <cmath>
#include <complex>
#include <iostream>
#include <random>

using namespace std;

int main()
{
    uniform_real_distribution<double> uniform(-1E5, 1E5);
    default_random_engine engine;
    double s = 0;
    for (int i = 0; i < 10000000; ++i) {
        s += norm(complex<double>(uniform(engine), uniform(engine)));
    }
    cout << s << '\n';
    return 0;
}
```

I compile it with g++ -O2 -g and then record it with perf record --call- graph dwarf. Using perf script, I then see e.g.:

```
$ perf script -v --no-inline --time 90229.12668,90229.127158 --ns
...
# first frame (working unwinding from __hypot_finite):
unwind: reg 16, val 7faf7dca2696
unwind: reg 7, val 7ffc80811ca0
unwind: find_proc_info dso /usr/lib/libm-2.28.so
unwind: access_mem addr 0x7ffc80811ce8 val 7faf7dc88af9, offset 72
unwind: find_proc_info dso /usr/lib/libm-2.28.so
unwind: access_mem addr 0x7ffc80811d08 val 56382b0fc129, offset 104
unwind: find_proc_info dso /home/milian/projects/kdab/rnd/hotspot/build/tests/
test-clients/cpp-inlining/cpp-inlining
unwind: access_mem addr 0x7ffc80811d58 val 7faf7dabf223, offset 184
unwind: find_proc_info dso /usr/lib/libc-2.28.so
unwind: access_mem addr 0x7ffc80811e18 val 56382b0fc1ee, offset 376
unwind: find_proc_info dso /home/milian/projects/kdab/rnd/hotspot/build/tests/
test-clients/cpp-inlining/cpp-inlining
unwind: __hypot_finite:ip = 0x7faf7dca2696 (0x29696)
unwind: hypotf32x:ip = 0x7faf7dc88af8 (0xfaf8)
unwind: main:ip = 0x56382b0fc128 (0x1128)
unwind: __libc_start_main:ip = 0x7faf7dabf222 (0x24222)
unwind: _start:ip = 0x56382b0fc1ed (0x11ed)
# second frame (unrelated)
unwind: reg 16, val 56382b0fc114
unwind: reg 7, val 7ffc80811d10
unwind: find_proc_info dso /home/milian/projects/kdab/rnd/hotspot/build/tests/
test-clients/cpp-inlining/cpp-inlining
unwind: access_mem addr 0x7ffc80811d58 val 7faf7dabf223, offset 72
unwind: access_mem addr 0x7ffc80811e18 val 56382b0fc1ee, offset 264
unwind: main:ip = 0x56382b0fc114 (0x1114)
unwind: __libc_start_main:ip = 0x7faf7dabf222 (0x24222)
unwind: _start:ip = 0x56382b0fc1ed (0x11ed)
# third frame (broken unwinding from __hypot_finite)
unwind: reg 16, val 7faf7dca2688
unwind: reg 7, val 7ffc80811ca0
unwind: find_proc_info dso /usr/lib/libm-2.28.so
unwind: access_mem addr 0x7ffc80811cc0 val 0, offset 32
unwind: __hypot_finite:ip = 0x7faf7dca2688 (0x29688)
unwind: '':ip = 0xffffffffffffffff (0x0)
cpp-inlining 24617 90229.126685606:     711026 cycles:uppp: 
	    7faf7dca2696 __hypot_finite+0x36 (/usr/lib/libm-2.28.so)
	    7faf7dc88af8 hypotf32x+0x18 (/usr/lib/libm-2.28.so)
	    56382b0fc128 main+0x88 (/home/milian/projects/kdab/rnd/hotspot/
build/tests/test-clients/cpp-inlining/cpp-inlining)
	    7faf7dabf222 __libc_start_main+0xf2 (/usr/lib/libc-2.28.so)
	    56382b0fc1ed _start+0x2d (/home/milian/projects/kdab/rnd/hotspot/
build/tests/test-clients/cpp-inlining/cpp-inlining)

cpp-inlining 24617 90229.126921551:     714657 cycles:uppp: 
	    56382b0fc114 main+0x74 (/home/milian/projects/kdab/rnd/hotspot/
build/tests/test-clients/cpp-inlining/cpp-inlining)
	    7faf7dabf222 __libc_start_main+0xf2 (/usr/lib/libc-2.28.so)
	    56382b0fc1ed _start+0x2d (/home/milian/projects/kdab/rnd/hotspot/
build/tests/test-clients/cpp-inlining/cpp-inlining)

cpp-inlining 24617 90229.127157818:     719976 cycles:uppp: 
	    7faf7dca2688 __hypot_finite+0x28 (/usr/lib/libm-2.28.so)
	ffffffffffffffff [unknown] ([unknown])
...
```

Now I'm trying to figure out why one __hypot_finite sample works but the other one breaks for no apparent reason. One thing I noticed so far is the following discrepancy in memory accesses, i.e. for the working sample we get:

```
unwind: reg 16, val 7faf7dca2696
unwind: reg 7, val 7ffc80811ca0
unwind: access_mem addr 0x7ffc80811ce8 val 7faf7dc88af9, offset 72
...
```

But the broken sample only produces:

```
unwind: reg 16, val 7faf7dca2688
unwind: reg 7, val 7ffc80811ca0
unwind: find_proc_info dso /usr/lib/libm-2.28.so
unwind: access_mem addr 0x7ffc80811cc0 val 0, offset 32
```

The user stack of the working sample starts with (in hex):

0000000000000000000000009c830441000000000000000000000000000000000000000000000000254a980000000000301d8180fc7f0000c0c10f2b3856000030

The user stack of the broken sample starts with (in hex):

0000000000000000000000002f64fd4000000000000000000000000000000000000000000000000073bb970000000000301d8180fc7f0000c0c10f2b3856000030

This is a 64bit machine, so word width is 8. So both user stacks start with 24 * 2 = 48 words of zeros. Hence offset 32 cannot possibly produce a meaningful value...

This offset is calculcated from LIBUNWIND__ARCH_REG_SP, cf. unwind-libunwind- local.c. So is the stack pointer address in the register wrong? If I hackishly offset the value for the stack pointer by 40, i.e.:

```
diff --git a/tools/perf/util/unwind-libunwind-local.c b/tools/perf/util/
unwind-libunwind-local.c
index 79f521a552cf..a766ddaaa4dd 100644
--- a/tools/perf/util/unwind-libunwind-local.c
+++ b/tools/perf/util/unwind-libunwind-local.c
@@ -502,6 +502,7 @@ static int access_mem(unw_addr_space_t __maybe_unused as,
 	if (ret)
 		return ret;
 
+	start -= 40;
 	end = start + stack->size;
 
 	/* Check overflow. */
```

Then I can successfully unwind the broken sample:

```
$ perf script -v --no-inline --time 90229.127156,90229.127158 --ns
...
unwind: reg 16, val 7faf7dca2688
unwind: reg 7, val 7ffc80811ca0
unwind: find_proc_info dso /usr/lib/libm-2.28.so
unwind: access_mem addr 0x7ffc80811cc0 val 7faf7dc88af9, offset 72
unwind: find_proc_info dso /usr/lib/libm-2.28.so
unwind: access_mem addr 0x7ffc80811ce0 val 56382b0fc129, offset 104
unwind: find_proc_info dso /home/milian/projects/kdab/rnd/hotspot/build/tests/
test-clients/cpp-inlining/cpp-inlining
unwind: access_mem addr 0x7ffc80811d30 val 7faf7dabf223, offset 184
unwind: find_proc_info dso /usr/lib/libc-2.28.so
unwind: access_mem addr 0x7ffc80811df0 val 56382b0fc1ee, offset 376
unwind: find_proc_info dso /home/milian/projects/kdab/rnd/hotspot/build/tests/
test-clients/cpp-inlining/cpp-inlining
unwind: __hypot_finite:ip = 0x7faf7dca2688 (0x29688)
unwind: hypotf32x:ip = 0x7faf7dc88af8 (0xfaf8)
unwind: main:ip = 0x56382b0fc128 (0x1128)
unwind: __libc_start_main:ip = 0x7faf7dabf222 (0x24222)
unwind: _start:ip = 0x56382b0fc1ed (0x11ed)
cpp-inlining 24617 90229.127157818:     719976 cycles:uppp: 
	    7faf7dca2688 __hypot_finite+0x28 (/usr/lib/libm-2.28.so)
	    7faf7dc88af8 hypotf32x+0x18 (/usr/lib/libm-2.28.so)
	    56382b0fc128 main+0x88 (/home/milian/projects/kdab/rnd/hotspot/
build/tests/test-clients/cpp-inlining/cpp-inlining)
	    7faf7dabf222 __libc_start_main+0xf2 (/usr/lib/libc-2.28.so)
	    56382b0fc1ed _start+0x2d (/home/milian/projects/kdab/rnd/hotspot/
build/tests/test-clients/cpp-inlining/cpp-inlining)

```

So, what now? Here are my open questions:

Is this just working now by chance, or is this the real reason? I.e. is the register value for the stack pointer incorrectly recorded?

Can this be fixed somehow during record time?

Can we detect this scenario at analysis time and correct the stack pointer address automatically somehow? Should the first frame always try to read from offset 72 maybe?

Any help would be greatly appreciated, many thanks

Milian Wolff
[email protected]
http://milianw.de

With my patch to regularly flush the perf script output buffer, we can now easily find all broken backtraces and the corresponding debug output via:

    $ perf script --ns -v |& awk -v RS='' '/\[unknown\]/ {print "\n"$0}'

I've pasted the output to the above command from my machine here:
https://paste.kde.org/pmyxwkk1k

This contains 139 samples with broken unwinding, out of 2350 samples in total, so about 6% of all samples are broken.

In many cases, the first accessed memory is 0 because a too-low offset into the stack is computed from the SP value, similar to the scenario I described in my initial mail. In other cases we read garbadge addresses such as

unwind: access_mem addr 0x7ffc80811cf0 val 408195dfbda90580, offset 24

In all cases except for the the two samples at the very start and end of this log, the last offset encountered in access_mem is lower than 72. Remember what I wrote in the initial mail - if I manually hack the access_mem function to use 72 for one of the broken samples, it made unwinding magically work again...

With this addition of data - can anyone sched some light on what's potentially going on here? How can we improve this situation?

Thanks

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

I've now collected some more background information, which is quite helpful I believe for the analysis of this issue:

Note how the broken sample has the IP pointing at __hypot_finite+0x28:

unwind: __hypot_finite:ip = 0x7faf7dca2688 (0x29688)

When we run my reproducer code in GDB, we can see that obtaining a backtrace from that address works just fine there:

```
$ gdb ./cpp-inlining
GNU gdb (GDB) 8.2
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./cpp-inlining...done.
(gdb) break main
Breakpoint 1 at 0x10a0: file /home/milian/projects/kdab/rnd/hotspot/tests/
test-clients/cpp-inlining/main.cpp, line 34.
(gdb) run
Starting program: /home/milian/projects/kdab/rnd/hotspot/build/tests/test-
clients/cpp-inlining/cpp-inlining 

Breakpoint 1, main () at /home/milian/projects/kdab/rnd/hotspot/tests/test-
clients/cpp-inlining/main.cpp:34
34      {
(gdb) disassemble __hypot_finite 
Dump of assembler code for function __hypot_finite:
   0x00007ffff7c96660 <+0>:     endbr64 
   0x00007ffff7c96664 <+4>:     push   %r13
   0x00007ffff7c96666 <+6>:     push   %r12
   0x00007ffff7c96668 <+8>:     push   %rbp
   0x00007ffff7c96669 <+9>:     movq   %xmm1,%rbp
   0x00007ffff7c9666e <+14>:    push   %rbx
   0x00007ffff7c9666f <+15>:    movq   %xmm0,%rbx
   0x00007ffff7c96674 <+20>:    shr    $0x20,%rbp
   0x00007ffff7c96678 <+24>:    shr    $0x20,%rbx
   0x00007ffff7c9667c <+28>:    and    $0x7fffffff,%ebp
   0x00007ffff7c96682 <+34>:    and    $0x7fffffff,%ebx
   0x00007ffff7c96688 <+40>:    sub    $0x28,%rsp
   0x00007ffff7c9668c <+44>:    cmp    %ebp,%ebx
   0x00007ffff7c9668e <+46>:    jge    0x7ffff7c966a2 <__hypot_finite+66>
   0x00007ffff7c96690 <+48>:    mov    %ebx,%eax
   0x00007ffff7c96692 <+50>:    movapd %xmm0,%xmm2
   0x00007ffff7c96696 <+54>:    movapd %xmm1,%xmm0
   0x00007ffff7c9669a <+58>:    mov    %ebp,%ebx
   0x00007ffff7c9669c <+60>:    movapd %xmm2,%xmm1
   0x00007ffff7c966a0 <+64>:    mov    %eax,%ebp
   0x00007ffff7c966a2 <+66>:    movq   %xmm0,%r13
   0x00007ffff7c966a7 <+71>:    mov    %rbx,%rax
   0x00007ffff7c966aa <+74>:    movq   %xmm1,%r12
--Type <RET> for more, q to quit, c to continue without paging--q
Quit
(gdb) break *0x00007ffff7c96688
Breakpoint 2 at 0x7ffff7c96688
(gdb) cont
Continuing.

Breakpoint 2, 0x00007ffff7c96688 in __hypot_finite () from /usr/lib/libm.so.6
(gdb) bt
#0  0x00007ffff7c96688 in __hypot_finite () from /usr/lib/libm.so.6
#1  0x00007ffff7c7caf9 in hypotf64 () from /usr/lib/libm.so.6
#2  0x0000555555555129 in std::__complex_abs (__z=<optimized out>) at /usr/
include/c++/8.2.1/complex:1362
#3  std::abs<double> (__z=...) at /usr/include/c++/8.2.1/complex:618
#4  std::_Norm_helper<true>::_S_do_it<double> (__z=...) at /usr/include/c++/
8.2.1/complex:675
#5  std::norm<double> (__z=...) at /usr/include/c++/8.2.1/complex:685
#6  main () at /home/milian/projects/kdab/rnd/hotspot/tests/test-clients/cpp-
inlining/main.cpp:39
```

But note how __hypot_finite+0x28 actually points at an instruction that modifies the stack pointer by 40, just like I did manually to "fix" unwinding for this sample (see my initial email):

0x00007ffff7c96688 <+40>: sub $0x28,%rsp

So we are still in the function prologue, and can't properly unwind from there apparently! Any suggestions on how this should be handled? Can we figure out the size of the function prologue somehow and manually fix the stack pointer then?

Cheers

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

After more digging, it turns out that I've apparently chased a red herring. I'm running archlinux which isn't shipping debug symbols for libm. Without those, we are apparently out of luck to unwind from the function prologue.

I still wonder whether we could catch this somehow and handle it ourselves. I wonder what GDB does to unwind here, despite the lack of debug information in libm...

Cheers

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

64bit executables normally have unwind information even when stripped. Unless someone forcefully stripped those too.

You can checkout with objdump --sections.

-Andi

Right, we do have .eh_frame and .eh_frame_hdr according to readelf:

```
$ readelf  --sections /usr/lib/libm.so.6        
There are 26 section headers, starting at offset 0x183120:

Section Headers:
  [Nr] Name              Type             Address           Offset
       Size              EntSize          Flags  Link  Info  Align
  [ 0]                   NULL             0000000000000000  00000000
       0000000000000000  0000000000000000           0     0     0
  [ 1] .note.gnu.build-i NOTE             0000000000000270  00000270
       0000000000000024  0000000000000000   A       0     0     4
  [ 2] .note.ABI-tag     NOTE             0000000000000294  00000294
       0000000000000020  0000000000000000   A       0     0     4
  [ 3] .note.gnu.propert NOTE             00000000000002b8  000002b8
       0000000000000020  0000000000000000   A       0     0     8
  [ 4] .gnu.hash         GNU_HASH         00000000000002d8  000002d8
       00000000000024d0  0000000000000000   A       5     0     8
  [ 5] .dynsym           DYNSYM           00000000000027a8  000027a8
       00000000000066c0  0000000000000018   A       6     1     8
  [ 6] .dynstr           STRTAB           0000000000008e68  00008e68
       0000000000002352  0000000000000000   A       0     0     1
  [ 7] .gnu.version      VERSYM           000000000000b1ba  0000b1ba
       0000000000000890  0000000000000002   A       5     0     2
  [ 8] .gnu.version_d    VERDEF           000000000000ba50  0000ba50
       000000000000017c  0000000000000000   A       6    11     8
  [ 9] .gnu.version_r    VERNEED          000000000000bbd0  0000bbd0
       0000000000000060  0000000000000000   A       6     2     8
  [10] .rela.dyn         RELA             000000000000bc30  0000bc30
       0000000000000480  0000000000000018   A       5     0     8
  [11] .init             PROGBITS         000000000000d000  0000d000
       000000000000001b  0000000000000000  AX       0     0     4
  [12] .text             PROGBITS         000000000000d020  0000d020
       00000000000a063b  0000000000000000  AX       0     0     16
  [13] .fini             PROGBITS         00000000000ad65c  000ad65c
       000000000000000d  0000000000000000  AX       0     0     4
  [14] .rodata           PROGBITS         00000000000ae000  000ae000
       00000000000c76a4  0000000000000000   A       0     0     32
  [15] .eh_frame_hdr     PROGBITS         00000000001756a4  001756a4
       0000000000001c34  0000000000000000   A       0     0     4
  [16] .eh_frame         PROGBITS         00000000001772d8  001772d8
       00000000000093f0  0000000000000000   A       0     0     8
  [17] .hash             HASH             00000000001806c8  001806c8
       000000000000210c  0000000000000004   A       5     0     8
  [18] .init_array       INIT_ARRAY       0000000000183c80  00182c80
       0000000000000008  0000000000000008  WA       0     0     8
  [19] .fini_array       FINI_ARRAY       0000000000183c88  00182c88
       0000000000000008  0000000000000008  WA       0     0     8
  [20] .dynamic          DYNAMIC          0000000000183c90  00182c90
       00000000000001f0  0000000000000010  WA       6     0     8
  [21] .got              PROGBITS         0000000000183e80  00182e80
       0000000000000180  0000000000000008  WA       0     0     8
  [22] .data             PROGBITS         0000000000184000  00183000
       000000000000000c  0000000000000000  WA       0     0     8
  [23] .bss              NOBITS           000000000018400c  0018300c
       000000000000000c  0000000000000000  WA       0     0     4
  [24] .comment          PROGBITS         0000000000000000  0018300c
       000000000000001a  0000000000000001  MS       0     0     1
  [25] .shstrtab         STRTAB           0000000000000000  00183026
       00000000000000fa  0000000000000000           0     0     1
Key to Flags:
  W (write), A (alloc), X (execute), M (merge), S (strings), I (info),
  L (link order), O (extra OS processing required), G (group), T (TLS),
  C (compressed), x (unknown), o (OS specific), E (exclude),
  l (large), p (processor specific)
```

But should that be enough information to be able to unwind from a function prologue? I mean, it obviously seems to work when we unwind from the function body. But how would I know whether it should work from the prologue too?

Reading e.g. https://www.airs.com/blog/archives/460, I can find:

executed when an exception occurs. By default an exception can only occur during a function call or a throw. When using the -fnon-call-exceptions gcc option, an exception can also occur on most memory references and floating point operations. When using -fasynchronous-unwind-tables, the FDE will cover every instruction, to permit unwinding from a signal handler.

So what if my libm wasn't compiled with -fasynchronous-unwind-tables? We probably cannot throw an exception in the function prologue, so potentially that range is simply not mapped? But this is just a shot in the dark, I have no clue how to get more information about what contents are actually stored in the .eh_frame section. I would love to find out though! Does anyone know a tool to sched some light into this section?

I found http://www.bitlackeys.org/#eh_frame which at least shows me that __hypot_finite is mentioned in the .eh_frame section:

$ nm -aD /usr/lib/libm.so.6 |& grep hypot_finite
0000000000029660 T __hypot_finite
$ ./eh_frame /usr/lib/libm.so.6 |& grep 29660
Function size: 878 Function Addr: 29660

Thanks

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

It's default (64bit since always and 32bit now too) Unless someone disabled it.

However libm might be partially written in assembler and hand written assembler often has problems with unwind tables because the programmer has to get them correct explicitely.

-Andi

Excellent, good to know. Since [1] doesn't explicitly disable it, I would assume the information should be available.

[1]: https://git.archlinux.org/svntogit/packages.git/tree/trunk/PKGBUILD?
h=packages/glibc

Yes, that could be the case. I'm unsure about the glibc build system and what actually gets compiled, but I found a potential source at [2]:

[2]: https://github.com/bminor/glibc/blob/
43b1048ab9418e902aac8c834a7a9a88c501620a/sysdeps/ieee754/dbl-64/e_hypot.c

I believe this is what is used on my system, since I can spot calls to __issignaling@@GLIBC_2.18 etc. in the disassembly of __hypot_finite ([3]), which matches the sources referenced in [2].

[3]: https://paste.kde.org/poywa7y2z

If [2] is used, then it's not hand written assembler but code compiled by the compiler. So unwinding should work, even from the prologue?

I have since also figured out how to dump the .eh_frame contents in a human readable format via readelf. Remember, __hypot_finite on my system is at offset 0x29660 of libm, so I think the following are the corresponding .eh_frame contents:

```
$ readelf --debug-dump=frames /usr/lib/libm.so.6 |& less
...
00002b60 000000000000004c 00002b64 FDE cie=00000000 
pc=0000000000029660..00000000000299ce
  DW_CFA_advance_loc: 6 to 0000000000029666
  DW_CFA_def_cfa_offset: 16
  DW_CFA_offset: r13 (r13) at cfa-16
  DW_CFA_advance_loc: 2 to 0000000000029668
  DW_CFA_def_cfa_offset: 24
  DW_CFA_offset: r12 (r12) at cfa-24
  DW_CFA_advance_loc: 1 to 0000000000029669
  DW_CFA_def_cfa_offset: 32
  DW_CFA_offset: r6 (rbp) at cfa-32
  DW_CFA_advance_loc: 6 to 000000000002966f
  DW_CFA_def_cfa_offset: 40
  DW_CFA_offset: r3 (rbx) at cfa-40
  DW_CFA_advance_loc: 29 to 000000000002968c
  DW_CFA_def_cfa_offset: 80
  DW_CFA_advance_loc2: 291 to 00000000000297af
  DW_CFA_remember_state
  DW_CFA_def_cfa_offset: 40
  DW_CFA_advance_loc: 5 to 00000000000297b4
  DW_CFA_def_cfa_offset: 32
  DW_CFA_advance_loc: 1 to 00000000000297b5
  DW_CFA_def_cfa_offset: 24
  DW_CFA_advance_loc: 2 to 00000000000297b7
  DW_CFA_def_cfa_offset: 16
  DW_CFA_advance_loc: 2 to 00000000000297b9
  DW_CFA_def_cfa_offset: 8
  DW_CFA_advance_loc: 7 to 00000000000297c0
  DW_CFA_restore_state
  DW_CFA_advance_loc1: 88 to 0000000000029818
  DW_CFA_remember_state
  DW_CFA_def_cfa_offset: 40
  DW_CFA_advance_loc: 1 to 0000000000029819
  DW_CFA_def_cfa_offset: 32
  DW_CFA_advance_loc: 1 to 000000000002981a
  DW_CFA_def_cfa_offset: 24
  DW_CFA_advance_loc: 2 to 000000000002981c
  DW_CFA_def_cfa_offset: 16
  DW_CFA_advance_loc: 2 to 000000000002981e
  DW_CFA_def_cfa_offset: 8
  DW_CFA_advance_loc: 18 to 0000000000029830
  DW_CFA_restore_state
  DW_CFA_nop
```

I notice that this does not touch the rsp register at all, even though it's mutated by the code, leading to the issue. See again this paste for the disassembly at [3], and note that the broken sample frame points at

0x0000000000029688 <+40>: sub $0x28,%rsp

Can someone at least confirm whether unwinding from a function prologue via .eh_frame (but without .debug_frame) should actually be possible?

Thanks

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

Yes it should be possible. Asynchronous unwind tables should work from any instruction.

-Andi

I'm still trying to figure out what's going on here... I have remembered, that libunwind has a quite helpful debug mode, which I further extended to generate a more detailed report of the failed unwinding attempt. For one of the broken samples, I see:

```
$ UNW_DEBUG_LEVEL=15 perf script -v
...
cpp-inlining 30227 18486.357148:     788066 cycles:ppp:  
>_Ux86_64_init_remote: (cursor=0x7fffafa55c10)
unwind: reg 16, val 7f91345d77b4
unwind: reg 7, val 7ffd1e276f18
 >_Ux86_64_step: (cursor=0x7fffafa55c10, ip=0x00007f91345d77b4, 
cfa=0x00007ffd1e276f18)
unwind: find_proc_info dso /usr/lib/libm-2.28.so
               >_Ux86_64_dwarf_search_unwind_table: ip=0x7f91345d77b4, 
start_ip=0xffffffffffeb3fbc
 >_Ux86_64_dwarf_search_unwind_table: e->fde_offset = 4794, segbase = 
7f91347236a4, debug_frame_base = 0, fde_addr = 7f9134727e38
            >_Ux86_64_dwarf_extract_proc_info_from_fde: FDE @ 0x7f9134727e38
               >_Ux86_64_dwarf_extract_proc_info_from_fde: looking for CIE at 
address 7f91347252d8
               >parse_cie: CIE parsed OK, augmentation = "zR", handler=0x0
               >_Ux86_64_dwarf_extract_proc_info_from_fde: FDE covers IP 
0x7f91345d7660-0x7f91345d79ce, LSDA=0x0
     >_Ux86_64_fetch_frame: fetch frame ip=0x7f91345d77b4 cfa=0x7ffd1e276f18 
format=0
               >run_cfi_program: CFA_def_cfa r7+0x8
               >run_cfi_program: CFA_offset r16 at cfa+0xfffffffffffffff8
               >run_cfi_program: CFA_advance_loc to 0x7f91345d7666
               >run_cfi_program: CFA_def_cfa_offset 0x10
               >run_cfi_program: CFA_offset r13 at cfa+0xfffffffffffffff0
               >run_cfi_program: CFA_advance_loc to 0x7f91345d7668
               >run_cfi_program: CFA_def_cfa_offset 0x18
               >run_cfi_program: CFA_offset r12 at cfa+0xffffffffffffffe8
               >run_cfi_program: CFA_advance_loc to 0x7f91345d7669
               >run_cfi_program: CFA_def_cfa_offset 0x20
               >run_cfi_program: CFA_offset r6 at cfa+0xffffffffffffffe0
               >run_cfi_program: CFA_advance_loc to 0x7f91345d766f
               >run_cfi_program: CFA_def_cfa_offset 0x28
               >run_cfi_program: CFA_offset r3 at cfa+0xffffffffffffffd8
               >run_cfi_program: CFA_advance_loc to 0x7f91345d768c
               >run_cfi_program: CFA_def_cfa_offset 0x50
               >run_cfi_program: CFA_advance_loc2 to 0x7f91345d77af
               >run_cfi_program: CFA_remember_state
               >run_cfi_program: CFA_def_cfa_offset 0x28
               >run_cfi_program: CFA_advance_loc to 0x7f91345d77b4
               >run_cfi_program: CFA_def_cfa_offset 0x20
               >run_cfi_program: CFA_advance_loc to 0x7f91345d77b5
     >_Ux86_64_cache_frame: cache frame ip=0x7f91345d77b4 cfa=0x7ffd1e276f18 
format=0
     >_Ux86_64_reuse_frame: reuse frame ip=0x7f91345d77b4 cfa=0x7ffd1e276f18 
format=0 addr=0x0 offset=+0
               >apply_reg_state: CFA_REG_COLUMN[17] = 0x7, 
DWARF_CFA_OFF_COLUMN[18] = 0x20
               >apply_reg_state: CFA = 0x7ffd1e276f18 (pop) + 0x20 = 
0x7ffd1e276f38
               >apply_reg_state: 0: DWARF_WHERE_SAME = (0, 2)
               >apply_reg_state: 1: DWARF_WHERE_SAME = (1, 2)
               >apply_reg_state: 2: DWARF_WHERE_SAME = (2, 2)
               >apply_reg_state: 3: DWARF_WHERE_CFAREL = 7ffd1e276f38 + -40 = 
(7ffd1e276f10, 0)
               >apply_reg_state: 4: DWARF_WHERE_SAME = (4, 2)
               >apply_reg_state: 5: DWARF_WHERE_SAME = (5, 2)
               >apply_reg_state: 6: DWARF_WHERE_CFAREL = 7ffd1e276f38 + -32 = 
(7ffd1e276f18, 0)
               >apply_reg_state: 7: DWARF_WHERE_SAME = (7, 2)
               >apply_reg_state: 8: DWARF_WHERE_SAME = (8, 2)
               >apply_reg_state: 9: DWARF_WHERE_SAME = (9, 2)
               >apply_reg_state: 10: DWARF_WHERE_SAME = (a, 2)
               >apply_reg_state: 11: DWARF_WHERE_SAME = (b, 2)
               >apply_reg_state: 12: DWARF_WHERE_CFAREL = 7ffd1e276f38 + -24 = 
(7ffd1e276f20, 0)
               >apply_reg_state: 13: DWARF_WHERE_CFAREL = 7ffd1e276f38 + -16 = 
(7ffd1e276f28, 0)
               >apply_reg_state: 14: DWARF_WHERE_SAME = (e, 2)
               >apply_reg_state: 15: DWARF_WHERE_SAME = (f, 2)
               >apply_reg_state: 16: DWARF_WHERE_CFAREL = 7ffd1e276f38 + -8 = 
(7ffd1e276f30, 0)
unwind: access_mem addr 0x7ffd1e276f30 val c0d885722245b5e4, offset 24
               >apply_reg_state: ret_addr_column: 16, ip: c0d885722245b5e4
               >_Ux86_64_step: dwarf_step returned 1
  >_Ux86_64_step: returning 1
 >_Ux86_64_step: (cursor=0x7fffafa55c10, ip=0xc0d885722245b5e4, 
cfa=0x00007ffd1e276f38)
               >_Ux86_64_step: dwarf_step returned -22
  >_Ux86_64_step: returning -22
unwind: __hypot_finite:ip = 0x7f91345d77b4 (0x297b4)
unwind: '':ip = 0xc0d885722245b5e3 (0x0)

            7f91345d77b4 __hypot_finite+0x154 (/usr/lib/libm-2.28.so)
        c0d885722245b5e3 [unknown] ([unknown])
```

Now, I also tried the following:

```
$ perf probe -x /usr/lib/libm-2.28.so -a __hypot_finite+0x154
$ perf record -F 1000 --call-graph dwarf -e probe_libm:__hypot_finite ./cpp-
inlining
```

And all of the samples unwind correctly! This makes me believe that it's not the .eh_frame information which is wrong - otherwise unwinding would always fail from these locations, esp. when using the custom probe trace point. But since this is not happening, what else could it be? I only see two
possibilities: the register values or the stack memory stored in in the sample by perf.

The register values is unlikely, since I now understand how the .eh_frame contents get analyzed. For __hypot_finite+0x154, we will always end up asking for the address at SP+24. access_mem thus will always look at the address at offset 24, independent of the actual value of SP.

So, what remains is that the stack dump is somehow wrong, i.e. its contents are moved by some offset. Note how I can "fix" the unwinding for such broken samples by manually applying some offset in access_mem. By looking at other samples where unwinding works from __hypot_finite, I could figure out that the correct address to be read for unwnding should be 7f91345bdaf8, e.g.:

```
            7f91345d76ed __hypot_finite+0x8d (/usr/lib/libm-2.28.so)
            7f91345bdaf8 hypotf32x+0x18 (/usr/lib/libm-2.28.so)
            5620579cb128 main+0x88 (/home/milian/projects/kdab/rnd/hotspot/
build/tests/test-clients/cpp-inlining/cpp-inlining)
```

This address indeed occurs in the user stack dump (starting at 0xe0 in the raw event data) for the broken sample, cf.:

```
.  00e0:  00 20 00 00 00 00 00 00 c0 b1 9c 57 20 56 00 00  . .........W V..
.  00f0:  70 70 27 1e fd 7f 00 00 f9 da 5b 34 91 7f 00 00  pp'.......[4....
.  0100:  e4 b5 45 22 72 85 d8 c0 c0 1d 16 84 43 30 bb c0  ..E"r.......C0..
.
```

We can find `7f91345bdaf8+1 = 7f91345bdaf9" at offset 16 (search for "f9 da 5b 34 91 7f"). Using that address makes unwinding work for this sample. What could be the reason for this shift?

Thanks

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

<snip>

I believe I have found the culprit: PEBS seems to be at fault here - i.e. the RIP/RSP and the ustack dump of the sample simply don't fit together.

Check this out:

```
$ for i in $(seq 10); do perf record -q -e "cycles:" --call-graph dwarf ./cpp-
inlining > /dev/null; perf script | pcre2grep -c -M "hypot_finite.*\n.*\
[unknown\]"; done
0
0
0
0
0
0
0
0
0
0

$ for i in $(seq 10); do perf record -q -e "cycles:p" --call-graph dwarf ./
cpp-inlining > /dev/null; perf script | pcre2grep -c -M "hypot_finite.*\n.*\
[unknown\]"; done
0
0
0
0
0
0
0
0
0
0

$ for i in $(seq 10); do perf record -q -e "cycles:pp" --call-graph dwarf ./
cpp-inlining > /dev/null; perf script | pcre2grep -c -M "hypot_finite.*\n.*\
[unknown\]"; done
37
39
35
28
40
39
29
37
31
26

$ for i in $(seq 10); do perf record -q -e "cycles:ppp" --call-graph dwarf ./
cpp-inlining > /dev/null; perf script | pcre2grep -c -M "hypot_finite.*\n.*\
[unknown\]"; done
79
70
76
77
70
90
64
78
86
74
```

Note how precise levels 0 and 1 do not produce any samples where unwinding fails. But precise level 2 produces some, and precise level 3 increases the amount (by ca. ~2x).

I can reproduce this pattern on two separate Intel CPUs and kernel versions currently:

Intel(R) Core(TM) i7-5600U CPU @ 2.60GHz with 4.18.16-arch1-1-ARCH Intel(R) Core(TM) i7-4770 CPU @ 3.40GHz with 4.14.78-1-lts

Could someone else try this? What about AMD and IBS - is it also affected? What about newer/different Intel CPUs?

Better yet, can someone come up with a fix for this on Intel with maximum precise level?

Thanks

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

I tried on intel and can't actualy see that.. how do the failed samples look like? like is there the stack dump attached, what's in the regs?

could you please paste the 'perf report -D' output for some of the failed samples?

thanks,
jirka

See here for one case: https://paste.kde.org/prryvdilq

What Intel CPU did you use? What microcode version? Which kernel version?

Generally, isn't what I'm seeing actually a neccessary evil of the ustack based unwinding in perf? I mean, the general procedure is as follows if I'm not mistaken:

- PMU triggers interrupt and PEBS stores RIP etc.
- code continous to execute, possibly changing the stack
- PMU interrupt is handled, and a perf sample is generated
- register values are used from "past" status stored in PEBS
- but ustack dump is based on the "current" status

From this latter discrepancy, it must directly follow that *sometimes* the ustack dump represents a state that cannot be unwound from, no?

Cheers

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

On Fri, Nov 02, 2018 at 06:56:50PM +0100, Milian Wolff wrote:

SNIP

we should really print some helpfull debug output for this.. like to show some markers where the stack data starts

I dont think the code continues to execute.. the stack is ok

the problem I saw in past is that the copy from user is not 100% and sometimes you might not get full stack data you asked for

have you tried with libdw unwinder? if one of the unwinder shows more callchains, we need to fix the other one ;-)

jirka

Further down below, the offset for the ustack start is given (0xe0). But yes, that would be welcome.

Are you sure about this? I mean, isn't that the whole reason why we need PEBS? Generally, if you are sure about this, can you point me to some documentation on this to allow me to understand it better?

Also, how do you explain the scenario I am seeing, with cycles: and cycles:p not suffering from this issue, but cycles:pp and cycles:ppp leading to broken samples? It _has_ to be PEBS then, no? What else could explain this?

But that would indicate missing data at the end of the ustack dump? In our case, the "problematic" data is always at the start.

Also note the apparent shift in the ustack copy which - in one case - directly correlatates with the code being executed, i.e. from objdump in libm I see:

0x0000000000029688 <+40>: sub $0x28,%rsp
(https://paste.kde.org/poywa7y2z)

The address of the expected parent frame is 7ffff7c7caf8 (hypotf32x+0x18). This can be found at offset 80 in the ustack dump (cf. https://paste.kde.org/
prryvdilq - ("f9 ca c7 f7 ff 7f" is found at 0x130, minus 0xe0 yields 0x50 or 80).

From the libunwind (or libdw) debug output in perf, we see that the unwinder tries to access offset 32 (cf. https://paste.kde.org/prryvdilq#line-610),
which is ofset by 48 from the desired value of 80. This offset is *veroy* close to the value of 40 we see in the libm disassembly for __hypot_function ("$0x28,%rsp"). Is this really just a coincidence?

Yes, I've looked at both unwinders. Both try to access the same values, and both break due to seemingly wrong data being read from the stack. And if you look at my other patches, you may have seen that I've regularly fixed the libdw unwinder to bring it closer to libunwind.

Thanks

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

Milian is right.

There is a execution window from PEBS capturing registers to actually triggering the PMU, and if there is stack manipulation in that window
the PEBS state might be out of sync with the real stack.

The right RIP/RSP to use for the stack unwinding is always the data in the PMI's exception frame on the stack.

Probably would need to modify perf to report those too in addition to the PEBS registers.

Of course it would still mean that the stack unwinding may not exactly match the sample RIP, but at least it should be consistent.

-Andi

hum, is this about having 'large pebs' or there's this window if there's also only single pebs record allowed? which should be case for dwarf unwind

ok, should not be that hard

jirka

With large PEBS today there is never any stack unwind because stack unwinding can be only done from a PMI.

The window happens even with single PEBS. It's related to the CPU being pipelined, so complex events may not happen fully atomically.

-Andi

Where would I look for the source to change here? So far, I only concentrated on the userspace side of perf in tools/perf.

Thanks

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

Kind of similar to

a405bad5ad20 perf/x86: Add Haswell specific transaction flag reporting fdfbbd07e91f perf: Add generic transaction flags

Report the original (not overwritten) regs->ip and regs->sp

-Andi

Thanks a lot Andi! With your help, I have managed to find the exact issue for my scenario. Turns out, it really is "just" the instruction pointer that is wrong. I.e. originally we have IP = 0x7feda32ca68c, but with PEBS we correct that to IP = 7feda32ca688. The SP register value stays the same according to my printk output. Using the original IP value, we can unwind correctly since we point to the correct place in the .eh_frame section. The PEBS IP points to a different position in the .eh_frame section, which is "too early".

That brings up some questions:

- I noticed perf record --intr-regs, but the values recorded in the perf.data file are always the same. I.e. comparing uregs and iregs, I always see the same values printed by perf script. This smells like a bug to me, but so far I haven't figured out why this happens...

- Independently, when I add a custom printk manually in arch/x86/events/ intel/ds.c at the end of setup_pebs_sample_data, then I'm never seeing any differences between SP in iregs/pebs/regs. Shouldn't it also be recorded via PEBS? Or is it just chance that I'm never seeing any difference in setup_pebs_sample_data between iregs->sp and regs->sp?

- Generally, how do we want to handle this bug? If --intr-regs would actually record a different IP than stored in uregs in the perf.data file, then we could use that as a fallback for unwinding, when it fails the first time. Or should we always unwind from that IP? How do we mark the "actual" frame/IP then, if that differs?

Thanks

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

The reason seems to be that perf_event_output only takes one set of registers, which then gets handed down into perf_prepare_sample where it gets sampled. Thus if sample type has both PERF_SAMPLE_REGS_USER and PERF_SAMPLE_REGS_INTR set, then by design both will store the same values for user space samples.

Can we change this, such that perf_event_output also takes a second set of registers (iregs) that get sampled for PERF_SAMPLE_REGS_INTR? I'm very new to real kernel development, what kind of ABI/API stability guarantees exist for something like "perf_event_output"?

The reason here seems to be that the registers stored in "pebs" are essentially the same as iregs for the setup for perf record --call-graph dwarf. The difference is the availability of pebs->real_ip which gets used on my system to fixup the IP. SP stays untouched and is thus only truly valid for the untouched IP (which is discarded currently - see above).

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

Yes you can change it.

That's no API/ABI stability guarantee for kernel internal functions, as long as you change all callers in tree.

-Andi

It will depend on the workload.

I don't think the regs include IP currently? Would need to add it. Then could report everything from the original stack in intr-regs, and this would address that problem.

Yes it might be useful to add some indication to the sample that there is a potential divergence between the backtrace and the IP. Would also need to report that in perf report then.

-Andi

This explains some weird results I was always getting especially when functions were small, including
failed unwindings when using dwarf unwinder.

I guess this problem doesn't occur for LBR unwinding since the LBR records are captured at the same
moment in time as the PEBS record, so reflect the correct branch sequence. Of course, LBR doesn't
always let you unwind fully, right?

What would this fix mean for perf report when you use cycles:pp and cycles:ppp (or any PEBS based events)? The unwinding should generally work, but the IP at the top of that stack (from the PMI) will generally be different than that recorded by PEBS. The tree view and overhead calculations will be based on the captured stacks, I guess - but when I annotate, will the values I see correspond to the PEBS IPs or the PMI IPs?

If someone is using cycles:pp or :ppp they probably care about instruction-level accuracy, so it would be a shame to throw it away.

Actually it happens with LBRs too, but it always gives the backtrace consistently at the PMI trigger point.

Based on PEBS IPs.

It would be a good idea to add a check to perf report that the two IPs are different, and if they differ
add some indicator to the sample. This could be a new sort key, although that would waste some space on the screen, or something else.

It wouldn't be cover all cases, for example if you have recursion on the same function it might report the same IP even though it's a different instance, but I presume that should be rare enough to not be a problem.

-Andi

That's weird - so the LBR records are from the PMI point, but the rest of the PEBS record comes from the PEBS trigger point? Or the LBR isn't part of PEBS at all?

In the case that PEBS events are used, the IP will differ essentially 100% of the time, right? That is, there will always be *some* skid.

Well the main problem I see is that "IP inconsistency" will be the usual case, and it will be hard to resent in a reasonable way in the report. For example, the backtrace-based displays/reports may indicate that 80% of your samples are in function X, but based on the PEBS IP records, only 50% may fall in that function, so you'll always have a weird thing where when you are investigating within the stack-display you might see 1234 samples in a function, but when you annotate only 789 samples are accounted for, or whatever.

I don't think this is 100% solvable, it's mostly an issue of displaying it reasonably and managing expectations.

If the LBR record came from PEBS (as I had thought, but perhaps you are indicating otherwise above), I could imagine a hybrid mode where LBR is used to go back some number of calls and then dwarf or FP or whatever unwinding takes over, because the further down the stack you do the more likely the PEBS trigger point and PMI point are likely to have a consistent stack.

LBR is not part of PEBS, but is collected separately in the PMI handler.

I wouldn't say that. It depends on what the CPU is doing and the IPC of the code.

Also the backtrace inconsistency can only happen if the sample races with function return. If you don't then the backtrace will point to the correct function, even though the unwind IP is different.

For example in the common case where you profile a long loop it is unlikely to happen.

Could collect numbers how often it happens, but it would surprise me if anything complicated is worth it. I would just do the minimum fixes to address the unwinder errors, and perhaps add the "unwind ip differs" indication.

-Andi

I now have a preliminary WIP patch up and running (see attached), which works for my usecase and improves perf noticeably. All traces of "unknown" frames are eradicated, i.e. unwinding now works for 100% of the samples!

There are some remaining open questions on my side:

1) Do we really want to change the API of perf_event_overflow_* and perf_event_output_* and adapt all its users? To me, it seems as if only PEBS and IBS would want to pass distinct register sets for iregs and uregs. All other users of the API would continue to pass the same set. Changing the central API produces a lot of churn for no good reason. Does anyone see an alternative to this?

The only alternative idea I have right now is to temporarily change the sample_type in __intel_pmu_pebs_event before we call perf_event_output / perf_event_overflow. I.e. unset PERF_SAMPLE_REGS_INTR, then sample the regs manually from iregs before calling perf_event_{overflow,output}, then set PERF_SAPMLE_REGS_INTR again. Or we could introduce a custom flag similar to __PERF_SAMPLE_CALLCHAIN_EARLY here...

2) How do we want to do »the "unwind ip differs" indication« as Andi puts it? I.e. on the perf report/script side, how should we display the stacks? Something like the following annotation maybe?

```
cpp-inlining  2605 [-01]    57.870061:     701199 cycles:pppu: 
           7fc1042797b4 __hypot_finite+0x154 (/usr/lib/libm-2.28.so)
           7fc10425faf8 hypotf32x+0x18 (/usr/lib/libm-2.28.so) (unwind ip 
differs)
           5622c7452128 main+0x88 (/tmp/cpp-inlining)
           7fc104096222 __libc_start_main+0xf2 (/usr/lib/libc-2.28.so)
           5622c74521ed _start+0x2d (/tmp/cpp-inlining)
```

3) I suggest we always keep the first frame and sample IP from the user regs, i.e. the accurate PEBS/IBS IP. Then we add the following frames from unwinding the ustack with the iregs. But what do we do with the first iregs IP? If we add it, then we could see the same frame with slightly different IP, like in the following, which is undesired I believe:

```
cpp-inlining  2605 [-01]    57.870061:     701199 cycles:pppu: 
           7fc1042797b4 __hypot_finite+0x154 (/usr/lib/libm-2.28.so)
           7fc1042797b5 __hypot_finite+0x155 (/usr/lib/libm-2.28.so)
           7fc10425faf8 hypotf32x+0x18 (/usr/lib/libm-2.28.so) (unwind ip 
differs)
           5622c7452128 main+0x88 (/tmp/cpp-inlining)
           7fc104096222 __libc_start_main+0xf2 (/usr/lib/libc-2.28.so)
           5622c74521ed _start+0x2d (/tmp/cpp-inlining)
```

But always skipping the IP is also sometimes wrong, like in this case:

```
cpp-inlining  2605 [-01]    57.862313:     694984 cycles:pppu: 
           7fc1042797b9 __hypot_finite+0x159 (/usr/lib/libm-2.28.so)
           5622c7452128 main+0x88 (/tmp/cpp-inlining)
           7fc104096222 __libc_start_main+0xf2 (/usr/lib/libc-2.28.so)
           5622c74521ed _start+0x2d (/tmp/cpp-inlining)
```

Here, we are missing the hypotf32x call inbetween __hypot_finite and main.

Do we want to introduce some heuristic on how handle these scenarios? I.e. if uregs->ip and iregs->ip point to the same function symbol, then skip the frame for iregs->ip, otherwise add it?

Thanks

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

From 422d2a95eff344407ec425f0de55b264841d1757 Mon Sep 17 00:00:00 2001
From: Milian Wolff <[email protected]>
Date: Wed, 14 Nov 2018 14:10:47 +0100
Subject: [PATCH 1/2] [WIP] perf: make it possible to collect both, iregs and
uregs

Previously, only one set of registers was stored in the perf data for both, user and interrupt registers. Now, two distinct sets can be sampled.

---
 arch/x86/events/amd/ibs.c        |  2 +-
 arch/x86/events/core.c           |  2 +-
 arch/x86/events/intel/core.c     |  2 +-
 arch/x86/events/intel/ds.c       |  7 +++----
 arch/x86/events/intel/knc.c      |  2 +-
 arch/x86/events/intel/p4.c       |  2 +-
 arch/x86/kernel/ptrace.c         |  2 +-
 arch/x86/kvm/pmu.c               |  4 ++--
 drivers/oprofile/nmi_timer_int.c |  2 +-
 include/linux/perf_event.h       | 18 +++++++++++------
 kernel/events/core.c             | 34 ++++++++++++++++----------------
 kernel/trace/bpf_trace.c         |  2 +-
 kernel/watchdog_hld.c            |  2 +-
 13 files changed, 43 insertions(+), 38 deletions(-)

index d50bb4dc0650..567db8878511 100644
@@ -670,7 +670,7 @@ static int perf_ibs_handle_irq(struct perf_ibs *perf_ibs, struct pt_regs *iregs)
 		data.raw = &raw;
 	}
 
-	throttle = perf_event_overflow(event, &data, &regs);
+	throttle = perf_event_overflow(event, &data, &regs, iregs);
 out:
 	if (throttle)
 		perf_ibs_stop(event, 0);

index 106911b603bd..acdcafa57ca0 100644
@@ -1493,7 +1493,7 @@ int x86_pmu_handle_irq(struct pt_regs *regs)
 		if (!x86_perf_event_set_period(event))
 			continue;
 
-		if (perf_event_overflow(event, &data, regs))
+		if (perf_event_overflow(event, &data, regs, regs))
 			x86_pmu_stop(event, 0);
 	}
 

index 273c62e81546..2156620b3d9e 100644
@@ -2299,7 +2299,7 @@ static int handle_pmi_common(struct pt_regs *regs, u64 status)
 		if (has_branch_stack(event))
 			data.br_stack = &cpuc->lbr_stack;
 
-		if (perf_event_overflow(event, &data, regs))
+		if (perf_event_overflow(event, &data, regs, regs))
 			x86_pmu_stop(event, 0);
 	}
 

index b7b01d762d32..018fc0649033 100644
@@ -639,7 +639,7 @@ int intel_pmu_drain_bts_buffer(void)
 	 * the sample.
 	 */
 	rcu_read_lock();
-	perf_prepare_sample(&header, &data, event, &regs);
+	perf_prepare_sample(&header, &data, event, &regs, &regs);
 
 	if (perf_output_begin(&handle, event, header.size *
 			      (top - base - skip)))

@@ -1273,7 +1273,6 @@ static void setup_pebs_sample_data(struct perf_event *event,
 		set_linear_ip(regs, pebs->ip);
 	}
 
-
 	if ((sample_type & (PERF_SAMPLE_ADDR | PERF_SAMPLE_PHYS_ADDR)) &&
 	    x86_pmu.intel_cap.pebs_format >= 1)
 		data->addr = pebs->dla;

@@ -1430,7 +1429,7 @@ static void __intel_pmu_pebs_event(struct perf_event *event,
 
 	while (count > 1) {
 		setup_pebs_sample_data(event, iregs, at, &data, &regs);
-		perf_event_output(event, &data, &regs);
+		perf_event_output(event, &data, &regs, iregs);
 		at += x86_pmu.pebs_record_size;
 		at = get_next_pebs_record_by_bit(at, top, bit);
 		count--;

@@ -1442,7 +1441,7 @@ static void __intel_pmu_pebs_event(struct perf_event *event,
 	 * All but the last records are processed.
 	 * The last one is left to be able to call the overflow handler.
 	 */
-	if (perf_event_overflow(event, &data, &regs)) {
+	if (perf_event_overflow(event, &data, &regs, iregs)) {
 		x86_pmu_stop(event, 0);
 		return;
 	}

index 618001c208e8..9ea5a13af83f 100644
@@ -252,7 +252,7 @@ static int knc_pmu_handle_irq(struct pt_regs *regs)
 
 		perf_sample_data_init(&data, 0, event->hw.last_period);
 
-		if (perf_event_overflow(event, &data, regs))
+		if (perf_event_overflow(event, &data, regs, regs))
 			x86_pmu_stop(event, 0);
 	}
 

index d32c0eed38ca..704457b5f49a 100644
@@ -1037,7 +1037,7 @@ static int p4_pmu_handle_irq(struct pt_regs *regs)
 			continue;
 
 
-		if (perf_event_overflow(event, &data, regs))
+		if (perf_event_overflow(event, &data, regs, regs))
 			x86_pmu_stop(event, 0);
 	}
 

index ffae9b9740fd..13b2230e5e9b 100644
@@ -499,7 +499,7 @@ static int genregs_set(struct task_struct *target,
 
 static void ptrace_triggered(struct perf_event *bp,
 			     struct perf_sample_data *data,
-			     struct pt_regs *regs)
+			     struct pt_regs *regs, struct pt_regs *iregs)
 {
 	int i;
 	struct thread_struct *thread = &(current->thread);

index 58ead7db71a3..b556b2d467e1 100644
@@ -57,7 +57,7 @@ static void kvm_pmi_trigger_fn(struct irq_work *irq_work)
 
 static void kvm_perf_overflow(struct perf_event *perf_event,
 			      struct perf_sample_data *data,
-			      struct pt_regs *regs)
+			      struct pt_regs *regs, struct pt_regs *iregs)
 {
 	struct kvm_pmc *pmc = perf_event->overflow_handler_context;
 	struct kvm_pmu *pmu = pmc_to_pmu(pmc);

@@ -71,7 +71,7 @@ static void kvm_perf_overflow(struct perf_event *perf_event,
 
 static void kvm_perf_overflow_intr(struct perf_event *perf_event,
 				   struct perf_sample_data *data,
-				   struct pt_regs *regs)
+				   struct pt_regs *regs, struct pt_regs *iregs)
 {
 	struct kvm_pmc *pmc = perf_event->overflow_handler_context;
 	struct kvm_pmu *pmu = pmc_to_pmu(pmc);

index f343bd96609a..110dfef21420 100644
@@ -28,7 +28,7 @@ static struct perf_event_attr nmi_timer_attr = {
 
 static void nmi_timer_callback(struct perf_event *event,
 			       struct perf_sample_data *data,
-			       struct pt_regs *regs)
+			       struct pt_regs *regs, struct pt_regs *iregs)
 {
 	event->hw.interrupts = 0;       /* don't throttle interrupts */
 	oprofile_add_sample(regs, 0);

index 53c500f0ca79..3a989c64c2c7 100644
@@ -506,7 +506,8 @@ struct perf_sample_data;
 
 typedef void (*perf_overflow_handler_t)(struct perf_event *,
 					struct perf_sample_data *,
-					struct pt_regs *regs);
+					struct pt_regs *regs,
+					struct pt_regs *iregs);
 
 /*
  * Event capabilities. For event_caps and groups caps.

@@ -966,21 +967,26 @@ extern void perf_output_sample(struct perf_output_handle *handle,
 extern void perf_prepare_sample(struct perf_event_header *header,
 				struct perf_sample_data *data,
 				struct perf_event *event,
-				struct pt_regs *regs);
+				struct pt_regs *regs,
+				struct pt_regs *iregs);
 
 extern int perf_event_overflow(struct perf_event *event,
 				 struct perf_sample_data *data,
-				 struct pt_regs *regs);
+				 struct pt_regs *regs,
+				 struct pt_regs *iregs);
 
 extern void perf_event_output_forward(struct perf_event *event,
 				     struct perf_sample_data *data,
-				     struct pt_regs *regs);
+				     struct pt_regs *regs,
+				     struct pt_regs *iregs);
 extern void perf_event_output_backward(struct perf_event *event,
 				       struct perf_sample_data *data,
-				       struct pt_regs *regs);
+				       struct pt_regs *regs,
+				       struct pt_regs *iregs);
 extern void perf_event_output(struct perf_event *event,
 			      struct perf_sample_data *data,
-			      struct pt_regs *regs);
+			      struct pt_regs *regs,
+			      struct pt_regs *iregs);
 
 static inline bool
 is_default_overflow_handler(struct perf_event *event)

index 84530ab358c3..1b57602dc6d8 100644
@@ -6369,7 +6369,7 @@ perf_callchain(struct perf_event *event, struct pt_regs *regs)
 void perf_prepare_sample(struct perf_event_header *header,
 			 struct perf_sample_data *data,
 			 struct perf_event *event,
-			 struct pt_regs *regs)
+			 struct pt_regs *regs, struct pt_regs *iregs)
 {
 	u64 sample_type = event->attr.sample_type;
 

@@ -6474,7 +6474,7 @@ void perf_prepare_sample(struct perf_event_header *header,
 		/* regs dump ABI info */
 		int size = sizeof(u64);
 
-		perf_sample_regs_intr(&data->regs_intr, regs);
+		perf_sample_regs_intr(&data->regs_intr, iregs);
 
 		if (data->regs_intr.regs) {
 			u64 mask = event->attr.sample_regs_intr;

@@ -6492,7 +6492,7 @@ void perf_prepare_sample(struct perf_event_header *header,
 static __always_inline void
 __perf_event_output(struct perf_event *event,
 		    struct perf_sample_data *data,
-		    struct pt_regs *regs,
+		    struct pt_regs *regs, struct pt_regs *iregs,
 		    int (*output_begin)(struct perf_output_handle *,
 					struct perf_event *,
 					unsigned int))

@@ -6503,7 +6503,7 @@ __perf_event_output(struct perf_event *event,
 	/* protect the callchain buffers */
 	rcu_read_lock();
 
-	perf_prepare_sample(&header, data, event, regs);
+	perf_prepare_sample(&header, data, event, regs, iregs);
 
 	if (output_begin(&handle, event, header.size))
 		goto exit;

@@ -6519,25 +6519,25 @@ __perf_event_output(struct perf_event *event,
 void
 perf_event_output_forward(struct perf_event *event,
 			 struct perf_sample_data *data,
-			 struct pt_regs *regs)
+			 struct pt_regs *regs, struct pt_regs *iregs)
 {
-	__perf_event_output(event, data, regs, perf_output_begin_forward);
+	__perf_event_output(event, data, regs, iregs, perf_output_begin_forward);
 }
 
 void
 perf_event_output_backward(struct perf_event *event,
 			   struct perf_sample_data *data,
-			   struct pt_regs *regs)
+			   struct pt_regs *regs, struct pt_regs *iregs)
 {
-	__perf_event_output(event, data, regs, perf_output_begin_backward);
+	__perf_event_output(event, data, regs, iregs, perf_output_begin_backward);
 }
 
 void
 perf_event_output(struct perf_event *event,
 		  struct perf_sample_data *data,
-		  struct pt_regs *regs)
+		  struct pt_regs *regs, struct pt_regs *iregs)
 {
-	__perf_event_output(event, data, regs, perf_output_begin);
+	__perf_event_output(event, data, regs, iregs, perf_output_begin);
 }
 
 /*

@@ -7738,7 +7738,7 @@ int perf_event_account_interrupt(struct perf_event *event)
 
 static int __perf_event_overflow(struct perf_event *event,
 				   int throttle, struct perf_sample_data *data,
-				   struct pt_regs *regs)
+				   struct pt_regs *regs, struct pt_regs *iregs)
 {
 	int events = atomic_read(&event->event_limit);
 	int ret = 0;

@@ -7765,7 +7765,7 @@ static int __perf_event_overflow(struct perf_event *event,
 		perf_event_disable_inatomic(event);
 	}
 
-	READ_ONCE(event->overflow_handler)(event, data, regs);
+	READ_ONCE(event->overflow_handler)(event, data, regs, iregs);
 
 	if (*perf_event_fasync(event) && event->pending_kill) {
 		event->pending_wakeup = 1;

@@ -7777,9 +7777,9 @@ static int __perf_event_overflow(struct perf_event *event,
 
 int perf_event_overflow(struct perf_event *event,
 			  struct perf_sample_data *data,
-			  struct pt_regs *regs)
+			  struct pt_regs *regs, struct pt_regs *iregs)
 {
-	return __perf_event_overflow(event, 1, data, regs);
+	return __perf_event_overflow(event, 1, data, regs, iregs);
 }
 
 /*

@@ -7842,7 +7842,7 @@ static void perf_swevent_overflow(struct perf_event *event, u64 overflow,
 
 	for (; overflow; overflow--) {
 		if (__perf_event_overflow(event, throttle,
-					    data, regs)) {
+					    data, regs, regs)) {
 			/*
 			 * We inhibit the overflow from happening when
 			 * hwc->interrupts == MAX_INTERRUPTS.

@@ -8550,7 +8550,7 @@ static void bpf_overflow_handler(struct perf_event *event,
 	if (!ret)
 		return;
 
-	event->orig_overflow_handler(event, data, regs);
+	event->orig_overflow_handler(event, data, regs, regs);
 }
 
 static int perf_event_set_bpf_handler(struct perf_event *event, u32 prog_fd)

@@ -9152,7 +9152,7 @@ static enum hrtimer_restart perf_swevent_hrtimer(struct hrtimer *hrtimer)
 
 	if (regs && !perf_exclude_event(event, regs)) {
 		if (!(event->attr.exclude_idle && is_idle_task(current)))
-			if (__perf_event_overflow(event, 1, &data, regs))
+			if (__perf_event_overflow(event, 1, &data, regs, regs))
 				ret = HRTIMER_NORESTART;
 	}
 

index 08fcfe440c63..6faf12fd6114 100644
@@ -392,7 +392,7 @@ __bpf_perf_event_output(struct pt_regs *regs, struct bpf_map *map,
 	if (unlikely(event->oncpu != cpu))
 		return -EOPNOTSUPP;
 
-	perf_event_output(event, sd, regs);
+	perf_event_output(event, sd, regs, regs);
 	return 0;
 }
 

index 71381168dede..5f4e18d003bb 100644
@@ -109,7 +109,7 @@ static struct perf_event_attr wd_hw_attr = {
 /* Callback function for perf event subsystem */
 static void watchdog_overflow_callback(struct perf_event *event,
 				       struct perf_sample_data *data,
-				       struct pt_regs *regs)
+				       struct pt_regs *regs, struct pt_regs *iregs)
 {
 	/* Ensure the watchdog never gets throttled */
 	event->hw.interrupts = 0;

2.19.1

From 721bb20a8a7d1ff2f7b062f8d92f50c743883d35 Mon Sep 17 00:00:00 2001
From: Milian Wolff <[email protected]>
Date: Wed, 14 Nov 2018 14:18:56 +0100
Subject: [PATCH 2/2] [WIP] perf unwind: use iregs for unwinding

TODO: only use it if available
TODO: figure out when to skip iregs->ip frame, and when to use it (e.g. when function for iregs->ip and uregs->ip differs?)

---
 tools/perf/util/unwind-libunwind-local.c | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

index 79f521a552cf..39f19673cc34 100644
@@ -492,12 +492,12 @@ static int access_mem(unw_addr_space_t __maybe_unused as,
 	int ret;
 
 	/* Don't support write, probably not needed. */
-	if (__write || !stack || !ui->sample->user_regs.regs) {
+	if (__write || !stack || !ui->sample->intr_regs.regs) {
 		*valp = 0;
 		return 0;
 	}
 
-	ret = perf_reg_value(&start, &ui->sample->user_regs,
+	ret = perf_reg_value(&start, &ui->sample->intr_regs,
 			     LIBUNWIND__ARCH_REG_SP);
 	if (ret)
 		return ret;

@@ -541,7 +541,7 @@ static int access_reg(unw_addr_space_t __maybe_unused as,
 		return 0;
 	}
 
-	if (!ui->sample->user_regs.regs) {
+	if (!ui->sample->intr_regs.regs) {
 		*valp = 0;
 		return 0;
 	}

@@ -550,7 +550,7 @@ static int access_reg(unw_addr_space_t __maybe_unused as,
 	if (id < 0)
 		return -EINVAL;
 
-	ret = perf_reg_value(&val, &ui->sample->user_regs, id);
+	ret = perf_reg_value(&val, &ui->sample->intr_regs, id);
 	if (ret) {
 		pr_err("unwind: can't read reg %d\n", regnum);
 		return ret;

@@ -716,7 +716,7 @@ static int _unwind__get_entries(unwind_entry_cb_t cb, void *arg,
 		.machine      = thread->mg->machine,
 	};
 
-	if (!data->user_regs.regs)
+	if (!data->intr_regs.regs)
 		return -EINVAL;
 
 	if (max_stack <= 0)

2.19.1

Does this mean that the displayed unwind will sometimes be "impossible" to have actually be generated from a consistent execution of the user program?

For example, the top frame (from PEBS) and second frame (from iregs) may be inconsistent in that the latter function never calls the first. At this point it would be good to have an indication at the top frame is from a different source than the rest of the frames, lest the user pull is hair out trying to determine how function X seems to call function Y despite that not being the case in the source.

Yes, that is exactly what I'm saying.

I agree. I personally like your suggested approach - only add an indication when the IP differs so much that it points to a different function. What do others say to this?

Cheers

Milian Wolff | [email protected] | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

Yes that's fine.

-Andi

Thanks for clearing this up - so you can ignore any earlier suggestions on my part of trying to use LBR to fix the unwinding inconsistency.

Well other than say a long-latency cache miss, it is my experience that the skid is generally never zero. That is, the PEBS and ireg IP will usually differ. This is mostly moot though: what is important is how often the ireg skip results in a different call chain (i.e., a return occurred between the PEBS point and the interrupt), as you have pointed out.

Agreed.

As above, I think the most important UX problem is not when the IP differs, but when the top frame of the IP unwind is different than the function in which the PEBS sample occurred. I think the case where the skid ends up with both in the same function doesn't pose any presentation difficulties [1]. When they are different though, it seems tough to present a consistent picture.

[1] Strictly speaking, this the "IPs are in the same function" is not sufficient. Imagine a scenario where you have T->B->A (T calls B calls
A) and the PEBS sample happens in A, and then A and B return, and now C then A are called (T->C->A) and the PMI happens. Now the PEBS IP and the ireg IP are in the same function, but the stacks are still inconsistent. It is probably fine to paper this over and show the user the T->C->A stack, as this stack is somehow accurate (it really happened), but the user might be confused when he looks at the annotation for A, and sees code being executed (having PEBS samples) that he knows can never execute when C calls A (for example) since the annotations are based on the hidden T->B->A execution...

Bleh.