Groups > linux.kernel > #1271890 > unrolled thread

[BUG REPORT] perf tools: x86_64: Broken calllchain when sampling taken at 'callq' instruction

Started by	"Wangnan (F)" <wangnan0@huawei.com>
First post	2015-11-18 08:30 +0100
Last post	2015-11-18 10:20 +0100
Articles	15 — 4 participants

Back to article view | Back to linux.kernel

  [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction "Wangnan (F)" <wangnan0@huawei.com> - 2015-11-18 08:30 +0100
    Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction "Wangnan (F)" <wangnan0@huawei.com> - 2015-11-18 09:20 +0100
      Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction Ingo Molnar <mingo@kernel.org> - 2015-11-18 09:30 +0100
        Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction "Wangnan (F)" <wangnan0@huawei.com> - 2015-11-18 10:00 +0100
          Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction Ingo Molnar <mingo@kernel.org> - 2015-11-19 07:40 +0100
            Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction "Wangnan (F)" <wangnan0@huawei.com> - 2015-11-19 07:50 +0100
              Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction Ingo Molnar <mingo@kernel.org> - 2015-11-19 11:30 +0100
                Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction "Wangnan (F)" <wangnan0@huawei.com> - 2015-11-19 11:50 +0100
                  Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction Peter Zijlstra <peterz@infradead.org> - 2015-11-19 12:30 +0100
                Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction Peter Zijlstra <peterz@infradead.org> - 2015-11-19 12:30 +0100
                  Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction Ingo Molnar <mingo@kernel.org> - 2015-11-27 09:40 +0100
                    Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction Peter Zijlstra <peterz@infradead.org> - 2015-11-30 10:30 +0100
        Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction "Wangnan (F)" <wangnan0@huawei.com> - 2015-11-18 10:10 +0100
    Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction Jiri Olsa <jolsa@redhat.com> - 2015-11-18 09:50 +0100
      Re: [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling  taken at 'callq' instruction "Wangnan (F)" <wangnan0@huawei.com> - 2015-11-18 10:20 +0100

#1271890 — [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling taken at 'callq' instruction

From	"Wangnan (F)" <wangnan0@huawei.com>
Date	2015-11-18 08:30 +0100
Subject	[BUG REPORT] perf tools: x86_64: Broken calllchain when sampling taken at 'callq' instruction
Message-ID	<qw5lL-8cX-3@gated-at.bofh.it>

Hi all,

When analysising Jiri's patchset [1] I found a dwarf unwind problem.
On x86 platform, when sample is at a 'callq' instruction, dwarf based
stack unwind always fail.

I compile a small C source file with debug information, turn off
frame pointer and disable optimization:

$ gcc -g -O0 -fomit-frame-pointer ./test_dwarf_unwind.c -o 
./test_dwarf_unwind

Here is part of asm code. Please have a look at 40057d. Also, have a
look at 400534 and 4005bc, from these two instructions we know this
"funcc" need 0x38 bytes on stack, so we know where is the return address.

$ objdump -S ./test_dwarf_unwind
...
0000000000400534 <funcc>:
#include <sys/time.h>

static volatile int x = 0;

int funcc(void)
{
   400534:       48 83 ec 38             sub    $0x38,%rsp
     struct timeval tv1, tv2;
     unsigned long us1, us2;

     gettimeofday(&tv1, NULL);
   400538:       48 8d 44 24 10          lea    0x10(%rsp),%rax
   ...
   400572:       48 89 e0                mov    %rsp,%rax
   400575:       be 00 00 00 00          mov    $0x0,%esi
   40057a:       48 89 c7                mov    %rax,%rdi
   40057d:       e8 7e fe ff ff          callq  400400 
<gettimeofday@plt>    <---!!!
         us2 = tv2.tv_sec * 1000000 + tv2.tv_usec;
   400582:       48 8b 04 24             mov    (%rsp),%rax
   400586:       48 69 d0 40 42 0f 00    imul   $0xf4240,%rax,%rdx
   ...
     return x;
   4005b6:       8b 05 74 04 20 00       mov 0x200474(%rip),%eax        
# 600a30 <x>
}
   4005bc:       48 83 c4 38             add    $0x38,%rsp
   4005c0:       c3                      retq

Then use perf to trace it:

# ./pref record  -g -F 9 --call-graph dwarf ./test_dwarf_unwind
# ./perf report  --no-children --stdio
      ...
      1.23%  test_dwarf_unwi  test_dwarf_unwind  [.] funcc
             |
             ---funcc
                |
                |--0.62%-- funcb
                |          funca
                |          main
                |          __libc_start_main
                |          _start
                |
                 --0.62%-- 0   <-- I applied Jiri's patch in [1] so see 
this 0,
                                   which indicates a broken call chain.

 From 'perf script' result I found the two samples inside funcc:

# ./perf script
...
test_dwarf_unwi 25232 2201855.424651:  443365670 cycles:pp:
                   4005a4 funcc (/home/w00229757/test_dwarf_unwind)
                   4005ca funcb (/home/w00229757/test_dwarf_unwind)
                   4005d8 funca (/home/w00229757/test_dwarf_unwind)
                   4005e6 main (/home/w00229757/test_dwarf_unwind)
             7facc5c2ebd5 __libc_start_main 
(/tmp/oxygen_root-w00229757/lib64/libc-2.18.so)
                   400459 _start (/home/w00229757/test_dwarf_unwind)
...
test_dwarf_unwi 25232 2201856.647088:  443268987 cycles:pp:
                   40057d funcc (/home/w00229757/test_dwarf_unwind)
                        0 [unknown] ([unknown])

With perf report -D I can manually check their stack information manually.


This is stack of sample at 4005a4:

# ./perf report -D
...
0x1d9c8 [0x20e8]: event: 9
.
. ... raw event: size 8424 bytes
.  0000:  09 00 00 00 02 40 e8 20 a4 05 40 00 00 00 00 00  .....@. ..@.....
...
.  00d0:  00 00 00 00 00 00 00 00 00 20 00 00 00 00 00 00  ......... ......
.  00e0:  2b f6 4c 56 00 00 00 00 46 52 02 00 00 00 00 00 +.LV....FR......
.  00f0:  29 f6 4c 56 00 00 00 00 70 e4 0c 00 00 00 00 00 ).LV....p.......
.  0100:  06 f3 3b d7 d7 24 05 00 b0 00 28 d7 d7 24 05 00 ..;..$....(..$..
.  0110:  00 00 00 00 00 00 00 00 ca 05 40 00 00 00 00 00
...
.  20e0:  b0 06 00 00 00 00 00 00                          ........
.
2201855424651081 0x1d9c8 [0x20e8]: PERF_RECORD_SAMPLE(IP, 0x4002): 
25232/25232: 0x4005a4 period: 443365670 addr: 0
... FP chain: nr:0
... user regs: mask 0xff0fff ABI 64-bit
.......
.... IP    0x4005a4
.......
... ustack: size 1712, offset 0xd8
....

 From the above information we can check its stack from 0xe0 (stack size
reside at 0xd8 as a u64 so stack data start at 0xe0). Based on information
we get from the above asm code, we know the return address should at the
0x38 of the stack, which is 0x4005ca.

This is stack of sample at 40057d:

0x343c0 [0x20e8]: event: 9
.
. ... raw event: size 8424 bytes
.  0000:  09 00 00 00 02 40 e8 20 7d 05 40 00 00 00 00 00  .....@. }.@.....
...
.  00d0:  00 00 00 00 00 00 00 00 00 20 00 00 00 00 00 00  ......... ......
.  00e0:  82 05 40 00 00 00 00 00 2c f6 4c 56 00 00 00 00 ..@.....,.LV....
.  00f0:  84 b7 05 00 00 00 00 00 29 f6 4c 56 00 00 00 00 ........).LV....
.  0100:  70 e4 0c 00 00 00 00 00 84 9a 4e d7 d7 24 05 00 p.........N..$..
.  0110:  b0 00 28 d7 d7 24 05 00 00 00 00 00 00 00 00 00 ..(..$..........
.  0120:  ca 05 40 00 00 00 00 00 f0 05 40 00 00 00 00 00 ..@.......@.....
...
.  20e0:  b8 06 00 00 00 00 00 00                          ........
.
2201856647088808 0x343c0 [0x20e8]: PERF_RECORD_SAMPLE(IP, 0x4002): 
25232/25232: 0x40057d period: 443268987 addr: 0
... FP chain: nr:0
... user regs: mask 0xff0fff ABI 64-bit
......
.... IP    0x40057d
......
... ustack: size 1720, offset 0xd8
.....

By manually checking user stack from 0xe0, we can see problem that: 
although the IP
is still at 'callq', that instruction seems already take effect that, it has
already pushes its return address (0x400582) onto stack.

So there must be somewhere the pt_regs or the stack is adjusted in kernel.
Does anyone can give some hint on it?

Thank you.

[1] 
http://lkml.kernel.org/r/1447772739-18471-1-git-send-email-jolsa@kernel.org

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [next] | [standalone]

#1271915

From	"Wangnan (F)" <wangnan0@huawei.com>
Date	2015-11-18 09:20 +0100
Message-ID	<qw68a-jO-27@gated-at.bofh.it>
In reply to	#1271890


On 2015/11/18 15:20, Wangnan (F) wrote:
> Hi all,
>
> When analysising Jiri's patchset [1] I found a dwarf unwind problem.
> On x86 platform, when sample is at a 'callq' instruction, dwarf based
> stack unwind always fail.
>
> I compile a small C source file with debug information, turn off
> frame pointer and disable optimization:
>
> $ gcc -g -O0 -fomit-frame-pointer ./test_dwarf_unwind.c -o 
> ./test_dwarf_unwind

For whom want to test it: here is the test code I used.

#include <stdio.h>
#include <unistd.h>
#include <sys/time.h>

static volatile int x = 0;

int funcc(void)
{
     struct timeval tv1, tv2;
     unsigned long us1, us2;

     gettimeofday(&tv1, NULL);

     us1 = tv1.tv_sec * 1000000 + tv1.tv_usec;

     while(1) {
         x = x + 100;
         gettimeofday(&tv2, NULL);
         us2 = tv2.tv_sec * 1000000 + tv2.tv_usec;
         if (us2 - us1 >= 3000000)
             break;
     }
     return x;
}
int funcb(void) { return funcc();}
int funca(void) { return funcb();}
int main() { funca(); return 0;}



--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1271923

From	Ingo Molnar <mingo@kernel.org>
Date	2015-11-18 09:30 +0100
Message-ID	<qw6hQ-nn-15@gated-at.bofh.it>
In reply to	#1271915

* Wangnan (F) <wangnan0@huawei.com> wrote:

> On 2015/11/18 15:20, Wangnan (F) wrote:
> >Hi all,
> >
> >When analysising Jiri's patchset [1] I found a dwarf unwind problem.
> >On x86 platform, when sample is at a 'callq' instruction, dwarf based
> >stack unwind always fail.
> >
> >I compile a small C source file with debug information, turn off
> >frame pointer and disable optimization:
> >
> >$ gcc -g -O0 -fomit-frame-pointer ./test_dwarf_unwind.c -o
> >./test_dwarf_unwind
> 
> For whom want to test it: here is the test code I used.
> 
> #include <stdio.h>
> #include <unistd.h>
> #include <sys/time.h>
> 
> static volatile int x = 0;
> 
> int funcc(void)
> {
>     struct timeval tv1, tv2;
>     unsigned long us1, us2;
> 
>     gettimeofday(&tv1, NULL);
> 
>     us1 = tv1.tv_sec * 1000000 + tv1.tv_usec;
> 
>     while(1) {
>         x = x + 100;
>         gettimeofday(&tv2, NULL);
>         us2 = tv2.tv_sec * 1000000 + tv2.tv_usec;
>         if (us2 - us1 >= 3000000)
>             break;
>     }
>     return x;
> }
> int funcb(void) { return funcc();}
> int funca(void) { return funcb();}
> int main() { funca(); return 0;}

What CPU model is this, and what event was used - PEBS perhaps? This might be some 
sort of PMU sampling bug/quirk/misfeature - or perhaps a kernel side fixup that 
went bad?

Thanks,

	Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1271960

From	"Wangnan (F)" <wangnan0@huawei.com>
Date	2015-11-18 10:00 +0100
Message-ID	<qw6KS-Af-7@gated-at.bofh.it>
In reply to	#1271923


On 2015/11/18 16:42, Wangnan (F) wrote:
>
>
> On 2015/11/18 16:20, Ingo Molnar wrote:
>> * Wangnan (F) <wangnan0@huawei.com> wrote:
>>
>>> On 2015/11/18 15:20, Wangnan (F) wrote:
>>>> Hi all,
>>>>
>>>> When analysising Jiri's patchset [1] I found a dwarf unwind problem.
>>>> On x86 platform, when sample is at a 'callq' instruction, dwarf based
>>>> stack unwind always fail.
>>>>
>>>> I compile a small C source file with debug information, turn off
>>>> frame pointer and disable optimization:
>>>>
>>>> $ gcc -g -O0 -fomit-frame-pointer ./test_dwarf_unwind.c -o
>>>> ./test_dwarf_unwind
>>> For whom want to test it: here is the test code I used.
>>>
>>> #include <stdio.h>
>>> #include <unistd.h>
>>> #include <sys/time.h>
>>>
>>> static volatile int x = 0;
>>>
>>> int funcc(void)
>>> {
>>>      struct timeval tv1, tv2;
>>>      unsigned long us1, us2;
>>>
>>>      gettimeofday(&tv1, NULL);
>>>
>>>      us1 = tv1.tv_sec * 1000000 + tv1.tv_usec;
>>>
>>>      while(1) {
>>>          x = x + 100;
>>>          gettimeofday(&tv2, NULL);
>>>          us2 = tv2.tv_sec * 1000000 + tv2.tv_usec;
>>>          if (us2 - us1 >= 3000000)
>>>              break;
>>>      }
>>>      return x;
>>> }
>>> int funcb(void) { return funcc();}
>>> int funca(void) { return funcb();}
>>> int main() { funca(); return 0;}
>> What CPU model is this, and what event was used - PEBS perhaps? This 
>> might be some
>> sort of PMU sampling bug/quirk/misfeature - or perhaps a kernel side 
>> fixup that
>> went bad?
>
> $ cat /proc/cpuinfo
> processor    : 0
> vendor_id    : GenuineIntel
> cpu family    : 6
> model        : 60
> model name    : Intel(R) Core(TM) i7-4790 CPU @ 3.60GHz
> stepping    : 3
> microcode    : 0x1c
> cpu MHz        : 3600.000
> cache size    : 8192 KB
> physical id    : 0
> siblings    : 8
> core id        : 0
> cpu cores    : 4
> apicid        : 0
> initial apicid    : 0
> fpu        : yes
> fpu_exception    : yes
> cpuid level    : 13
> wp        : yes
> flags        : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge 
> mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe 
> syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts 
> rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq 
> dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm 
> pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave 
> avx f16c rdrand lahf_lm abm ida arat epb pln pts dtherm tpr_shadow 
> vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 
> erms invpcid xsaveopt
> bugs        :
> bogomips    : 7183.88
> clflush size    : 64
> cache_alignment    : 64
> address sizes    : 39 bits physical, 48 bits virtual
> power management:
>
>
> perf cmdline is
>
> # ./pref record  -g -F 9 --call-graph dwarf ./test_dwarf_unwind
>
> Use default events, precise_ip == 2 so uses PEBS.
>

Testetd 'cycles', 'cycles:p' and 'cycles:pp'. Only 'cycles:pp' captures
sample at callq. So maybe a PEBS problem?

Thank you.


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1272877

From	Ingo Molnar <mingo@kernel.org>
Date	2015-11-19 07:40 +0100
Message-ID	<qwr2V-5I2-5@gated-at.bofh.it>
In reply to	#1271960

* Wangnan (F) <wangnan0@huawei.com> wrote:

> >perf cmdline is
> >
> ># ./pref record  -g -F 9 --call-graph dwarf ./test_dwarf_unwind
> >
> >Use default events, precise_ip == 2 so uses PEBS.
> >
> 
> Testetd 'cycles', 'cycles:p' and 'cycles:pp'. Only 'cycles:pp' captures
> sample at callq. So maybe a PEBS problem?

Well, that's how our PEBS sampling works: we roll back the instruction pointer to 
point at the instruction generating the sample. The state itself is 
post-instruction.

So dwarf unwind has to take this into account. Should the kernel pass in the 
original (uncorrected) RIP as well, perhaps?

Thanks,

	Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1272879

From	"Wangnan (F)" <wangnan0@huawei.com>
Date	2015-11-19 07:50 +0100
Message-ID	<qwrcB-5Lq-5@gated-at.bofh.it>
In reply to	#1272877


On 2015/11/19 14:37, Ingo Molnar wrote:
> * Wangnan (F) <wangnan0@huawei.com> wrote:
>
>>> perf cmdline is
>>>
>>> # ./pref record  -g -F 9 --call-graph dwarf ./test_dwarf_unwind
>>>
>>> Use default events, precise_ip == 2 so uses PEBS.
>>>
>> Testetd 'cycles', 'cycles:p' and 'cycles:pp'. Only 'cycles:pp' captures
>> sample at callq. So maybe a PEBS problem?
> Well, that's how our PEBS sampling works: we roll back the instruction pointer to
> point at the instruction generating the sample. The state itself is
> post-instruction.

Just for curiosity:

how the interrupted process continue to execute, when the PC
saved in pt_regs still pointed to 'callq' but SP and stack has
already changes? Do we fix it in kernel, or by hardware?

Thank you.

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1273003

From	Ingo Molnar <mingo@kernel.org>
Date	2015-11-19 11:30 +0100
Message-ID	<qwuDv-820-5@gated-at.bofh.it>
In reply to	#1272879

* Wangnan (F) <wangnan0@huawei.com> wrote:

> 
> 
> On 2015/11/19 14:37, Ingo Molnar wrote:
> >* Wangnan (F) <wangnan0@huawei.com> wrote:
> >
> >>>perf cmdline is
> >>>
> >>># ./pref record  -g -F 9 --call-graph dwarf ./test_dwarf_unwind
> >>>
> >>>Use default events, precise_ip == 2 so uses PEBS.
> >>>
> >>Testetd 'cycles', 'cycles:p' and 'cycles:pp'. Only 'cycles:pp' captures
> >>sample at callq. So maybe a PEBS problem?
> >Well, that's how our PEBS sampling works: we roll back the instruction pointer to
> >point at the instruction generating the sample. The state itself is
> >post-instruction.
> 
> Just for curiosity:
> 
> how the interrupted process continue to execute, when the PC
> saved in pt_regs still pointed to 'callq' but SP and stack has
> already changes? Do we fix it in kernel, or by hardware?

PEBS is an asynchronous hardware tracing mechanism, when batched PEBS is used it 
might not even result in any interruption of execution. The 'pt_regs' does not 
necessarily correspond to an interrupted, restartable context - we take the RIP 
from the PEBS machinery and also use LBR and disassembly to determine the previous 
instruction, before reporting it to user-space.

Thanks,

	Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1273019

From	"Wangnan (F)" <wangnan0@huawei.com>
Date	2015-11-19 11:50 +0100
Message-ID	<qwuWR-88v-15@gated-at.bofh.it>
In reply to	#1273003


On 2015/11/19 18:23, Ingo Molnar wrote:
> * Wangnan (F) <wangnan0@huawei.com> wrote:
>
>>
>> On 2015/11/19 14:37, Ingo Molnar wrote:
>>> * Wangnan (F) <wangnan0@huawei.com> wrote:
>>>
>>>>> perf cmdline is
>>>>>
>>>>> # ./pref record  -g -F 9 --call-graph dwarf ./test_dwarf_unwind
>>>>>
>>>>> Use default events, precise_ip == 2 so uses PEBS.
>>>>>
>>>> Testetd 'cycles', 'cycles:p' and 'cycles:pp'. Only 'cycles:pp' captures
>>>> sample at callq. So maybe a PEBS problem?
>>> Well, that's how our PEBS sampling works: we roll back the instruction pointer to
>>> point at the instruction generating the sample. The state itself is
>>> post-instruction.
>> Just for curiosity:
>>
>> how the interrupted process continue to execute, when the PC
>> saved in pt_regs still pointed to 'callq' but SP and stack has
>> already changes? Do we fix it in kernel, or by hardware?
> PEBS is an asynchronous hardware tracing mechanism, when batched PEBS is used it
> might not even result in any interruption of execution. The 'pt_regs' does not
> necessarily correspond to an interrupted, restartable context - we take the RIP
> from the PEBS machinery and also use LBR and disassembly to determine the previous
> instruction, before reporting it to user-space.

You mean __intel_pmu_pebs_event(), which generates many perf_events?
Then their output are based on a same user stack, and could be error,
because the instruction has finished, and user stack could be modified.
Right?

Also, why not fixing rsp in kernel if that instruction is a 'callq'?
For avoiding instruction decoding?

Thank you.

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1273055

From	Peter Zijlstra <peterz@infradead.org>
Date	2015-11-19 12:30 +0100
Message-ID	<qwvzB-by-45@gated-at.bofh.it>
In reply to	#1273019

On Thu, Nov 19, 2015 at 06:43:14PM +0800, Wangnan (F) wrote:
> Also, why not fixing rsp in kernel if that instruction is a 'callq'?
> For avoiding instruction decoding?

Why would the kernel do that? It doesn't need this.

Have userspace do it when trying to interpret the data.

If PERF_EFLAGS_EXACT is set, you know the IP points to the actual
instruction and you can attempt to undo whatever parts of it you need at
post processing time.

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1273057

From	Peter Zijlstra <peterz@infradead.org>
Date	2015-11-19 12:30 +0100
Message-ID	<qwvzB-by-39@gated-at.bofh.it>
In reply to	#1273003

On Thu, Nov 19, 2015 at 11:23:00AM +0100, Ingo Molnar wrote:
> PEBS is an asynchronous hardware tracing mechanism, when batched PEBS is used it 
> might not even result in any interruption of execution. The 'pt_regs' does not 
> necessarily correspond to an interrupted, restartable context - we take the RIP 
> from the PEBS machinery and also use LBR and disassembly to determine the previous 
> instruction, before reporting it to user-space.

Note that modern PEBS hardware (hsw+) does the rollback in hardware.
Prior to that we indeed to it manually using the LBR.

As to pt_regs, we construct a franken pt_regs based on the actual PEBS
buffer overflow PMI and bits from the PEBS record (which also includes
some register state). See
arch/x86/kernel/cpu/perf_event_intel_ds.c:setup_pebs_sample_data().

We always copy the flags, ip, bp and sp from the PEBS record into the
interrupt pt_regs.

And note that the PEBS record is constructed at instruction retirement,
so it shows the state _after_ the instruction, with exception of the
(hsw+) real_ip field.

So the unwinder will have to be taught that if the IP points at a stack
altering instruction (call, push, etc.) it will have to 'undo' the
effects on the actual stack (I appreciate this might be 'interesting'
for things like: pop, ret, etc.).

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1278625

From	Ingo Molnar <mingo@kernel.org>
Date	2015-11-27 09:40 +0100
Message-ID	<qzmJt-pZ-31@gated-at.bofh.it>
In reply to	#1273057

* Peter Zijlstra <peterz@infradead.org> wrote:

> On Thu, Nov 19, 2015 at 11:23:00AM +0100, Ingo Molnar wrote:
> > PEBS is an asynchronous hardware tracing mechanism, when batched PEBS is used it 
> > might not even result in any interruption of execution. The 'pt_regs' does not 
> > necessarily correspond to an interrupted, restartable context - we take the RIP 
> > from the PEBS machinery and also use LBR and disassembly to determine the previous 
> > instruction, before reporting it to user-space.
> 
> Note that modern PEBS hardware (hsw+) does the rollback in hardware.
> Prior to that we indeed to it manually using the LBR.
> 
> As to pt_regs, we construct a franken pt_regs based on the actual PEBS
> buffer overflow PMI and bits from the PEBS record (which also includes
> some register state). See
> arch/x86/kernel/cpu/perf_event_intel_ds.c:setup_pebs_sample_data().
> 
> We always copy the flags, ip, bp and sp from the PEBS record into the
> interrupt pt_regs.
> 
> And note that the PEBS record is constructed at instruction retirement,
> so it shows the state _after_ the instruction, with exception of the
> (hsw+) real_ip field.
> 
> So the unwinder will have to be taught that if the IP points at a stack
> altering instruction (call, push, etc.) it will have to 'undo' the
> effects on the actual stack (I appreciate this might be 'interesting'
> for things like: pop, ret, etc.).

So do we dump both the 'real' and the actual RIP, to not force tooling into having 
to decode instructions and such? (Which is pretty hard and fragile and not always 
possible with instructions that destroy the original RIP, like JMP, etc.)

Thanks,

	Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1279729

From	Peter Zijlstra <peterz@infradead.org>
Date	2015-11-30 10:30 +0100
Message-ID	<qAsWv-1JR-35@gated-at.bofh.it>
In reply to	#1278625

On Fri, Nov 27, 2015 at 09:38:11AM +0100, Ingo Molnar wrote:
> 
> * Peter Zijlstra <peterz@infradead.org> wrote:
> 
> > On Thu, Nov 19, 2015 at 11:23:00AM +0100, Ingo Molnar wrote:
> > > PEBS is an asynchronous hardware tracing mechanism, when batched PEBS is used it 
> > > might not even result in any interruption of execution. The 'pt_regs' does not 
> > > necessarily correspond to an interrupted, restartable context - we take the RIP 
> > > from the PEBS machinery and also use LBR and disassembly to determine the previous 
> > > instruction, before reporting it to user-space.
> > 
> > Note that modern PEBS hardware (hsw+) does the rollback in hardware.
> > Prior to that we indeed to it manually using the LBR.
> > 
> > As to pt_regs, we construct a franken pt_regs based on the actual PEBS
> > buffer overflow PMI and bits from the PEBS record (which also includes
> > some register state). See
> > arch/x86/kernel/cpu/perf_event_intel_ds.c:setup_pebs_sample_data().
> > 
> > We always copy the flags, ip, bp and sp from the PEBS record into the
> > interrupt pt_regs.
> > 
> > And note that the PEBS record is constructed at instruction retirement,
> > so it shows the state _after_ the instruction, with exception of the
> > (hsw+) real_ip field.
> > 
> > So the unwinder will have to be taught that if the IP points at a stack
> > altering instruction (call, push, etc.) it will have to 'undo' the
> > effects on the actual stack (I appreciate this might be 'interesting'
> > for things like: pop, ret, etc.).
> 
> So do we dump both the 'real' and the actual RIP, to not force tooling into having 
> to decode instructions and such?

Nope, we only expose the corrected one.

> (Which is pretty hard and fragile and not always 
> possible with instructions that destroy the original RIP, like JMP, etc.)

Not sure what you're getting at here. We don't need the uncorrected
instruction.

But the problem here is that we rewind the instruction stream, but not
the stack. And the stack unwinder is (obviously) interested in the stack
state.

I'm not sure we want (or need) to go undo the specific instruction's
stack effect in-kernel. If the !DWARF unwinders are similarly confused
we might need to put it in kernel (expensive *groan*). If its only the
DWARF muck then its something that can be done in userspace just
fine, although we might need to copy slightly more of the stack than SP
is pointing at, such that we can undo RET/POP etc. which would have data
beyond the head of stack.

The easiest solution might be to figure out the biggest stack offset for
any instruction and always capture that much over the head of stack.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1272003

From	"Wangnan (F)" <wangnan0@huawei.com>
Date	2015-11-18 10:10 +0100
Message-ID	<qw6KS-Af-9@gated-at.bofh.it>
In reply to	#1271923


On 2015/11/18 16:20, Ingo Molnar wrote:
> * Wangnan (F) <wangnan0@huawei.com> wrote:
>
>> On 2015/11/18 15:20, Wangnan (F) wrote:
>>> Hi all,
>>>
>>> When analysising Jiri's patchset [1] I found a dwarf unwind problem.
>>> On x86 platform, when sample is at a 'callq' instruction, dwarf based
>>> stack unwind always fail.
>>>
>>> I compile a small C source file with debug information, turn off
>>> frame pointer and disable optimization:
>>>
>>> $ gcc -g -O0 -fomit-frame-pointer ./test_dwarf_unwind.c -o
>>> ./test_dwarf_unwind
>> For whom want to test it: here is the test code I used.
>>
>> #include <stdio.h>
>> #include <unistd.h>
>> #include <sys/time.h>
>>
>> static volatile int x = 0;
>>
>> int funcc(void)
>> {
>>      struct timeval tv1, tv2;
>>      unsigned long us1, us2;
>>
>>      gettimeofday(&tv1, NULL);
>>
>>      us1 = tv1.tv_sec * 1000000 + tv1.tv_usec;
>>
>>      while(1) {
>>          x = x + 100;
>>          gettimeofday(&tv2, NULL);
>>          us2 = tv2.tv_sec * 1000000 + tv2.tv_usec;
>>          if (us2 - us1 >= 3000000)
>>              break;
>>      }
>>      return x;
>> }
>> int funcb(void) { return funcc();}
>> int funca(void) { return funcb();}
>> int main() { funca(); return 0;}
> What CPU model is this, and what event was used - PEBS perhaps? This might be some
> sort of PMU sampling bug/quirk/misfeature - or perhaps a kernel side fixup that
> went bad?

$ cat /proc/cpuinfo
processor    : 0
vendor_id    : GenuineIntel
cpu family    : 6
model        : 60
model name    : Intel(R) Core(TM) i7-4790 CPU @ 3.60GHz
stepping    : 3
microcode    : 0x1c
cpu MHz        : 3600.000
cache size    : 8192 KB
physical id    : 0
siblings    : 8
core id        : 0
cpu cores    : 4
apicid        : 0
initial apicid    : 0
fpu        : yes
fpu_exception    : yes
cpuid level    : 13
wp        : yes
flags        : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca 
cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall 
nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl 
xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor 
ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2 
x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm 
abm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid 
fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid xsaveopt
bugs        :
bogomips    : 7183.88
clflush size    : 64
cache_alignment    : 64
address sizes    : 39 bits physical, 48 bits virtual
power management:


perf cmdline is

# ./pref record  -g -F 9 --call-graph dwarf ./test_dwarf_unwind

Use default events, precise_ip == 2 so uses PEBS.

Thank you.

>
> Thanks,
>
> 	Ingo


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1271944

From	Jiri Olsa <jolsa@redhat.com>
Date	2015-11-18 09:50 +0100
Message-ID	<qw6Bc-vx-11@gated-at.bofh.it>
In reply to	#1271890

On Wed, Nov 18, 2015 at 03:20:36PM +0800, Wangnan (F) wrote:

SNIP

> 
> Then use perf to trace it:
> 
> # ./pref record  -g -F 9 --call-graph dwarf ./test_dwarf_unwind
> # ./perf report  --no-children --stdio
>      ...
>      1.23%  test_dwarf_unwi  test_dwarf_unwind  [.] funcc
>             |
>             ---funcc
>                |
>                |--0.62%-- funcb
>                |          funca
>                |          main
>                |          __libc_start_main
>                |          _start
>                |
>                 --0.62%-- 0   <-- I applied Jiri's patch in [1] so see this
> 0,
>                                   which indicates a broken call chain.

can't see this case after multiple running your test,
just the 'end-of-the-callchain' zeros

    49.14%  test_dwarf_unwi  [vdso]             [.] __vdso_gettimeofday  
            |
            ---__vdso_gettimeofday
               funcc
               funcb
               funca
               main
               __libc_start_main
               _start
               0

    40.78%  test_dwarf_unwi  [vdso]             [.] 0x0000000000000987   
            |
            ---0x7ffe28ab7987
               __vdso_gettimeofday
               funcc
               funcb
               funca
               main
               __libc_start_main
               _start
               0


what kernel do you have?

jirka
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1272013

From	"Wangnan (F)" <wangnan0@huawei.com>
Date	2015-11-18 10:20 +0100
Message-ID	<qw74e-WO-19@gated-at.bofh.it>
In reply to	#1271944


On 2015/11/18 16:48, Jiri Olsa wrote:
> On Wed, Nov 18, 2015 at 03:20:36PM +0800, Wangnan (F) wrote:
>
> SNIP
>
>> Then use perf to trace it:
>>
>> # ./pref record  -g -F 9 --call-graph dwarf ./test_dwarf_unwind
>> # ./perf report  --no-children --stdio
>>       ...
>>       1.23%  test_dwarf_unwi  test_dwarf_unwind  [.] funcc
>>              |
>>              ---funcc
>>                 |
>>                 |--0.62%-- funcb
>>                 |          funca
>>                 |          main
>>                 |          __libc_start_main
>>                 |          _start
>>                 |
>>                  --0.62%-- 0   <-- I applied Jiri's patch in [1] so see this
>> 0,
>>                                    which indicates a broken call chain.
> can't see this case after multiple running your test,
> just the 'end-of-the-callchain' zeros
>
>      49.14%  test_dwarf_unwi  [vdso]             [.] __vdso_gettimeofday
>              |
>              ---__vdso_gettimeofday
>                 funcc
>                 funcb
>                 funca
>                 main
>                 __libc_start_main
>                 _start
>                 0
>
>      40.78%  test_dwarf_unwi  [vdso]             [.] 0x0000000000000987
>              |
>              ---0x7ffe28ab7987
>                 __vdso_gettimeofday
>                 funcc
>                 funcb
>                 funca
>                 main
>                 __libc_start_main
>                 _start
>                 0
>
>
> what kernel do you have?

My kernel is 4.3-rc4.

Please see my reply to Ingo. It is possible a problem related
to hardware and PEBS? Maybe on your system perf never capture
samples on 'callq'? I tested 'cycle' and 'cycle:p', can't get
such samples. Only 'cycles:pp' (the default event) have this
problem.

Thank you.

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [standalone]

csiph-web

[BUG REPORT] perf tools: x86_64: Broken calllchain when sampling taken at 'callq' instruction

Contents

#1271890 — [BUG REPORT] perf tools: x86_64: Broken calllchain when sampling taken at 'callq' instruction

#1271915

#1271923

#1271960

#1272877

#1272879

#1273003

#1273019

#1273055

#1273057

#1278625

#1279729

#1272003

#1271944

#1272013