[legion:patchset/meminfo/v2.1] [proc] 8dade3a353: WARNING:suspicious_RCU_usage

From: kernel test robot
Date: Mon Nov 13 2023 - 03:32:01 EST

Next message: tip-bot2 for Yuntao Wang: "[tip: x86/cleanups] x86/setup: Make relocated_ramdisk a local variable of relocate_initrd()"
Previous message: Gou Hao: "[PATCH] ext4: improving calculation of 'fe_{len|start}' in mb_find_extent()"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hello,

kernel test robot noticed "WARNING:suspicious_RCU_usage" on:

commit: 8dade3a353290abfbfd3c38279c29c3c4ecd7356 ("proc: Implement /proc/self/meminfo")
https://git.kernel.org/cgit/linux/kernel/git/legion/linux.git patchset/meminfo/v2.1

in testcase: trinity
version: trinity-i386-abe9de86-1_20230429
with following parameters:

runtime: 600s

test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/

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

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

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 <oliver.sang@xxxxxxxxx>
| Closes: https://lore.kernel.org/oe-lkp/202311131653.14708bb6-oliver.sang@xxxxxxxxx

the issue doesn't always happen, as below, we observed it 21 times out of 50
runs, but keeps clean on parent.

v6.6-rc7 8dade3a353290abfbfd3c38279c
---------------- ---------------------------
fail:runs %reproduction fail:runs
| | |
:50 42% 21:50 dmesg.WARNING:suspicious_RCU_usage
:50 42% 21:50 dmesg.include/linux/cgroup.h:#suspicious_rcu_dereference_check()usage

[ 366.327498][ T3447] WARNING: suspicious RCU usage
[ 366.328145][ T3447] 6.6.0-rc7-00001-g8dade3a35329 #1 Not tainted
[ 366.329177][ T3447] -----------------------------
[ 366.329833][ T3447] include/linux/cgroup.h:436 suspicious rcu_dereference_check() usage!
[ 366.330891][ T3447]
[ 366.330891][ T3447] other info that might help us debug this:
[ 366.330891][ T3447]
[ 366.332203][ T3447]
[ 366.332203][ T3447] rcu_scheduler_active = 2, debug_locks = 1
[ 366.333484][ T3447] 2 locks held by trinity-c5/3447:
[ 366.334175][ T3447] #0: ffff88814ee10858 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos (fs/file.c:1066)
[ 366.335356][ T3447] #1: ffff88814f3836c0 (&p->lock){+.+.}-{3:3}, at: seq_read_iter (fs/seq_file.c:188)
[ 366.336736][ T3447]
[ 366.336736][ T3447] stack backtrace:
[ 366.337562][ T3447] CPU: 1 PID: 3447 Comm: trinity-c5 Not tainted 6.6.0-rc7-00001-g8dade3a35329 #1 10f1bfacea84478d84947570355f5fbda1b33451
[ 366.339032][ T3447] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 366.340233][ T3447] Call Trace:
[ 366.340701][ T3447] <TASK>
[ 366.341175][ T3447] dump_stack_lvl (lib/dump_stack.c:107)
[ 366.341814][ T3447] lockdep_rcu_suspicious (include/linux/context_tracking.h:153 kernel/locking/lockdep.c:6712)
[ 366.342512][ T3447] mem_fill_meminfo (include/linux/cgroup.h:436 mm/memcontrol.c:4133)
[ 366.343143][ T3447] proc_meminfo_show (fs/proc/meminfo.c:202)
[ 366.343745][ T3447] ? meminfo_proc_show (fs/proc/meminfo.c:197)
[ 366.344423][ T3447] ? get_pid_task (include/linux/rcupdate.h:308 include/linux/rcupdate.h:782 kernel/pid.c:458)
[ 366.345071][ T3447] proc_single_show (include/linux/instrumented.h:96 include/linux/atomic/atomic-instrumented.h:400 include/linux/refcount.h:272 include/linux/refcount.h:315 include/linux/refcount.h:333 include/linux/sched/task.h:125 fs/proc/base.c:779)
[ 366.345750][ T3447] seq_read_iter (fs/seq_file.c:230)
[ 366.346411][ T3447] seq_read (fs/seq_file.c:163)
[ 366.346973][ T3447] ? seq_read_iter (fs/seq_file.c:152)
[ 366.347621][ T3447] ? seq_read_iter (fs/seq_file.c:152)
[ 366.348247][ T3447] do_loop_readv_writev+0x130/0x440
[ 366.349039][ T3447] do_iter_read (fs/read_write.c:748 fs/read_write.c:797)
[ 366.349683][ T3447] vfs_readv (fs/read_write.c:916)
[ 366.350285][ T3447] ? vfs_iter_read (fs/read_write.c:907)
[ 366.350879][ T3447] ? __fdget_pos (fs/file.c:1066)
[ 366.351470][ T3447] ? mutex_lock_io_nested (kernel/locking/mutex.c:746)
[ 366.352216][ T3447] ? preempt_count_sub (kernel/sched/core.c:5863 kernel/sched/core.c:5859 kernel/sched/core.c:5881)
[ 366.352916][ T3447] do_readv (fs/read_write.c:952)
[ 366.356628][ T3447] ? vfs_readv (fs/read_write.c:942)
[ 366.357285][ T3447] __do_fast_syscall_32 (arch/x86/entry/common.c:112 arch/x86/entry/common.c:178)
[ 366.357972][ T3447] do_fast_syscall_32 (arch/x86/entry/common.c:203)
[ 366.358626][ T3447] entry_SYSENTER_compat_after_hwframe (arch/x86/entry/entry_64_compat.S:122)
[ 366.359427][ T3447] RIP: 0023:0xf7f2a579
[ 366.360000][ T3447] Code: b8 01 10 06 03 74 b4 01 10 07 03 74 b0 01 10 08 03 74 d8 01 00 00 00 00 00 00 00 00 00 00 00 00 00 51 52 55 89 e5 0f 34 cd 80 <5d> 5a 59 c3 cc 90 90 90 8d b4 26 00 00 00 00 8d b4 26 00 00 00 00
All code
========
0: b8 01 10 06 03 mov $0x3061001,%eax
5: 74 b4 je 0xffffffffffffffbb
7: 01 10 add %edx,(%rax)
9: 07 (bad)
a: 03 74 b0 01 add 0x1(%rax,%rsi,4),%esi
e: 10 08 adc %cl,(%rax)
10: 03 74 d8 01 add 0x1(%rax,%rbx,8),%esi
...
20: 00 51 52 add %dl,0x52(%rcx)
23: 55 push %rbp
24:* 89 e5 mov %esp,%ebp <-- trapping instruction
26: 0f 34 sysenter
28: cd 80 int $0x80
2a: 5d pop %rbp
2b: 5a pop %rdx
2c: 59 pop %rcx
2d: c3 ret
2e: cc int3
2f: 90 nop
30: 90 nop
31: 90 nop
32: 8d b4 26 00 00 00 00 lea 0x0(%rsi,%riz,1),%esi
39: 8d b4 26 00 00 00 00 lea 0x0(%rsi,%riz,1),%esi

