Re: [PATCH v3 3/3] tracing: convert __trace_seq_init to use WARN_ON_ONCE

From: kernel test robot
Date: Mon Feb 05 2024 - 09:00:49 EST



Hello,

kernel test robot noticed "WARNING:at_kernel/trace/trace_seq.c:#trace_seq_printf" on:

commit: 233bcd2427b36992e8918a67a88912f9c3d497af ("[PATCH v3 3/3] tracing: convert __trace_seq_init to use WARN_ON_ONCE")
url: https://github.com/intel-lab-lkp/linux/commits/Ricardo-B-Marliere/tracing-initialize-trace_seq-buffers/20240126-063125
base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git ecb1b8288dc7ccbdcb3b9df005fa1c0e0c0388a7
patch link: https://lore.kernel.org/all/20240125222818.7425-4-ricardo@xxxxxxxxxxxx/
patch subject: [PATCH v3 3/3] tracing: convert __trace_seq_init to use WARN_ON_ONCE

in testcase: boot

compiler: clang-17
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G

(please refer to attached dmesg/kmsg for entire log/backtrace)


we noticed the WARN_ON_ONCE added in this commit was hit in our tests. but
not always happen, just FYI.

27b32d2097dcb40a 233bcd2427b36992e8918a67a88
---------------- ---------------------------
fail:runs %reproduction fail:runs
| | |
:10 50% 5:11 dmesg.RIP:trace_seq_printf
:10 50% 5:11 dmesg.WARNING:at_kernel/trace/trace_seq.c:#trace_seq_printf



If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@xxxxxxxxx>
| Closes: https://lore.kernel.org/oe-lkp/202402052141.769871e2-lkp@xxxxxxxxx


