Dynamic ftrace self test broken on ARM

Hi,

On a ARM (i.MX 7) I noticed today that the kernel crashes after dynamic ftrace self test. I tried v4.18-rc1 first, but it seems that at least also v4.17 is affected.

VFP support v0.3: implementor 41 architecture 2 part 30 variant 7 rev 5
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff,
max_idle_ns: 19112604462750000 ns
futex hash table entries: 512 (order: 3, 32768 bytes) Running postponed tracer tests:
Testing tracer function: PASSED
Testing dynamic ftrace: PASSED
Testing dynamic ftrace ops #1:
(1 0 1 0 0)
(1 1 2 0 0)
(2 1 3 0 93620)
(2 2 4 0 93807) PASSED
Testing dynamic ftrace ops #2:
(1 0 1 96630 0)
(1 1 2 96804 0)
(2 1 3 1 342)
(2 2 4 121 462) PASSED
Testing ftrace recursion: PASSED
Testing ftrace recursion safe: PASSED
Testing ftrace regs: PASSED
Testing tracer nop: PASSED
Testing tracer function_graph: PASSED
pinctrl core: initialized pinctrl subsystem

Unable to handle kernel paging request at virtual address c0ca14e4
pgd = (ptrval)
[c0ca14e4] *pgd=80c1940e(bad)
Internal error: Oops: 80d [#1] SMP ARM
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.17.0 #564
Hardware name: Freescale i.MX7 Dual (Device Tree)
PC is at skb_init+0x50/0x7c
LR is at kmem_cache_create_usercopy+0x10c/0x320
pc : [<c0e63b80>]    lr : [<c023bd5c>]    psr: 60000013

sp : dc11be98 ip : dc11be58 fp : dc11bebc
r10: c0e006f0 r9 : c0e82820 r8 : c0faa8c0
r7 : c0e63a10 r6 : 00000000 r5 : 00000000 r4 : c0ca14e4 r3 : c0eb72c8 r2 : 00000000 r1 : 1ea8b000 r0 : dc0eef00
Flags: nZCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment none
Control: 10c5387d Table: 8000406a DAC: 00000051 Process swapper/0 (pid: 1, stack limit = 0x(ptrval))

Stack: (0xdc11be98 to 0xdc11c000)

be80: 00000018
00000030
bea0: 00000000 c07fda4c 00000000 ffffe000 dc11bedc dc11bec0 c0e63a38 c0e63b3c
bec0: c0e5d488 c0170c64 c0fa7140 c0fa7140 dc11bf44 dc11bee0 c0103080 c0e63a1c
bee0: c0145d74 c0e006fc c0bf3c00 c0bf3ca4 c0bf3cf0 c0c03b98 00000000 c0bf3c7c
bf00: 00000001 00000001 c0bf6c04 c0cf0b68 dffffc66 00000000 00000000 c0fa7140
bf20: c0e82844 00000002 c0fa7140 c0eb6264 00000002 c0faa8c0 dc11bf94 dc11bf48
bf40: c0e011d8 c0103038 00000001 00000001 00000000 c0e006f0 00000000 c0f09fc0
bf60: c0cf0b68 000000dc c0989c58 00000000 c0989c58 00000000 00000000 00000000
bf80: 00000000 00000000 dc11bfac dc11bf98 c0989c70 c0e00f74 00000000 c0989c58
bfa0: 00000000 dc11bfb0 c01010e8 c0989c64 00000000 00000000 00000000 00000000
bfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
bfe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000 00000000
[<c0e63b80>] (skb_init) from [<c0e63a38>] (sock_init+0x28/0xc8) [<c0e63a38>] (sock_init) from [<c0103080>] (do_one_initcall+0x54/0x1e8) [<c0103080>] (do_one_initcall) from [<c0e011d8>] (kernel_init_freeable+0x270/0x308)
[<c0e011d8>] (kernel_init_freeable) from [<c0989c70>] (kernel_init+0x18/0x124)
[<c0989c70>] (kernel_init) from [<c01010e8>] (ret_from_fork+0x14/0x2c)

Exception stack(0xdc11bfb0 to 0xdc11bff8)

bfa0: 00000000 00000000 00000000
00000000
bfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
bfe0: 00000000 00000000 00000000 00000000 00000013 00000000

Code: e58d3000 e3a010b8 e3a03a42 ebcf6033 (e5840000)
---[ end trace fff84001ba23c9c9 ]---
Kernel panic - not syncing: Attempted to kill init! exitcode=0x0000000b
[    2.292924]
CPU1: stopping
CPU: 1 PID: 0 Comm: swapper/1 Tainted: G      D           4.17.0 #564
Hardware name: Freescale i.MX7 Dual (Device Tree)
[<c01128a4>] (unwind_backtrace) from [<c010d868>] (show_stack+0x20/0x24)
[<c010d868>] (show_stack) from [<c0975590>] (dump_stack+0x90/0xa4)
[<c0975590>] (dump_stack) from [<c0110608>] (handle_IPI+0x2dc/0x2fc)
[<c0110608>] (handle_IPI) from [<c010233c>] (gic_handle_irq+0x9c/0xa0)
[<c010233c>] (gic_handle_irq) from [<c0101a0c>] (__irq_svc+0x6c/0x90)
Exception stack(0xdc14df18 to 0xdc14df60)

df00: 00000000
00000324
df20: df957420 c011c4c0 ffffe000 c0f05d28 c0f05d6c 00000002 00000000 c0f05d80
df40: 00000000 dc14df74 dc14df78 dc14df68 c0109938 c010993c 60000013 ffffffff
[<c0101a0c>] (__irq_svc) from [<c010993c>] (arch_cpu_idle+0x48/0x4c) [<c010993c>] (arch_cpu_idle) from [<c098f81c>] (default_idle_call+0x30/0x3c)
[<c098f81c>] (default_idle_call) from [<c01566a4>] (do_idle+0x1bc/0x284) [<c01566a4>] (do_idle) from [<c0156a18>] (cpu_startup_entry+0x28/0x30) [<c0156a18>] (cpu_startup_entry) from [<c01100b0>] (secondary_start_kernel+0x158/0x164)
[<c01100b0>] (secondary_start_kernel) from [<8010274c>] (0x8010274c)

---[ end Kernel panic - not syncing: Attempted to kill init!

exitcode=0x0000000b
]---

I tested with imx_v6_v7_defconfig and enabled the following options:

CONFIG_DYNAMIC_FTRACE=y

CONFIG_DYNAMIC_FTRACE_WITH_REGS=y

CONFIG_FTRACE_MCOUNT_RECORD=y

CONFIG_FTRACE_SELFTEST=y

CONFIG_FTRACE_STARTUP_TEST=y

I guess startup test should leave the kernel unencumbered?

Quoted 123 lines · On Mon, 18 Jun 2018 23:09:04 +0200 Stefan Agner <[email protected]> wrote:

Hi,

On a ARM (i.MX 7) I noticed today that the kernel crashes after dynamic ftrace self test. I tried v4.18-rc1 first, but it seems that at least also v4.17 is affected.

VFP support v0.3: implementor 41 architecture 2 part 30 variant 7 rev 5
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff,
max_idle_ns: 19112604462750000 ns
futex hash table entries: 512 (order: 3, 32768 bytes) Running postponed tracer tests:
Testing tracer function: PASSED
Testing dynamic ftrace: PASSED
Testing dynamic ftrace ops #1:
(1 0 1 0 0)
(1 1 2 0 0)
(2 1 3 0 93620)
(2 2 4 0 93807) PASSED
Testing dynamic ftrace ops #2:
(1 0 1 96630 0)
(1 1 2 96804 0)
(2 1 3 1 342)
(2 2 4 121 462) PASSED
Testing ftrace recursion: PASSED
Testing ftrace recursion safe: PASSED
Testing ftrace regs: PASSED
Testing tracer nop: PASSED
Testing tracer function_graph: PASSED
pinctrl core: initialized pinctrl subsystem

Unable to handle kernel paging request at virtual address c0ca14e4
pgd = (ptrval)
[c0ca14e4] *pgd=80c1940e(bad)
Internal error: Oops: 80d [#1] SMP ARM
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.17.0 #564
Hardware name: Freescale i.MX7 Dual (Device Tree)
PC is at skb_init+0x50/0x7c
LR is at kmem_cache_create_usercopy+0x10c/0x320
pc : [<c0e63b80>]    lr : [<c023bd5c>]    psr: 60000013

sp : dc11be98 ip : dc11be58 fp : dc11bebc
r10: c0e006f0 r9 : c0e82820 r8 : c0faa8c0
r7 : c0e63a10 r6 : 00000000 r5 : 00000000 r4 : c0ca14e4 r3 : c0eb72c8 r2 : 00000000 r1 : 1ea8b000 r0 : dc0eef00
Flags: nZCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment none
Control: 10c5387d Table: 8000406a DAC: 00000051 Process swapper/0 (pid: 1, stack limit = 0x(ptrval))

Stack: (0xdc11be98 to 0xdc11c000)

be80: 00000018
00000030
bea0: 00000000 c07fda4c 00000000 ffffe000 dc11bedc dc11bec0 c0e63a38 c0e63b3c
bec0: c0e5d488 c0170c64 c0fa7140 c0fa7140 dc11bf44 dc11bee0 c0103080 c0e63a1c
bee0: c0145d74 c0e006fc c0bf3c00 c0bf3ca4 c0bf3cf0 c0c03b98 00000000 c0bf3c7c
bf00: 00000001 00000001 c0bf6c04 c0cf0b68 dffffc66 00000000 00000000 c0fa7140
bf20: c0e82844 00000002 c0fa7140 c0eb6264 00000002 c0faa8c0 dc11bf94 dc11bf48
bf40: c0e011d8 c0103038 00000001 00000001 00000000 c0e006f0 00000000 c0f09fc0
bf60: c0cf0b68 000000dc c0989c58 00000000 c0989c58 00000000 00000000 00000000
bf80: 00000000 00000000 dc11bfac dc11bf98 c0989c70 c0e00f74 00000000 c0989c58
bfa0: 00000000 dc11bfb0 c01010e8 c0989c64 00000000 00000000 00000000 00000000
bfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
bfe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000 00000000
[<c0e63b80>] (skb_init) from [<c0e63a38>] (sock_init+0x28/0xc8) [<c0e63a38>] (sock_init) from [<c0103080>] (do_one_initcall+0x54/0x1e8) [<c0103080>] (do_one_initcall) from [<c0e011d8>] (kernel_init_freeable+0x270/0x308)
[<c0e011d8>] (kernel_init_freeable) from [<c0989c70>] (kernel_init+0x18/0x124)
[<c0989c70>] (kernel_init) from [<c01010e8>] (ret_from_fork+0x14/0x2c)

Exception stack(0xdc11bfb0 to 0xdc11bff8)

bfa0: 00000000 00000000 00000000
00000000
bfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
bfe0: 00000000 00000000 00000000 00000000 00000013 00000000

Code: e58d3000 e3a010b8 e3a03a42 ebcf6033 (e5840000)
---[ end trace fff84001ba23c9c9 ]---
Kernel panic - not syncing: Attempted to kill init! exitcode=0x0000000b
[    2.292924]
CPU1: stopping
CPU: 1 PID: 0 Comm: swapper/1 Tainted: G      D           4.17.0 #564
Hardware name: Freescale i.MX7 Dual (Device Tree)
[<c01128a4>] (unwind_backtrace) from [<c010d868>] (show_stack+0x20/0x24)
[<c010d868>] (show_stack) from [<c0975590>] (dump_stack+0x90/0xa4)
[<c0975590>] (dump_stack) from [<c0110608>] (handle_IPI+0x2dc/0x2fc)
[<c0110608>] (handle_IPI) from [<c010233c>] (gic_handle_irq+0x9c/0xa0)
[<c010233c>] (gic_handle_irq) from [<c0101a0c>] (__irq_svc+0x6c/0x90)
Exception stack(0xdc14df18 to 0xdc14df60)

df00: 00000000
00000324
df20: df957420 c011c4c0 ffffe000 c0f05d28 c0f05d6c 00000002 00000000 c0f05d80
df40: 00000000 dc14df74 dc14df78 dc14df68 c0109938 c010993c 60000013 ffffffff
[<c0101a0c>] (__irq_svc) from [<c010993c>] (arch_cpu_idle+0x48/0x4c) [<c010993c>] (arch_cpu_idle) from [<c098f81c>] (default_idle_call+0x30/0x3c)
[<c098f81c>] (default_idle_call) from [<c01566a4>] (do_idle+0x1bc/0x284) [<c01566a4>] (do_idle) from [<c0156a18>] (cpu_startup_entry+0x28/0x30) [<c0156a18>] (cpu_startup_entry) from [<c01100b0>] (secondary_start_kernel+0x158/0x164)
[<c01100b0>] (secondary_start_kernel) from [<8010274c>] (0x8010274c)

---[ end Kernel panic - not syncing: Attempted to kill init!

exitcode=0x0000000b
]---

I tested with imx_v6_v7_defconfig and enabled the following options:

CONFIG_DYNAMIC_FTRACE=y

CONFIG_DYNAMIC_FTRACE_WITH_REGS=y

Quoted 9 lines

CONFIG_FTRACE_MCOUNT_RECORD=y

CONFIG_FTRACE_SELFTEST=y

CONFIG_FTRACE_STARTUP_TEST=y

I guess startup test should leave the kernel unencumbered?

I'm guessing that it boots fine with CONFIG_FTRACE_STARTUP_TEST=n? Can you try disable the tracers to see if it's the function graph or function tracer that is causing the issue? That is, turn off CONFIG_FUNCTION_GRAPH_TRACER and test it again, and if that crashes, turn off CONFIG_FUNCTION_TRACER to make sure the crash goes away there too.

Quoted 6 lines

I'm guessing that it boots fine with CONFIG_FTRACE_STARTUP_TEST=n? Can you try disable the tracers to see if it's the function graph or function tracer that is causing the issue? That is, turn off CONFIG_FUNCTION_GRAPH_TRACER and test it again, and if that crashes, turn off CONFIG_FUNCTION_TRACER to make sure the crash goes away there too.

Without CONFIG_FTRACE_STARTUP_TEST the kernel boots fine.

CONFIG_FUNCTION_TRACER=y
# CONFIG_FUNCTION_GRAPH_TRACER is not set
# CONFIG_SCHED_TRACER is not set
CONFIG_FTRACE_STARTUP_TEST=y

Crashes with the same stack trace.

# CONFIG_FUNCTION_TRACER is not set
CONFIG_SCHED_TRACER=y
CONFIG_FTRACE_STARTUP_TEST=y

Runs tracer tests and boots fine.

Quoted 7 lines · On Tue, 19 Jun 2018 10:16:19 +0200 Stefan Agner <[email protected]> wrote:

Quoted 6 lines

I'm guessing that it boots fine with CONFIG_FTRACE_STARTUP_TEST=n? Can you try disable the tracers to see if it's the function graph or function tracer that is causing the issue? That is, turn off CONFIG_FUNCTION_GRAPH_TRACER and test it again, and if that crashes, turn off CONFIG_FUNCTION_TRACER to make sure the crash goes away there too.

Quoted 6 lines

Without CONFIG_FTRACE_STARTUP_TEST the kernel boots fine.

CONFIG_FUNCTION_TRACER=y
# CONFIG_FUNCTION_GRAPH_TRACER is not set
# CONFIG_SCHED_TRACER is not set
CONFIG_FTRACE_STARTUP_TEST=y

OK, so it's not a graph tracer issue, but a function tracer issue.

Quoted 7 lines

Crashes with the same stack trace.

# CONFIG_FUNCTION_TRACER is not set
CONFIG_SCHED_TRACER=y
CONFIG_FTRACE_STARTUP_TEST=y

Quoted 1 line

Runs tracer tests and boots fine.

Thanks. Did this ever work? And if so, perhaps you have time to perform a bisect. If you have a ktest setup, you can have it run the bisect for you (over night).

v4.9 seems to work, so I started bisecting. It turned out that commit 6f05d0761af6 ("ARM: 8668/1: ftrace: Fix dynamic ftrace with DEBUG_RODATA and !FRAME_POINTER") broke it, introduced during the v4.12 merge window.

Quoted 3 lines · On Wed, 20 Jun 2018 15:51:55 +0200 Stefan Agner <[email protected]> wrote:

v4.9 seems to work, so I started bisecting. It turned out that commit 6f05d0761af6 ("ARM: 8668/1: ftrace: Fix dynamic ftrace with DEBUG_RODATA and !FRAME_POINTER") broke it, introduced during the v4.12 merge window.

That patch doesn't appear to be the cause. It could have been a failed bisect. Does the commit before that commit work? Does that commit fail?

It may be due to some other RODATA change though. That is actually one of my thoughts when looking at the bug.

Quoted 10 lines · Steven Rostedt

Quoted 3 lines · On Wed, 20 Jun 2018 15:51:55 +0200 Stefan Agner <[email protected]> wrote:

v4.9 seems to work, so I started bisecting. It turned out that commit 6f05d0761af6 ("ARM: 8668/1: ftrace: Fix dynamic ftrace with DEBUG_RODATA and !FRAME_POINTER") broke it, introduced during the v4.12 merge window.

That patch doesn't appear to be the cause. It could have been a failed bisect. Does the commit before that commit work? Does that commit fail?

Pretty sure it is that one. Reverting it on top of v4.18-rc1 fixes it...

Quoted 3 lines

It may be due to some other RODATA change though. That is actually one of my thoughts when looking at the bug.

CONFIG_STRICT_KERNEL_RWX=y is set, will test without.

Quoted 15 lines · Stefan Agner

Quoted 10 lines · Steven Rostedt

Quoted 3 lines · On Wed, 20 Jun 2018 15:51:55 +0200 Stefan Agner <[email protected]> wrote:

v4.9 seems to work, so I started bisecting. It turned out that commit 6f05d0761af6 ("ARM: 8668/1: ftrace: Fix dynamic ftrace with DEBUG_RODATA and !FRAME_POINTER") broke it, introduced during the v4.12 merge window.

That patch doesn't appear to be the cause. It could have been a failed bisect. Does the commit before that commit work? Does that commit fail?

Pretty sure it is that one. Reverting it on top of v4.18-rc1 fixes it...

Quoted 1 line

Quoted 4 lines

Quoted 2 lines

It may be due to some other RODATA change though. That is actually one of my thoughts when looking at the bug.

CONFIG_STRICT_KERNEL_RWX=y is set, will test without.

Compiling without CONFIG_STRICT_KERNEL_RWX fixes the issue too. So seems to be a RODATA issue...

Quoted 16 lines · Stefan Agner

Quoted 15 lines · Stefan Agner

Quoted 10 lines · Steven Rostedt

Quoted 3 lines · On Wed, 20 Jun 2018 15:51:55 +0200 Stefan Agner <[email protected]> wrote:

v4.9 seems to work, so I started bisecting. It turned out that commit 6f05d0761af6 ("ARM: 8668/1: ftrace: Fix dynamic ftrace with DEBUG_RODATA and !FRAME_POINTER") broke it, introduced during the v4.12 merge window.

That patch doesn't appear to be the cause. It could have been a failed bisect. Does the commit before that commit work? Does that commit fail?

Pretty sure it is that one. Reverting it on top of v4.18-rc1 fixes it...

Quoted 1 line

Quoted 7 lines

Quoted 4 lines

Quoted 2 lines

It may be due to some other RODATA change though. That is actually one of my thoughts when looking at the bug.

CONFIG_STRICT_KERNEL_RWX=y is set, will test without.

Compiling without CONFIG_STRICT_KERNEL_RWX fixes the issue too. So seems to be a RODATA issue...

Ok, I understand the issue now:

In ARM ftrace we set kernel text to RW and back to RO in arch_ftrace_update_code.

ARM sets the kernel at free_initmem to RO. So using ftrace selftest sets the kernel text to RO much earlier, which seems to cause issues.

Reverting the above commit actually fixes selftests during boot, but it breaks ftrace at runtime...

This resolves the issue:

(quoted diff) +13 -1

+static int __ftrace_modify_code_boot(void *data)
+{
+       int *command = data;
+
+       ftrace_modify_all_code(*command);
+
+       return 0;
+}
+
 void arch_ftrace_update_code(int command)
 {
-       stop_machine(__ftrace_modify_code, &command, NULL);
+       if (system_state < SYSTEM_RUNNING)
+               stop_machine(__ftrace_modify_code_boot, &command, NULL);
+       else
+               stop_machine(__ftrace_modify_code, &command, NULL);
 }

Using system_state to indicate whether fix_kernmem_perms has been called is rather brittle...

Any input from ARM folks?

Quoted 1 line

Any input from ARM folks?

The same issues must exist on other architectures as ARM is not the only architecture to implement read-only kernel text and dynamic ftrace, so surely this problem isn't unique to ARM.

Quoted 5 lines · On Thu, 21 Jun 2018 00:07:34 +0100 Russell King - ARM Linux…

Quoted 1 line

Any input from ARM folks?

The same issues must exist on other architectures as ARM is not the only architecture to implement read-only kernel text and dynamic ftrace, so surely this problem isn't unique to ARM.

Probably because of the way set_kernel_text_ro() is implemented in other archs. For example, in x86, we have:

void set_kernel_text_ro(void)

{
	unsigned long start = PFN_ALIGN(_text);
	unsigned long end = PFN_ALIGN(__stop___ex_table);

	if (!kernel_set_to_readonly)
		return;

	/*
	 * Set the kernel identity mapping for text RO.
	 */
	set_memory_ro(start, (end - start) >> PAGE_SHIFT);
}

and arm has:

void set_kernel_text_ro(void)

{
	set_section_perms(ro_perms, ARRAY_SIZE(ro_perms), true,
				current->active_mm);
}

Where x86's set_kernel_text_ro() is a nop until the kernel_set_to_readonly is set.

Perhaps this may fix things?

[ Not even compiled tested ]

-- Steve

arch/arm/mm/init.c +6 -0

index c186474422f3..0cc8e04295a4 100644
@@ -736,20 +736,29 @@ static int __mark_rodata_ro(void *unused)
 	return 0;
 }
 
+static int kernel_set_to_readonly __read_mostly;
+
 void mark_rodata_ro(void)
 {
+	kernel_set_to_readonly = 1;
 	stop_machine(__mark_rodata_ro, NULL, NULL);
 	debug_checkwx();
 }
 
 void set_kernel_text_rw(void)
 {
+	if (!kernel_set_to_readonly)
+		return;
+
 	set_section_perms(ro_perms, ARRAY_SIZE(ro_perms), false,
 				current->active_mm);

This aligns nicely with how this has been solved with commit 162396309745 ("ftrace, x86: make kernel text writable only for conversions") a while ago.

Reviewed-by Stefan Agner <[email protected]>

Compiled and tested here, selftest as well as ftrace at runtime seems to work fine.

Tested-by Stefan Agner <[email protected]>

Thanks Steven! Can you send a patch or should I do it?