[PATCH] ftrace/x86: Fix function graph tracer reset path

[PATCH] ftrace/x86: Fix function graph tracer reset path

[Namhyung Kim]

On my system, simply enabling and disabling function graph tracer can
crash the kernel.  I don't know how it worked until now.

The ftrace_disable_ftrace_graph_caller() modifies jmp instruction at
ftrace_graph_call assuming it's a 5 bytes near jmp (e9 <offset>).
However it's a short jmp consisting of 2 bytes only (eb <offset>).  And
ftrace_stub() is located just below the ftrace_graph_caller so
modification above breaks the instruction resulting in kernel oops on
the ftrace_stub() with the invalid opcode like below:

  # cd /sys/kernel/trace
  # echo function_graph > current_tracer
  # echo nop > current_tracer

  [   78.122055] invalid opcode: 0000 [#1] SMP
  [   78.125125] Modules linked in: x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32c_intel pcspkr iwldvm iwlwifi
  [   78.128241] CPU: 2 PID: 17 Comm: migration/2 Not tainted 4.6.0-rc4+ #36
  [   78.131310] Hardware name: LENOVO 4286A74/4286A74, BIOS 8DET56WW (1.26 ) 12/01/2011
  [   78.134369] task: ffff88040bec4240 ti: ffff88040bee4000 task.ti: ffff88040bee4000
  [   78.137412] RIP: 0010:[<ffffffff818939a8>]  [<ffffffff818939a8>] ftrace_stub+0x0/0x8
  [   78.140477] RSP: 0018:ffff88040bee7e48  EFLAGS: 00010246
  [   78.143489] RAX: ffff88040bec4240 RBX: ffffffff8107a7b0 RCX: 000000000000001f
  [   78.146512] RDX: 0000000000000000 RSI: ffff88041e2929d8 RDI: ffff88040bee7e50
  [   78.149581] RBP: ffff88040bee7e80 R08: ffff88040bee4000 R09: 0000000000000000
  [   78.152647] R10: 00000000000318b7 R11: ffff8800d661f800 R12: ffff88040d8011b0
  [   78.155679] R13: ffffffff81e43620 R14: ffff88040bda8588 R15: ffffffff81e503e0
  [   78.158675] FS:  0000000000000000(0000) GS:ffff88041e280000(0000) knlGS:0000000000000000
  [   78.161699] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
  [   78.164690] CR2: 00007fadb22dde1d CR3: 00000000d5ce2000 CR4: 00000000000406e0
  [   78.167691] Stack:
  [   78.170658]  ffffffff8110b3ee ffffffff8188de90 00000009161d55f6 00000012306fc2e4
  [   78.173710]  0000000000000000 ffff880400000000 ffff88040bec4240 ffff88040bee7ec8
  [   78.176783]  ffffffff81893bbd 0000000000000000 ffff88040bec4240 ffffffff81893ba8
  [   78.179863] Call Trace:
  [   78.182853]  [<ffffffff8110b3ee>] ? ftrace_return_to_handler+0x8e/0x100
  [   78.185909]  [<ffffffff8188de90>] ? __schedule+0xae0/0xae0
  [   78.188941]  [<ffffffff81893bbd>] return_to_handler+0x15/0x27
  [   78.192001]  [<ffffffff81893ba8>] ? ftrace_graph_caller+0xa8/0xa8
  [   78.195091]  [<ffffffff8107a6f0>] ? sort_range+0x30/0x30
  [   78.198138]  [<ffffffff810778a9>] kthread+0xc9/0xe0
  [   78.201143]  [<ffffffff81891a12>] ret_from_fork+0x22/0x40
  [   78.204138]  [<ffffffff810777e0>] ? kthread_worker_fn+0x170/0x170
  [   78.207129] Code: 8b 44 24 48 48 8b 7c 24 70 48 8b 74 24 68 48 8b 54 24 60
                       48 8b 4c 24 58 48 8b 44 24 50 48 8b 6c 24 20 48 81 c4 d0
                       00 00 00 e9 fd <ff> ff ff 80 00 00 00 00 9c 55 ff 74 24 18
                       55 48 89 e5 ff 74 24
  [   78.213997] RIP  [<ffffffff818939a8>] ftrace_stub+0x0/0x8
  [   78.217190]  RSP <ffff88040bee7e48>
  [   78.220374] ---[ end trace 0af2f0d9f7301011 ]---

Looking at the code dump, the ftrace_stub instruction was overwritten as
<ff>.  Below is disassembly output of related code.

  $ objdump -d --start-address=0xffffffff818939a6 --stop-address=0xffffffff818939b0 vmlinux

  vmlinux:     file format elf64-x86-64

  Disassembly of section .text:

  ffffffff818939a6 <ftrace_epilogue>:
  ffffffff818939a6:	eb 00			jmp    ffffffff818939a8 <ftrace_stub>

  ffffffff818939a8 <ftrace_stub>:
  ffffffff818939a8:	c3			retq
  ffffffff818939a9:	0f 1f 80 00 00 00 00 	nopl   0x0(%rax)

As you can see ftrace_epilogue (same as ftrace_graph_caller) is 2 byte
ahead of ftrace_stub.  And it's replaced by a jump to ftrace_stub() by
ftrace_disable_ftrace_graph_caller: "e9 <0xfffffffd>".  Pads 3 bytes
after ftrace_epilogue to prevent ftrace_stub from being overwritten.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 arch/x86/kernel/mcount_64.S | 9 +++++++++
 1 file changed, 9 insertions(+)

diff --git a/arch/x86/kernel/mcount_64.S b/arch/x86/kernel/mcount_64.S
index ed48a9f465f8..0e6af57a713a 100644
--- a/arch/x86/kernel/mcount_64.S
+++ b/arch/x86/kernel/mcount_64.S
@@ -180,6 +180,15 @@ GLOBAL(ftrace_epilogue)
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 GLOBAL(ftrace_graph_call)
 	jmp ftrace_stub
+	/*
+	 * The above jmp is generated as a short jump which occupies 2 bytes
+	 * but ftrace_enable/disable_ftrace_graph_caller() assumes it's a
+	 * near jump which occupies 5 bytes so breaks ftrace_stub() below.
+	 * Add 3 bytes padding to avoid that.
+	 */
+	nop
+	nop
+	nop
 #endif
 
 GLOBAL(ftrace_stub)
-- 
2.8.0

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Steven Rostedt]

Matt,

This bug looks very similar to what you were hitting with the function
profiler. Can you apply this patch and see if it fixes the issue for
you.

Thanks!

-- Steve


On Fri, 13 May 2016 22:53:43 +0900
Namhyung Kim <namhyung@kernel.org> wrote:

> On my system, simply enabling and disabling function graph tracer can
> crash the kernel.  I don't know how it worked until now.
> 
> The ftrace_disable_ftrace_graph_caller() modifies jmp instruction at
> ftrace_graph_call assuming it's a 5 bytes near jmp (e9 <offset>).
> However it's a short jmp consisting of 2 bytes only (eb <offset>).  And
> ftrace_stub() is located just below the ftrace_graph_caller so
> modification above breaks the instruction resulting in kernel oops on
> the ftrace_stub() with the invalid opcode like below:
> 
>   # cd /sys/kernel/trace
>   # echo function_graph > current_tracer
>   # echo nop > current_tracer
> 
>   [   78.122055] invalid opcode: 0000 [#1] SMP
>   [   78.125125] Modules linked in: x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32c_intel pcspkr iwldvm iwlwifi
>   [   78.128241] CPU: 2 PID: 17 Comm: migration/2 Not tainted 4.6.0-rc4+ #36
>   [   78.131310] Hardware name: LENOVO 4286A74/4286A74, BIOS 8DET56WW (1.26 ) 12/01/2011
>   [   78.134369] task: ffff88040bec4240 ti: ffff88040bee4000 task.ti: ffff88040bee4000
>   [   78.137412] RIP: 0010:[<ffffffff818939a8>]  [<ffffffff818939a8>] ftrace_stub+0x0/0x8
>   [   78.140477] RSP: 0018:ffff88040bee7e48  EFLAGS: 00010246
>   [   78.143489] RAX: ffff88040bec4240 RBX: ffffffff8107a7b0 RCX: 000000000000001f
>   [   78.146512] RDX: 0000000000000000 RSI: ffff88041e2929d8 RDI: ffff88040bee7e50
>   [   78.149581] RBP: ffff88040bee7e80 R08: ffff88040bee4000 R09: 0000000000000000
>   [   78.152647] R10: 00000000000318b7 R11: ffff8800d661f800 R12: ffff88040d8011b0
>   [   78.155679] R13: ffffffff81e43620 R14: ffff88040bda8588 R15: ffffffff81e503e0
>   [   78.158675] FS:  0000000000000000(0000) GS:ffff88041e280000(0000) knlGS:0000000000000000
>   [   78.161699] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>   [   78.164690] CR2: 00007fadb22dde1d CR3: 00000000d5ce2000 CR4: 00000000000406e0
>   [   78.167691] Stack:
>   [   78.170658]  ffffffff8110b3ee ffffffff8188de90 00000009161d55f6 00000012306fc2e4
>   [   78.173710]  0000000000000000 ffff880400000000 ffff88040bec4240 ffff88040bee7ec8
>   [   78.176783]  ffffffff81893bbd 0000000000000000 ffff88040bec4240 ffffffff81893ba8
>   [   78.179863] Call Trace:
>   [   78.182853]  [<ffffffff8110b3ee>] ? ftrace_return_to_handler+0x8e/0x100
>   [   78.185909]  [<ffffffff8188de90>] ? __schedule+0xae0/0xae0
>   [   78.188941]  [<ffffffff81893bbd>] return_to_handler+0x15/0x27
>   [   78.192001]  [<ffffffff81893ba8>] ? ftrace_graph_caller+0xa8/0xa8
>   [   78.195091]  [<ffffffff8107a6f0>] ? sort_range+0x30/0x30
>   [   78.198138]  [<ffffffff810778a9>] kthread+0xc9/0xe0
>   [   78.201143]  [<ffffffff81891a12>] ret_from_fork+0x22/0x40
>   [   78.204138]  [<ffffffff810777e0>] ? kthread_worker_fn+0x170/0x170
>   [   78.207129] Code: 8b 44 24 48 48 8b 7c 24 70 48 8b 74 24 68 48 8b 54 24 60
>                        48 8b 4c 24 58 48 8b 44 24 50 48 8b 6c 24 20 48 81 c4 d0
>                        00 00 00 e9 fd <ff> ff ff 80 00 00 00 00 9c 55 ff 74 24 18
>                        55 48 89 e5 ff 74 24
>   [   78.213997] RIP  [<ffffffff818939a8>] ftrace_stub+0x0/0x8
>   [   78.217190]  RSP <ffff88040bee7e48>
>   [   78.220374] ---[ end trace 0af2f0d9f7301011 ]---
> 
> Looking at the code dump, the ftrace_stub instruction was overwritten as
> <ff>.  Below is disassembly output of related code.
> 
>   $ objdump -d --start-address=0xffffffff818939a6 --stop-address=0xffffffff818939b0 vmlinux
> 
>   vmlinux:     file format elf64-x86-64
> 
>   Disassembly of section .text:
> 
>   ffffffff818939a6 <ftrace_epilogue>:
>   ffffffff818939a6:	eb 00			jmp    ffffffff818939a8 <ftrace_stub>
> 
>   ffffffff818939a8 <ftrace_stub>:
>   ffffffff818939a8:	c3			retq
>   ffffffff818939a9:	0f 1f 80 00 00 00 00 	nopl   0x0(%rax)
> 
> As you can see ftrace_epilogue (same as ftrace_graph_caller) is 2 byte
> ahead of ftrace_stub.  And it's replaced by a jump to ftrace_stub() by
> ftrace_disable_ftrace_graph_caller: "e9 <0xfffffffd>".  Pads 3 bytes
> after ftrace_epilogue to prevent ftrace_stub from being overwritten.
> 
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  arch/x86/kernel/mcount_64.S | 9 +++++++++
>  1 file changed, 9 insertions(+)
> 
> diff --git a/arch/x86/kernel/mcount_64.S b/arch/x86/kernel/mcount_64.S
> index ed48a9f465f8..0e6af57a713a 100644
> --- a/arch/x86/kernel/mcount_64.S
> +++ b/arch/x86/kernel/mcount_64.S
> @@ -180,6 +180,15 @@ GLOBAL(ftrace_epilogue)
>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
>  GLOBAL(ftrace_graph_call)
>  	jmp ftrace_stub
> +	/*
> +	 * The above jmp is generated as a short jump which occupies 2 bytes
> +	 * but ftrace_enable/disable_ftrace_graph_caller() assumes it's a
> +	 * near jump which occupies 5 bytes so breaks ftrace_stub() below.
> +	 * Add 3 bytes padding to avoid that.
> +	 */
> +	nop
> +	nop
> +	nop
>  #endif
>  
>  GLOBAL(ftrace_stub)

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Masami Hiramatsu]