[ 1915.506477][ T42] ------------[ cut here ]------------
[ 1915.506778][ T42] WARNING: CPU: 0 PID: 42 at kernel/trace/trace_seq.c:35 trace_seq_printf (kernel/trace/trace_seq.c:35)
[ 1915.507296][ T42] Modules linked in: ipv6
[ 1915.507538][ T42] CPU: 0 PID: 42 Comm: rcu_scale_write Tainted: G TN 6.8.0-rc1-00172-g233bcd2427b3 #1
[ 1915.508125][ T42] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 1915.508690][ T42] RIP: 0010:trace_seq_printf (kernel/trace/trace_seq.c:35)
[ 1915.508999][ T42] Code: 00 00 48 3b 83 e8 1f 00 00 77 51 48 8d 65 f0 5b 41 5e 5d 31 c0 31 c9 31 ff 31 d2 45 31 c0 45 31 c9 c3 cc 48 8d 83 f0 1f 00 00 <0f> 0b 48 89 9b e0 1f 00 00 48 c7 83 e8 1f 00 00 dc 1f 00 00 c6 03
All code
========
0: 00 00 add %al,(%rax)
2: 48 3b 83 e8 1f 00 00 cmp 0x1fe8(%rbx),%rax
9: 77 51 ja 0x5c
b: 48 8d 65 f0 lea -0x10(%rbp),%rsp
f: 5b pop %rbx
10: 41 5e pop %r14
12: 5d pop %rbp
13: 31 c0 xor %eax,%eax
15: 31 c9 xor %ecx,%ecx
17: 31 ff xor %edi,%edi
19: 31 d2 xor %edx,%edx
1b: 45 31 c0 xor %r8d,%r8d
1e: 45 31 c9 xor %r9d,%r9d
21: c3 ret
22: cc int3
23: 48 8d 83 f0 1f 00 00 lea 0x1ff0(%rbx),%rax
2a:* 0f 0b ud2 <-- trapping instruction
2c: 48 89 9b e0 1f 00 00 mov %rbx,0x1fe0(%rbx)
33: 48 c7 83 e8 1f 00 00 movq $0x1fdc,0x1fe8(%rbx)
3a: dc 1f 00 00
3e: c6 .byte 0xc6
3f: 03 .byte 0x3

Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: 48 89 9b e0 1f 00 00 mov %rbx,0x1fe0(%rbx)
9: 48 c7 83 e8 1f 00 00 movq $0x1fdc,0x1fe8(%rbx)
10: dc 1f 00 00
14: c6 .byte 0xc6
15: 03 .byte 0x3
[ 1915.510058][ T42] RSP: 0018:ffffc90000157d40 EFLAGS: 00010046
[ 1915.510390][ T42] RAX: ffffffff84141a18 RBX: ffffffff8413fa28 RCX: 0000000000000001
[ 1915.510822][ T42] RDX: ffffc90000157dc0 RSI: ffffffff82768da2 RDI: ffffffff84141a08
[ 1915.511253][ T42] RBP: ffffc90000157da0 R08: 0000000000000000 R09: 0000000000000000
[ 1915.511684][ T42] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[ 1915.512115][ T42] R13: ffffc90000157dc0 R14: 0000000000000000 R15: ffffffff8413d894
[ 1915.512546][ T42] FS: 0000000000000000(0000) GS:ffffffff82a60000(0000) knlGS:0000000000000000
[ 1915.513033][ T42] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1915.513392][ T42] CR2: 000055fe70034138 CR3: 00000001740d7000 CR4: 00000000000406b0
[ 1915.513828][ T42] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1915.514262][ T42] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 1915.514696][ T42] Call Trace:
[ 1915.514881][ T42] <TASK>
[ 1915.515048][ T42] ? __warn (kernel/panic.c:236 kernel/panic.c:677)
[ 1915.515275][ T42] ? trace_seq_printf (kernel/trace/trace_seq.c:35)
[ 1915.515550][ T42] ? report_bug (lib/bug.c:?)
[ 1915.515799][ T42] ? handle_bug (arch/x86/kernel/traps.c:238)
[ 1915.516038][ T42] ? exc_invalid_op (arch/x86/kernel/traps.c:259)
[ 1915.516298][ T42] ? asm_exc_invalid_op (arch/x86/include/asm/idtentry.h:568)
[ 1915.516586][ T42] ? trace_seq_printf (kernel/trace/trace_seq.c:35)
[ 1915.516860][ T42] ? trace_find_cmdline (arch/x86/include/asm/preempt.h:103 kernel/trace/trace.c:2546)
[ 1915.517142][ T42] ? trace_find_cmdline (arch/x86/include/asm/preempt.h:103 kernel/trace/trace.c:2546)
[ 1915.517420][ T42] ? preempt_count_sub (arch/x86/include/asm/preempt.h:84 kernel/sched/core.c:5900)
[ 1915.517694][ T42] trace_print_lat_context (kernel/trace/trace_output.c:516 kernel/trace/trace_output.c:664)
[ 1915.517995][ T42] print_trace_fmt (kernel/trace/trace.c:?)
[ 1915.518257][ T42] ftrace_dump (kernel/trace/trace.c:10413)
[ 1915.518505][ T42] rcu_scale_writer (kernel/rcu/rcuscale.c:534)
[ 1915.518775][ T42] ? __cfi_rcu_scale_writer (kernel/rcu/rcuscale.c:453)
[ 1915.519071][ T42] kthread (kernel/kthread.c:390)
[ 1915.519298][ T42] ? __cfi_kthread (kernel/kthread.c:341)
[ 1915.519554][ T42] ret_from_fork (arch/x86/kernel/process.c:153)
[ 1915.519802][ T42] ? __cfi_kthread (kernel/kthread.c:341)
[ 1915.520057][ T42] ret_from_fork_asm (arch/x86/entry/entry_64.S:250)
[ 1915.520326][ T42] </TASK>
[ 1915.520496][ T42] irq event stamp: 8228
[ 1915.520724][ T42] hardirqs last enabled at (8227): _raw_spin_unlock_irqrestore (include/linux/spinlock_api_smp.h:?)
[ 1915.521290][ T42] hardirqs last disabled at (8228): ftrace_dump (kernel/trace/trace.c:10359)
[ 1915.521783][ T42] softirqs last enabled at (0): copy_process (include/linux/rcupdate.h:298 include/linux/rcupdate.h:750 kernel/fork.c:2366)
[ 1915.522276][ T42] softirqs last disabled at (0): 0x0
[ 1915.522663][ T42] ---[ end trace 0000000000000000 ]---
[ 1915.522970][ T42] swapper-1 0..Zff 1910231878us : fib6_table_lookup: table 2166473472 oif 80736 iif -14080 proto 0 81ff:ffff:ff60:6d05:81ff:ffff:ff00:0/0 -> ::/0 tos 96 scope 109 flags 5 ==> dev gw :: err -1
[ 1915.524039][ T42] swapper-1 0..... 1910231880us : Unknown type 1830
[ 1915.524442][ T42] ---------------------------------
[ 1915.524733][ T42] rcu-scale: Test complete



The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20240205/202402052141.769871e2-lkp@xxxxxxxxx



--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki