On Thu, 12 Jun 2025 18:39:41 +0530 Naresh Kamboju naresh.kamboju@linaro.org wrote:
On Tue, 10 Jun 2025 at 20:22, Steven Rostedt rostedt@goodmis.org wrote:
On Tue, 10 Jun 2025 18:50:05 +0530 Naresh Kamboju naresh.kamboju@linaro.org wrote:
Is this bug reproducible easier recently?
Yes. It is easy to reproduce.
Can you test before and after this commit:
4334336e769b ("x86/alternatives: Improve code-patching scalability by removing false sharing in poke_int3_handler()")
I think that may be the culprit.
Even if Masami's patches work, I want to know what exactly caused it.
Steven,
Since the reported regressions are intermittent, It is not easy to bisect. However, The commit merged into Linux next-20250414 tag and then started noticing from next-20250415 onwards this regression on both x86_64 devices and qemu-x86_64 intermittently with and without compat mode.
- https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20250606/tes...
- https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20250606/tes...
And above commit landed into Linus master branch on 2025-05-13 and then started noticing this regression intermittently on x86 with and without compat mode.
Masami San,
case 1) compat mode x86_64 (64-bit kernel + 32-bit rootfs) I have tested your patch on top of linux next-20250606 tag and tested on real x86_64 (64-bit kernel + 32-bit rootfs) hardware for 7 test runs.
ftrace_regression01 - pass ftrace_regression02 - pass ftrace-stress-test - pass dynamic_debug01 - Hangs (No crash log on serial console)
Hm, this last one seems different reason.
Case 1.1) Above case noticed on qemu-x86_64 with compat mode ^ with 12 test runs.
case 2) x86_64 (64-bit kernel + 64-bit rootfs) I have tested your patch on top of linux next-20250606 tag and tested on real x86_64 (64-bit kernel + 64-bit rootfs) hardware for 4 runs and out of these 3 runs failed and found these kernel warnings, kernel BUG and invalid opcode while running LTP tracing test cases.
Here I am sharing the crash log snippet and boot and test log links and build link.
Test logs: [ 112.596591] Ring buffer clock went backwards: 113864910133 -> 112596588266 [ 115.829620] cat (5762) used greatest stack depth: 10936 bytes left [ 120.922517] ------------[ cut here ]------------ [ 120.927198] WARNING: CPU: 2 PID: 6639 at kernel/trace/trace_functions_graph.c:985 print_graph_entry+0x579/0x590 [ 120.937364] Modules linked in: x86_pkg_temp_thermal [ 120.942405] CPU: 2 UID: 0 PID: 6639 Comm: cat Tainted: G S 6.15.0-next-20250606 #1 PREEMPT(voluntary) [ 120.953380] Tainted: [S]=CPU_OUT_OF_SPEC [ 120.957477] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS 2.7 12/07/2021 [ 120.965036] RIP: 0010:print_graph_entry+0x579/0x590
Run 1:
The warning came from; ---- /* Save this function pointer to see if the exit matches */ if (call->depth < FTRACE_RETFUNC_DEPTH && !WARN_ON_ONCE(call->depth < 0)) cpu_data->enter_funcs[call->depth] = call->func; } ----
Hit the "call->depth < 0". Thus this is function graph tracer's problem.
ftrace-stress-test: [ 58.963898] /usr/local/bin/kirk[340]: starting test ftrace-stress-test (ftrace_stress_test.sh 90) [ 60.316588] ------------[ cut here ]------------ [ 60.316588] ------------[ cut here ]------------ [ 60.316590] ------------[ cut here ]------------ [ 60.316593] ------------[ cut here ]------------ [ 60.316593] ------------[ cut here ]------------ [ 60.316594] ------------[ cut here ]------------ [ 60.316594] kernel BUG at kernel/entry/common.c:328! [ 60.316594] kernel BUG at kernel/entry/common.c:328! [ 60.316595] kernel BUG at kernel/entry/common.c:328! [ 60.316600] Oops: invalid opcode: 0000 [#1] SMP PTI [ 60.316604] CPU: 2 UID: 0 PID: 1556 Comm: sh Tainted: G S 6.15.0-next-20250606 #1 PREEMPT(voluntary) [ 60.316608] Tainted: [S]=CPU_OUT_OF_SPEC [ 60.316609] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS 2.7 12/07/2021 [ 60.316614] ------------[ cut here ]------------ [ 60.316615] kernel BUG at kernel/entry/common.c:328! [ 60.316617] Oops: invalid opcode: 0000 [#2] SMP PTI [ 60.316620] CPU: 2 UID: 0 PID: 1556 Comm: sh Tainted: G S 6.15.0-next-20250606 #1 PREEMPT(voluntary) [ 60.316622] Tainted: [S]=CPU_OUT_OF_SPEC [ 60.316623] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS 2.7 12/07/2021 [ 60.316625] RIP: 0010:irqentry_nmi_enter+0x6c/0x70
Run 2:
Interesting. This hits the max nestable number of NMI.
/* * nmi_enter() can nest up to 15 times; see NMI_BITS. */ #define __nmi_enter() \ do { \ lockdep_off(); \ arch_nmi_enter(); \ BUG_ON(in_nmi() == NMI_MASK); \ <===== __preempt_count_add(NMI_OFFSET + HARDIRQ_OFFSET); \ } while (0)
ftrace-stress-test: [ 78.877495] /usr/local/bin/kirk[343]: starting test ftrace-stress-test (ftrace_stress_test.sh 90) [ 78.977303] Scheduler tracepoints stat_sleep, stat_iowait, stat_blocked and stat_runtime require the kernel parameter schedstats=enable or kernel.sched_schedstats=1 [ 82.299799] cat (2322) used greatest stack depth: 11520 bytes left [ 82.327708] cat (2327) used greatest stack depth: 11256 bytes left [ 82.632183] cat (2375) used greatest stack depth: 10992 bytes left [ 137.335901] ------------[ cut here ]------------ [ 137.335901] ------------[ cut here ]------------ [ 137.335902] ------------[ cut here ]------------ [ 137.335907] kernel BUG at kernel/entry/common.c:328! [ 137.335908] ------------[ cut here ]------------ [ 137.335909] ------------[ cut here ]------------ [ 137.335912] kernel BUG at kernel/entry/common.c:328! [ 137.335912] kernel BUG at kernel/entry/common.c:328! [ 137.335915] Oops: invalid opcode: 0000 [#1] SMP PTI [ 137.335921] CPU: 0 UID: 0 PID: 544 Comm: sh Tainted: G S 6.15.0-next-20250606 #1 PREEMPT(voluntary) [ 137.335926] Tainted: [S]=CPU_OUT_OF_SPEC [ 137.335929] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS 2.7 12/07/2021 [ 137.335937] ------------[ cut here ]------------ [ 137.335939] kernel BUG at kernel/entry/common.c:328! [ 137.335945] Oops: invalid opcode: 0000 [#2] SMP PTI [ 137.335949] CPU: 0 UID: 0 PID: 544 Comm: sh Tainted: G S 6.15.0-next-20250606 #1 PREEMPT(voluntary) [ 137.335953] Tainted: [S]=CPU_OUT_OF_SPEC [ 137.335956] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS 2.7 12/07/2021 [ 137.335959] RIP: 0010:irqentry_nmi_enter+0x6c/0x70
Run 3:
This is the same as Run 2, and clearer.
In do_int3(), if we hit a disappeared int3, it is evacuated after all. This means kprobe_int3_handler() is hit, and call get_kprobe() to find the corresponding kprobes. But,
ffffffff8150a040 <get_kprobe>: ffffffff8150a040: f3 0f 1e fa endbr64 ffffffff8150a044: e8 07 b0 e2 ff call ffffffff81335050 <__fentry__> ffffffff8150a049: 48 b8 eb 83 b5 80 46 movabs $0x61c8864680b583eb,%rax ffffffff8150a050: 86 c8 61
It hits the ftrace and hooked by fgraph, and eventually returns via ftrace_return_to_handler()
[ 137.338572] RIP: 0010:ftrace_return_to_handler+0xd5/0x1f0 [ 137.338577] Code: 00 89 55 c8 48 85 ff 74 07 4c 89 b7 80 00 00 00 49 8b 94 24 38 0b 00 00 48 98 48 8b 04 c2 48 c1 e8 0c 0f b7 c0 48 89 45 b8 cc <90> 48 8b 05 e3 ac c2 01 48 63 80 f8 00 00 00 48 0f a3 45 b8 72 39
This address is;
$ eu-addr2line -fi -e vmlinux ftrace_return_to_handler+0xd5 arch_static_branch inlined at /builds/linux/kernel/trace/fgraph.c:839:6 in ftrace_return_to_handler /builds/linux/arch/x86/include/asm/jump_label.h:36:2 __ftrace_return_to_handler /builds/linux/kernel/trace/fgraph.c:839:6 ftrace_return_to_handler /builds/linux/kernel/trace/fgraph.c:874:9
It is for static_branch, which also uses a text_poke.
----- #ifdef CONFIG_HAVE_STATIC_CALL if (static_branch_likely(&fgraph_do_direct)) { <====== if (test_bit(fgraph_direct_gops->idx, &bitmap)) static_call(fgraph_retfunc)(&trace, fgraph_direct_gops, fregs); -----
But actually, this static_branch modifies the kernel code with smp_text_poke_single() (note, this is a wrapper of smp_text_poke_batch).
And this is MISSED by the smp_text_poke_int3_handler() again and go through the kprobes, and hit ftrace (fgraph) and caused this loop.
So the fundamental issue is that smp_text_poke_batch missed handling INT3.
I guess some text_poke user do not get text_mutex?
Thank you,
Build log:
-- Steve