Hi Namhyung,

I'm interested in this problem, and it seems compiling environment
related or kconfig related problem.
If you can reproduce this kernel, would you share what the "AS"
commandline shows? That can be done as below;

 $ make V=1 arch/x86/kernel/mcount_64.o | grep mcount_64

Thank you,

On Fri, 13 May 2016 22:53:43 +0900
Namhyung Kim <namhyung@kernel.org> wrote:

> On my system, simply enabling and disabling function graph tracer can
> crash the kernel.  I don't know how it worked until now.
> 
> The ftrace_disable_ftrace_graph_caller() modifies jmp instruction at
> ftrace_graph_call assuming it's a 5 bytes near jmp (e9 <offset>).
> However it's a short jmp consisting of 2 bytes only (eb <offset>).  And
> ftrace_stub() is located just below the ftrace_graph_caller so
> modification above breaks the instruction resulting in kernel oops on
> the ftrace_stub() with the invalid opcode like below:
> 
>   # cd /sys/kernel/trace
>   # echo function_graph > current_tracer
>   # echo nop > current_tracer
> 
>   [   78.122055] invalid opcode: 0000 [#1] SMP
>   [   78.125125] Modules linked in: x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32c_intel pcspkr iwldvm iwlwifi
>   [   78.128241] CPU: 2 PID: 17 Comm: migration/2 Not tainted 4.6.0-rc4+ #36
>   [   78.131310] Hardware name: LENOVO 4286A74/4286A74, BIOS 8DET56WW (1.26 ) 12/01/2011
>   [   78.134369] task: ffff88040bec4240 ti: ffff88040bee4000 task.ti: ffff88040bee4000
>   [   78.137412] RIP: 0010:[<ffffffff818939a8>]  [<ffffffff818939a8>] ftrace_stub+0x0/0x8
>   [   78.140477] RSP: 0018:ffff88040bee7e48  EFLAGS: 00010246
>   [   78.143489] RAX: ffff88040bec4240 RBX: ffffffff8107a7b0 RCX: 000000000000001f
>   [   78.146512] RDX: 0000000000000000 RSI: ffff88041e2929d8 RDI: ffff88040bee7e50
>   [   78.149581] RBP: ffff88040bee7e80 R08: ffff88040bee4000 R09: 0000000000000000
>   [   78.152647] R10: 00000000000318b7 R11: ffff8800d661f800 R12: ffff88040d8011b0
>   [   78.155679] R13: ffffffff81e43620 R14: ffff88040bda8588 R15: ffffffff81e503e0
>   [   78.158675] FS:  0000000000000000(0000) GS:ffff88041e280000(0000) knlGS:0000000000000000
>   [   78.161699] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>   [   78.164690] CR2: 00007fadb22dde1d CR3: 00000000d5ce2000 CR4: 00000000000406e0
>   [   78.167691] Stack:
>   [   78.170658]  ffffffff8110b3ee ffffffff8188de90 00000009161d55f6 00000012306fc2e4
>   [   78.173710]  0000000000000000 ffff880400000000 ffff88040bec4240 ffff88040bee7ec8
>   [   78.176783]  ffffffff81893bbd 0000000000000000 ffff88040bec4240 ffffffff81893ba8
>   [   78.179863] Call Trace:
>   [   78.182853]  [<ffffffff8110b3ee>] ? ftrace_return_to_handler+0x8e/0x100
>   [   78.185909]  [<ffffffff8188de90>] ? __schedule+0xae0/0xae0
>   [   78.188941]  [<ffffffff81893bbd>] return_to_handler+0x15/0x27
>   [   78.192001]  [<ffffffff81893ba8>] ? ftrace_graph_caller+0xa8/0xa8
>   [   78.195091]  [<ffffffff8107a6f0>] ? sort_range+0x30/0x30
>   [   78.198138]  [<ffffffff810778a9>] kthread+0xc9/0xe0
>   [   78.201143]  [<ffffffff81891a12>] ret_from_fork+0x22/0x40
>   [   78.204138]  [<ffffffff810777e0>] ? kthread_worker_fn+0x170/0x170
>   [   78.207129] Code: 8b 44 24 48 48 8b 7c 24 70 48 8b 74 24 68 48 8b 54 24 60
>                        48 8b 4c 24 58 48 8b 44 24 50 48 8b 6c 24 20 48 81 c4 d0
>                        00 00 00 e9 fd <ff> ff ff 80 00 00 00 00 9c 55 ff 74 24 18
>                        55 48 89 e5 ff 74 24
>   [   78.213997] RIP  [<ffffffff818939a8>] ftrace_stub+0x0/0x8
>   [   78.217190]  RSP <ffff88040bee7e48>
>   [   78.220374] ---[ end trace 0af2f0d9f7301011 ]---
> 
> Looking at the code dump, the ftrace_stub instruction was overwritten as
> <ff>.  Below is disassembly output of related code.
> 
>   $ objdump -d --start-address=0xffffffff818939a6 --stop-address=0xffffffff818939b0 vmlinux
> 
>   vmlinux:     file format elf64-x86-64
> 
>   Disassembly of section .text:
> 
>   ffffffff818939a6 <ftrace_epilogue>:
>   ffffffff818939a6:	eb 00			jmp    ffffffff818939a8 <ftrace_stub>
> 
>   ffffffff818939a8 <ftrace_stub>:
>   ffffffff818939a8:	c3			retq
>   ffffffff818939a9:	0f 1f 80 00 00 00 00 	nopl   0x0(%rax)
> 
> As you can see ftrace_epilogue (same as ftrace_graph_caller) is 2 byte
> ahead of ftrace_stub.  And it's replaced by a jump to ftrace_stub() by
> ftrace_disable_ftrace_graph_caller: "e9 <0xfffffffd>".  Pads 3 bytes
> after ftrace_epilogue to prevent ftrace_stub from being overwritten.
> 
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  arch/x86/kernel/mcount_64.S | 9 +++++++++
>  1 file changed, 9 insertions(+)
> 
> diff --git a/arch/x86/kernel/mcount_64.S b/arch/x86/kernel/mcount_64.S
> index ed48a9f465f8..0e6af57a713a 100644
> --- a/arch/x86/kernel/mcount_64.S
> +++ b/arch/x86/kernel/mcount_64.S
> @@ -180,6 +180,15 @@ GLOBAL(ftrace_epilogue)
>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
>  GLOBAL(ftrace_graph_call)
>  	jmp ftrace_stub
> +	/*
> +	 * The above jmp is generated as a short jump which occupies 2 bytes
> +	 * but ftrace_enable/disable_ftrace_graph_caller() assumes it's a
> +	 * near jump which occupies 5 bytes so breaks ftrace_stub() below.
> +	 * Add 3 bytes padding to avoid that.
> +	 */
> +	nop
> +	nop
> +	nop
>  #endif
>  
>  GLOBAL(ftrace_stub)
> -- 
> 2.8.0
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Namhyung Kim]

On Sun, May 15, 2016 at 09:41:41AM +0900, Masami Hiramatsu wrote:

Hi Masami,

> Hi Namhyung,
> 
> I'm interested in this problem, and it seems compiling environment
> related or kconfig related problem.
> If you can reproduce this kernel, would you share what the "AS"
> commandline shows? That can be done as below;
> 
>  $ make V=1 arch/x86/kernel/mcount_64.o | grep mcount_64

  gcc -Wp,-MD,arch/x86/kernel/.mcount_64.o.d  -nostdinc -isystem /usr/lib/gcc/x86_64-unknown-linux-gnu/5.3.0/include -I/home/namhyung/project/linux/arch/x86/include -Iarch/x86/include/generated/uapi -Iarch/x86/include/generated  -I/home/namhyung/project/linux/include -Iinclude -I/home/namhyung/project/linux/arch/x86/include/uapi -Iarch/x86/include/generated/uapi -I/home/namhyung/project/linux/include/uapi -Iinclude/generated/uapi -include /home/namhyung/project/linux/include/linux/kconfig.h -D__KERNEL__ -D__ASSEMBLY__ -m64 -DCONFIG_AS_CFI=1 -DCONFIG_AS_CFI_SIGNAL_FRAME=1 -DCONFIG_AS_CFI_SECTIONS=1 -DCONFIG_AS_FXSAVEQ=1 -DCONFIG_AS_SSSE3=1 -DCONFIG_AS_CRC32=1 -DCONFIG_AS_AVX=1 -DCONFIG_AS_AVX2=1 -DCONFIG_AS_SHA1_NI=1 -DCONFIG_AS_SHA256_NI=1 -mfentry -DCC_USING_FENTRY -DCC_HAVE_ASM_GOTO   -c -o arch/x86/kernel/mcount_64.o /home/namhyung/project/linux/arch/x86/kernel/mcount_64.S


  $ gcc --version
  gcc (GCC) 5.3.0
  Copyright (C) 2015 Free Software Foundation, Inc.
  This is free software; see the source for copying conditions.  There is NO
  warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

  $ as --version
  GNU assembler (GNU Binutils) 2.26.0.20160302
  Copyright (C) 2015 Free Software Foundation, Inc.
  This program is free software; you may redistribute it under the terms of
  the GNU General Public License version 3 or later.
  This program has absolutely no warranty.
  This assembler was configured for a target of `x86_64-pc-linux-gnu'.


Thanks,
Namhyung

> 
> Thank you,
> 
> On Fri, 13 May 2016 22:53:43 +0900
> Namhyung Kim <namhyung@kernel.org> wrote:
> 
> > On my system, simply enabling and disabling function graph tracer can
> > crash the kernel.  I don't know how it worked until now.
> > 
> > The ftrace_disable_ftrace_graph_caller() modifies jmp instruction at
> > ftrace_graph_call assuming it's a 5 bytes near jmp (e9 <offset>).
> > However it's a short jmp consisting of 2 bytes only (eb <offset>).  And
> > ftrace_stub() is located just below the ftrace_graph_caller so
> > modification above breaks the instruction resulting in kernel oops on
> > the ftrace_stub() with the invalid opcode like below:
> > 
> >   # cd /sys/kernel/trace
> >   # echo function_graph > current_tracer
> >   # echo nop > current_tracer
> > 
> >   [   78.122055] invalid opcode: 0000 [#1] SMP
> >   [   78.125125] Modules linked in: x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32c_intel pcspkr iwldvm iwlwifi
> >   [   78.128241] CPU: 2 PID: 17 Comm: migration/2 Not tainted 4.6.0-rc4+ #36
> >   [   78.131310] Hardware name: LENOVO 4286A74/4286A74, BIOS 8DET56WW (1.26 ) 12/01/2011
> >   [   78.134369] task: ffff88040bec4240 ti: ffff88040bee4000 task.ti: ffff88040bee4000
> >   [   78.137412] RIP: 0010:[<ffffffff818939a8>]  [<ffffffff818939a8>] ftrace_stub+0x0/0x8
> >   [   78.140477] RSP: 0018:ffff88040bee7e48  EFLAGS: 00010246
> >   [   78.143489] RAX: ffff88040bec4240 RBX: ffffffff8107a7b0 RCX: 000000000000001f
> >   [   78.146512] RDX: 0000000000000000 RSI: ffff88041e2929d8 RDI: ffff88040bee7e50
> >   [   78.149581] RBP: ffff88040bee7e80 R08: ffff88040bee4000 R09: 0000000000000000
> >   [   78.152647] R10: 00000000000318b7 R11: ffff8800d661f800 R12: ffff88040d8011b0
> >   [   78.155679] R13: ffffffff81e43620 R14: ffff88040bda8588 R15: ffffffff81e503e0
> >   [   78.158675] FS:  0000000000000000(0000) GS:ffff88041e280000(0000) knlGS:0000000000000000
> >   [   78.161699] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> >   [   78.164690] CR2: 00007fadb22dde1d CR3: 00000000d5ce2000 CR4: 00000000000406e0
> >   [   78.167691] Stack:
> >   [   78.170658]  ffffffff8110b3ee ffffffff8188de90 00000009161d55f6 00000012306fc2e4
> >   [   78.173710]  0000000000000000 ffff880400000000 ffff88040bec4240 ffff88040bee7ec8
> >   [   78.176783]  ffffffff81893bbd 0000000000000000 ffff88040bec4240 ffffffff81893ba8
> >   [   78.179863] Call Trace:
> >   [   78.182853]  [<ffffffff8110b3ee>] ? ftrace_return_to_handler+0x8e/0x100
> >   [   78.185909]  [<ffffffff8188de90>] ? __schedule+0xae0/0xae0
> >   [   78.188941]  [<ffffffff81893bbd>] return_to_handler+0x15/0x27
> >   [   78.192001]  [<ffffffff81893ba8>] ? ftrace_graph_caller+0xa8/0xa8
> >   [   78.195091]  [<ffffffff8107a6f0>] ? sort_range+0x30/0x30
> >   [   78.198138]  [<ffffffff810778a9>] kthread+0xc9/0xe0
> >   [   78.201143]  [<ffffffff81891a12>] ret_from_fork+0x22/0x40
> >   [   78.204138]  [<ffffffff810777e0>] ? kthread_worker_fn+0x170/0x170
> >   [   78.207129] Code: 8b 44 24 48 48 8b 7c 24 70 48 8b 74 24 68 48 8b 54 24 60
> >                        48 8b 4c 24 58 48 8b 44 24 50 48 8b 6c 24 20 48 81 c4 d0
> >                        00 00 00 e9 fd <ff> ff ff 80 00 00 00 00 9c 55 ff 74 24 18
> >                        55 48 89 e5 ff 74 24
> >   [   78.213997] RIP  [<ffffffff818939a8>] ftrace_stub+0x0/0x8
> >   [   78.217190]  RSP <ffff88040bee7e48>
> >   [   78.220374] ---[ end trace 0af2f0d9f7301011 ]---
> > 
> > Looking at the code dump, the ftrace_stub instruction was overwritten as
> > <ff>.  Below is disassembly output of related code.
> > 
> >   $ objdump -d --start-address=0xffffffff818939a6 --stop-address=0xffffffff818939b0 vmlinux
> > 
> >   vmlinux:     file format elf64-x86-64
> > 
> >   Disassembly of section .text:
> > 
> >   ffffffff818939a6 <ftrace_epilogue>:
> >   ffffffff818939a6:	eb 00			jmp    ffffffff818939a8 <ftrace_stub>
> > 
> >   ffffffff818939a8 <ftrace_stub>:
> >   ffffffff818939a8:	c3			retq
> >   ffffffff818939a9:	0f 1f 80 00 00 00 00 	nopl   0x0(%rax)
> > 
> > As you can see ftrace_epilogue (same as ftrace_graph_caller) is 2 byte
> > ahead of ftrace_stub.  And it's replaced by a jump to ftrace_stub() by
> > ftrace_disable_ftrace_graph_caller: "e9 <0xfffffffd>".  Pads 3 bytes
> > after ftrace_epilogue to prevent ftrace_stub from being overwritten.
> > 
> > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > ---
> >  arch/x86/kernel/mcount_64.S | 9 +++++++++
> >  1 file changed, 9 insertions(+)
> > 
> > diff --git a/arch/x86/kernel/mcount_64.S b/arch/x86/kernel/mcount_64.S
> > index ed48a9f465f8..0e6af57a713a 100644
> > --- a/arch/x86/kernel/mcount_64.S
> > +++ b/arch/x86/kernel/mcount_64.S
> > @@ -180,6 +180,15 @@ GLOBAL(ftrace_epilogue)
> >  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
> >  GLOBAL(ftrace_graph_call)
> >  	jmp ftrace_stub
> > +	/*
> > +	 * The above jmp is generated as a short jump which occupies 2 bytes
> > +	 * but ftrace_enable/disable_ftrace_graph_caller() assumes it's a
> > +	 * near jump which occupies 5 bytes so breaks ftrace_stub() below.
> > +	 * Add 3 bytes padding to avoid that.
> > +	 */
> > +	nop
> > +	nop
> > +	nop
> >  #endif
> >  
> >  GLOBAL(ftrace_stub)
> > -- 
> > 2.8.0
> > 
> 
> 
> -- 
> Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Matt Fleming]

On Fri, 13 May, at 10:06:10AM, Steven Rostedt wrote:
> Matt,
> 
> This bug looks very similar to what you were hitting with the function
> profiler. Can you apply this patch and see if it fixes the issue for
> you.

Yep, this patch fixes it for me.

For the record, this is what objdump tells me (with patch applied),

00000000000000b6 <ftrace_epilogue>:
  b6:   eb 03                   jmp    bb <ftrace_stub>
  b8:   90                      nop
  b9:   90                      nop
  ba:   90                      nop

So my toolchain is definitely generating a short jump. This is
binutils 2.26.

But on one of my other test machines with binutils 2.24 I see this,

00000000000000aa <ftrace_epilogue>:
  aa:   e9 00 00 00 00          jmpq   af <ftrace_stub>
                        ab: R_X86_64_PC32       ftrace_stub-0x4

i.e. a near jump.

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Namhyung Kim]

On Mon, May 16, 2016 at 05:56:14PM +0900, Masami Hiramatsu wrote:
> On Sun, 15 May 2016 22:06:52 +0900
> Namhyung Kim <namhyung@kernel.org> wrote:
> 
> > On Sun, May 15, 2016 at 09:41:41AM +0900, Masami Hiramatsu wrote:
> > 
> > Hi Masami,
> > 
> > > Hi Namhyung,
> > > 
> > > I'm interested in this problem, and it seems compiling environment
> > > related or kconfig related problem.
> > > If you can reproduce this kernel, would you share what the "AS"
> > > commandline shows? That can be done as below;
> > > 
> > >  $ make V=1 arch/x86/kernel/mcount_64.o | grep mcount_64
> > 
> >   gcc -Wp,-MD,arch/x86/kernel/.mcount_64.o.d  -nostdinc -isystem /usr/lib/gcc/x86_64-unknown-linux-gnu/5.3.0/include -I/home/namhyung/project/linux/arch/x86/include -Iarch/x86/include/generated/uapi -Iarch/x86/include/generated  -I/home/namhyung/project/linux/include -Iinclude -I/home/namhyung/project/linux/arch/x86/include/uapi -Iarch/x86/include/generated/uapi -I/home/namhyung/project/linux/include/uapi -Iinclude/generated/uapi -include /home/namhyung/project/linux/include/linux/kconfig.h -D__KERNEL__ -D__ASSEMBLY__ -m64 -DCONFIG_AS_CFI=1 -DCONFIG_AS_CFI_SIGNAL_FRAME=1 -DCONFIG_AS_CFI_SECTIONS=1 -DCONFIG_AS_FXSAVEQ=1 -DCONFIG_AS_SSSE3=1 -DCONFIG_AS_CRC32=1 -DCONFIG_AS_AVX=1 -DCONFIG_AS_AVX2=1 -DCONFIG_AS_SHA1_NI=1 -DCONFIG_AS_SHA256_NI=1 -mfentry -DCC_USING_FENTRY -DCC_HAVE_ASM_GOTO   -c -o arch/x86/kernel/mcount_64.o /home/namhyung/project/linux/arch/x86/kernel/mcount_64.S
> 
> Thanks! I could reproduced on Ubuntu 16.04 which has gcc-5.3.1/as-2.26.
> On the other hand, on Fedora21(gcc 4.9.2/as-2.24) with same kconfig,
> I didn't see such short jump.
> 
> OK, I did bisect binutils and found below commit caused it ;D

Thanks for doing this!

> 
> 8dcea93252a9ea7dff57e85220a719e2a5e8ab41 is the first bad commit
> commit 8dcea93252a9ea7dff57e85220a719e2a5e8ab41
> Author: H.J. Lu <hjl.tools@gmail.com>
> Date:   Fri May 15 03:17:31 2015 -0700
> 
>     Add -mshared option to x86 ELF assembler
>     
>     This patch adds -mshared option to x86 ELF assembler.  By default,
>     assembler will optimize out non-PLT relocations against defined non-weak
>     global branch targets with default visibility.  The -mshared option tells
>     the assembler to generate code which may go into a shared library
>     where all non-weak global branch targets with default visibility can
>     be preempted.  The resulting code is slightly bigger.  This option
>     only affects the handling of branch instructions.
>     
>     This Linux kernel patch is needed to create a working x86 Linux kernel if
>     it hasn't been applied:
>     
>     diff --git a/arch/x86/kernel/head_64.S b/arch/x86/kernel/head_64.S
>     index ae6588b..b91a00c 100644
>     --- a/arch/x86/kernel/head_64.S
>     +++ b/arch/x86/kernel/head_64.S
>     @@ -339,8 +339,8 @@ early_idt_handlers:
>      	i = i + 1
>      	.endr
>     
>     -/* This is global to keep gas from relaxing the jumps */
>     -ENTRY(early_idt_handler)
>     +/* This is weak to keep gas from relaxing the jumps */
>     +WEAK(early_idt_handler)
>      	cld
>     
>      	cmpl $2,(%rsp)		# X86_TRAP_NMI
>     --
>     
>     gas/
>     
>     	* config/tc-i386.c (shared): New.
>     	(OPTION_MSHARED): Likewise.
>     	(elf_symbol_resolved_in_segment_p): Add relocation argument.
>     	Check PLT relocations and shared.
>     	(md_estimate_size_before_relax): Pass fragP->fr_var to
>     	elf_symbol_resolved_in_segment_p.
>     	(md_longopts): Add -mshared.
>     	(md_show_usage): Likewise.
>     	(md_parse_option): Handle OPTION_MSHARED.
>     	* doc/c-i386.texi: Document -mshared.
>     
>     gas/testsuite/
>     
>     	* gas/i386/i386.exp: Don't run pcrel for ELF targets.  Run
>     	pcrel-elf, relax-4 and x86-64-relax-3 for ELF targets.
>     	* gas/i386/pcrel-elf.d: New file.
>     	* gas/i386/relax-4.d: Likewise.
>     	* gas/i386/x86-64-relax-3.d: Likewise.
>     	* gas/i386/relax-3.d: Pass -mshared to assembler.  Updated.
>     	* gas/i386/x86-64-relax-2.d: Likewise.
>     	* gas/i386/relax-3.s: Add test for PLT relocation.
> 
> :040000 040000 e6c503c04807ae3ca8e74c78f6531050272923ba 8b4f3af73c6a3bac007faa5fe40ac22d45b8fa9f M	gas
> 
> 
> And I found that as above commit said, if we passed the -mshared option to
> gas ("-Wa,-mshared") as I did below, gas generated 5 byte jump again.

So IIUC, this -mshared option disables the optimization on branch
instructions and generates slightly bigger code.  Not sure how much
affected by this though.

Steve, do you think it's better to use this option?

Thanks,
Namhyung


> 
> 
> gcc -Wp,-MD,arch/x86/kernel/.mcount_64.o.d  -nostdinc -isystem /usr/lib/gcc/x86_64-redhat-linux/4.9.2/include -I/home/mhiramat/ksrc/linux/arch/x86/include -Iarch/x86/include/generated/uapi -Iarch/x86/include/generated  -I/home/mhiramat/ksrc/linux/include -Iinclude -I/home/mhiramat/ksrc/linux/arch/x86/include/uapi -Iarch/x86/include/generated/uapi -I/home/mhiramat/ksrc/linux/include/uapi -Iinclude/generated/uapi -include /home/mhiramat/ksrc/linux/include/linux/kconfig.h -D__KERNEL__ -D__ASSEMBLY__ -m64 -DCONFIG_AS_CFI=1 -DCONFIG_AS_CFI_SIGNAL_FRAME=1 -DCONFIG_AS_CFI_SECTIONS=1 -DCONFIG_AS_FXSAVEQ=1 -DCONFIG_AS_SSSE3=1 -DCONFIG_AS_CRC32=1 -DCONFIG_AS_AVX=1 -DCONFIG_AS_AVX2=1 -DCONFIG_AS_SHA1_NI=1 -DCONFIG_AS_SHA256_NI=1 -mfentry -DCC_USING_FENTRY -DCC_HAVE_ASM_GOTO -Wa,-mshared  -c -o arch/x86/kernel/mcount_64.o /home/mhiramat/ksrc/linux/arch/x86/kernel/mcount_64.S
> 
> 
> 
> 00000000000000b6 <ftrace_epilogue>:
>   b6:   e9 00 00 00 00          jmpq   bb <ftrace_stub>
> 
> 00000000000000bb <ftrace_stub>:
>   bb:   c3                      retq   
>   bc:   0f 1f 40 00             nopl   0x0(%rax)
> 
> 
> Thank you,
> 
> -- 
> Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Steven Rostedt]

Nice work Masami!

On Mon, 16 May 2016 21:32:50 +0900
Namhyung Kim <namhyung@kernel.org> wrote:

    
> >     -/* This is global to keep gas from relaxing the jumps */
> >     -ENTRY(early_idt_handler)
> >     +/* This is weak to keep gas from relaxing the jumps */
> >     +WEAK(early_idt_handler)
> >      	cld

> So IIUC, this -mshared option disables the optimization on branch
> instructions and generates slightly bigger code.  Not sure how much
> affected by this though.
> 
> Steve, do you think it's better to use this option?

Can we solve this by doing the same thing it did for the kernel?

-- Steve

diff --git a/arch/x86/kernel/mcount_64.S b/arch/x86/kernel/mcount_64.S
index ed48a9f465f8..e13a695c3084 100644
--- a/arch/x86/kernel/mcount_64.S
+++ b/arch/x86/kernel/mcount_64.S
@@ -182,7 +182,8 @@ GLOBAL(ftrace_graph_call)
 	jmp ftrace_stub
 #endif
 
-GLOBAL(ftrace_stub)
+/* This is weak to keep gas from relaxing the jumps */
+WEAK(ftrace_stub)
 	retq
 END(ftrace_caller)
 

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Namhyung Kim]

Hi Steve,

On Mon, May 16, 2016 at 09:58:33AM -0400, Steven Rostedt wrote:
> 
> Nice work Masami!
> 
> On Mon, 16 May 2016 21:32:50 +0900
> Namhyung Kim <namhyung@kernel.org> wrote:
> 
>     
> > >     -/* This is global to keep gas from relaxing the jumps */
> > >     -ENTRY(early_idt_handler)
> > >     +/* This is weak to keep gas from relaxing the jumps */
> > >     +WEAK(early_idt_handler)
> > >      	cld
> 
> > So IIUC, this -mshared option disables the optimization on branch
> > instructions and generates slightly bigger code.  Not sure how much
> > affected by this though.
> > 
> > Steve, do you think it's better to use this option?
> 
> Can we solve this by doing the same thing it did for the kernel?

Yes, it fixes my problem.

Thanks,
Namhyung


> 
> diff --git a/arch/x86/kernel/mcount_64.S b/arch/x86/kernel/mcount_64.S
> index ed48a9f465f8..e13a695c3084 100644
> --- a/arch/x86/kernel/mcount_64.S
> +++ b/arch/x86/kernel/mcount_64.S
> @@ -182,7 +182,8 @@ GLOBAL(ftrace_graph_call)
>  	jmp ftrace_stub
>  #endif
>  
> -GLOBAL(ftrace_stub)
> +/* This is weak to keep gas from relaxing the jumps */
> +WEAK(ftrace_stub)
>  	retq
>  END(ftrace_caller)
>  

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Borislav Petkov]

On Mon, May 16, 2016 at 11:24:53PM +0900, Namhyung Kim wrote:
> > -GLOBAL(ftrace_stub)
> > +/* This is weak to keep gas from relaxing the jumps */
> > +WEAK(ftrace_stub)
> >  	retq
> >  END(ftrace_caller)

You could also force the 5-byte jump. I guess you could also write
simply ".long 0" in there but this way it is more robust if someone
decides to add other stuff between the JMP and the ftrace_stub label.

---
diff --git a/arch/x86/kernel/mcount_64.S b/arch/x86/kernel/mcount_64.S
index ed48a9f465f8..b1db8a584c06 100644
--- a/arch/x86/kernel/mcount_64.S
+++ b/arch/x86/kernel/mcount_64.S
@@ -179,7 +179,9 @@ GLOBAL(ftrace_epilogue)
 
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 GLOBAL(ftrace_graph_call)
-	jmp ftrace_stub
+	.byte 0xe9
+	.long ftrace_stub - 1f
+1:
 #endif
 
 GLOBAL(ftrace_stub)

-- 
Regards/Gruss,
    Boris.

SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton, HRB 21284 (AG Nürnberg)
-- 

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Steven Rostedt]

On Mon, 16 May 2016 21:03:59 +0200
Borislav Petkov <bp@suse.de> wrote:

> On Mon, May 16, 2016 at 11:24:53PM +0900, Namhyung Kim wrote:
> > > -GLOBAL(ftrace_stub)
> > > +/* This is weak to keep gas from relaxing the jumps */
> > > +WEAK(ftrace_stub)
> > >  	retq
> > >  END(ftrace_caller)  
> 
> You could also force the 5-byte jump. I guess you could also write
> simply ".long 0" in there but this way it is more robust if someone
> decides to add other stuff between the JMP and the ftrace_stub label.
> 
> ---
> diff --git a/arch/x86/kernel/mcount_64.S b/arch/x86/kernel/mcount_64.S
> index ed48a9f465f8..b1db8a584c06 100644
> --- a/arch/x86/kernel/mcount_64.S
> +++ b/arch/x86/kernel/mcount_64.S
> @@ -179,7 +179,9 @@ GLOBAL(ftrace_epilogue)
>  
>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
>  GLOBAL(ftrace_graph_call)
> -	jmp ftrace_stub
> +	.byte 0xe9
> +	.long ftrace_stub - 1f
> +1:
>  #endif
>  

I actually thought about this first, but I thought it rather a hack
(although one could argue all of function tracing is a hack ;-) But as
the "weak" call was used to fix one location, why not use it here too.
Being consistent, and also making sure all calls to ftrace_stub do the
same.

-- Steve

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Borislav Petkov]

On Mon, May 16, 2016 at 03:13:57PM -0400, Steven Rostedt wrote:
> I actually thought about this first, but I thought it rather a hack
> (although one could argue all of function tracing is a hack ;-)

... I was about to say...

> But as the "weak" call was used to fix one location, why not use
> it here too. Being consistent, and also making sure all calls to
> ftrace_stub do the same.

Btw, arch_static_branch_jump() spells that 5-byte JMP too and not until
too long ago we had it in static_cpu_has()...

I guess after spending some time with the kernel, one can't really
differentiate hacks from proper design anymore. :-P

-- 
Regards/Gruss,
    Boris.

SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton, HRB 21284 (AG Nürnberg)
-- 

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Steven Rostedt]

On Mon, 16 May 2016 21:19:18 +0200
Borislav Petkov <bp@suse.de> wrote:

> Btw, arch_static_branch_jump() spells that 5-byte JMP too and not until
> too long ago we had it in static_cpu_has()...

Those are "special" too.

If we can get the compiler to do the Right Thing (TM) then we should
let it.

> 
> I guess after spending some time with the kernel, one can't really
> differentiate hacks from proper design anymore. :-P
> 

That's because a quality of a kernel is determined by the
maintainability of all its hacks, not lack of them.

-- Steve

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Matt Fleming]

On Mon, 16 May, at 09:58:33AM, Steven Rostedt wrote:
> 
> Can we solve this by doing the same thing it did for the kernel?
> 
> -- Steve
> 
> diff --git a/arch/x86/kernel/mcount_64.S b/arch/x86/kernel/mcount_64.S
> index ed48a9f465f8..e13a695c3084 100644
> --- a/arch/x86/kernel/mcount_64.S
> +++ b/arch/x86/kernel/mcount_64.S
> @@ -182,7 +182,8 @@ GLOBAL(ftrace_graph_call)
>  	jmp ftrace_stub
>  #endif
>  
> -GLOBAL(ftrace_stub)
> +/* This is weak to keep gas from relaxing the jumps */
> +WEAK(ftrace_stub)
>  	retq
>  END(ftrace_caller)
  
Works for me.

Tested-by: Matt Fleming <matt@codeblueprint.co.uk>

Re: [PATCH] ftrace/x86: Fix function graph tracer reset path

[Masami Hiramatsu]

On Mon, 16 May 2016 09:58:33 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> Nice work Masami!
> 
> On Mon, 16 May 2016 21:32:50 +0900
> Namhyung Kim <namhyung@kernel.org> wrote:
> 
>     
> > >     -/* This is global to keep gas from relaxing the jumps */
> > >     -ENTRY(early_idt_handler)
> > >     +/* This is weak to keep gas from relaxing the jumps */
> > >     +WEAK(early_idt_handler)
> > >      	cld
> 
> > So IIUC, this -mshared option disables the optimization on branch
> > instructions and generates slightly bigger code.  Not sure how much
> > affected by this though.
> > 
> > Steve, do you think it's better to use this option?
> 
> Can we solve this by doing the same thing it did for the kernel?

Looks good to me :)

Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org>

Thanks!

> 
> -- Steve
> 
> diff --git a/arch/x86/kernel/mcount_64.S b/arch/x86/kernel/mcount_64.S
> index ed48a9f465f8..e13a695c3084 100644
> --- a/arch/x86/kernel/mcount_64.S
> +++ b/arch/x86/kernel/mcount_64.S
> @@ -182,7 +182,8 @@ GLOBAL(ftrace_graph_call)
>  	jmp ftrace_stub
>  #endif
>  
> -GLOBAL(ftrace_stub)
> +/* This is weak to keep gas from relaxing the jumps */
> +WEAK(ftrace_stub)
>  	retq
>  END(ftrace_caller)
>  


-- 
Masami Hiramatsu <mhiramat@kernel.org>