Code starting with the faulting instruction
===========================================
0: 5d pop %rbp
1: 5a pop %rdx
2: 59 pop %rcx
3: c3 ret
4: cc int3
5: 90 nop
6: 90 nop
7: 90 nop
8: 8d b4 26 00 00 00 00 lea 0x0(%rsi,%riz,1),%esi
f: 8d b4 26 00 00 00 00 lea 0x0(%rsi,%riz,1),%esi
[ 366.362302][ T3447] RSP: 002b:00000000ffa75f8c EFLAGS: 00000296 ORIG_RAX: 0000000000000091
[ 366.363394][ T3447] RAX: ffffffffffffffda RBX: 00000000000000f7 RCX: 00000000580da6e0
[ 366.364419][ T3447] RDX: 000000000000005c RSI: 00000000710d3b51 RDI: 00000000ffffffff
[ 366.365453][ T3447] RBP: 00000000ffff0100 R08: 0000000000000000 R09: 0000000000000000
[ 366.366492][ T3447] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
[ 366.367518][ T3447] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 366.368584][ T3447] </TASK>
[ 382.029705][ T3448] trinity-c6 (3448): attempted to duplicate a private mapping with mremap. This is not supported.
[ 393.577743][ T3063] [main] 10786 iterations. [F:8083 S:2663 HI:1623]

The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20231113/202311131653.14708bb6-oliver.sang@xxxxxxxxx

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

Next message: tip-bot2 for Yuntao Wang: "[tip: x86/cleanups] x86/setup: Make relocated_ramdisk a local variable of relocate_initrd()"
Previous message: Gou Hao: "[PATCH] ext4: improving calculation of 'fe_{len|start}' in mb_find_extent()"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]