Re: [linus:master] [rcu/nocb] 7625926086: WARNING:at_kernel/rcu/tree_nocb.h:#rcu_nocb_try_bypass

From: Z qiang
Date: Tue Jul 11 2023 - 06:04:56 EST

Next message: James Clark: "[PATCH v3 5/5] perf vendor events arm64: Update N2-r0p0 metrics and events using Arm telemetry repo"
Previous message: James Clark: "[PATCH v3 4/5] perf vendor events arm64: Update N2-r0p3 and V2 metrics and events using Arm telemetry repo"
In reply to: Z qiang: "Re: [linus:master] [rcu/nocb] 7625926086: WARNING:at_kernel/rcu/tree_nocb.h:#rcu_nocb_try_bypass"
Next in thread: Frederic Weisbecker: "Re: [linus:master] [rcu/nocb] 7625926086: WARNING:at_kernel/rcu/tree_nocb.h:#rcu_nocb_try_bypass"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Tue, Jul 11, 2023 at 5:45 PM Z qiang <qiang.zhang1211@xxxxxxxxx> wrote:
>
> >
> >
> >
> > Hello,
> >
> > kernel test robot noticed "WARNING:at_kernel/rcu/tree_nocb.h:#rcu_nocb_try_bypass" on:
> >
> > commit: 7625926086765123251f765d91fc3a70617d334d ("rcu/nocb: Fix shrinker race against callback enqueuer")
> > https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
> >
> > [test failed on linus/master Linux 6.5-rc1]
> > [test failed on linux-next/master fe57d0d86f03a8b2afe2869a95477d0ed1824c96]
> >
> > in testcase: trinity
> > version: trinity-i386-abe9de86-1_20230429
> > with following parameters:
> >
> > runtime: 300s
> > group: group-00
> >
> > 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):
> >
> >
> > the WARNING only happens in a low rate (10 out of 204 runs as below).
> > but since we never observed the issue on parent, and we also noticed
> > there is a WARN_ON_ONCE in code change, so just report what we observed
> > in our tests FYI.
> >
> > 5c83cedbaaad6dfe 7625926086765123251f765d91f
> > ---------------- ---------------------------
> > fail:runs %reproduction fail:runs
> > | | |
> > :202 5% 10:204 dmesg.RIP:rcu_nocb_bypass_lock
> > :202 5% 10:204 dmesg.RIP:rcu_nocb_try_bypass
> > :202 5% 10:204 dmesg.WARNING:at_kernel/rcu/tree_nocb.h:#rcu_nocb_bypass_lock
> > :202 5% 10:204 dmesg.WARNING:at_kernel/rcu/tree_nocb.h:#rcu_nocb_try_bypass
> >
> >
> > 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/202307111535.4823c255-oliver.sang@xxxxxxxxx
> >
> >
> >
> > [ 315.569574][ T16] WARNING: CPU: 1 PID: 16 at kernel/rcu/tree_nocb.h:124 rcu_nocb_try_bypass (kernel/rcu/tree_nocb.h:124 kernel/rcu/tree_nocb.h:513)
> > [ 315.569582][ T16] Modules linked in: crc32c_intel polyval_clmulni polyval_generic ghash_clmulni_intel rapl qemu_fw_cfg intel_agp intel_gtt
> > [ 315.569591][ T16] CPU: 1 PID: 16 Comm: rcuop/0 Not tainted 6.4.0-rc1-00002-g762592608676 #1
> > [ 315.569594][ T16] RIP: 0010:rcu_nocb_try_bypass (kernel/rcu/tree_nocb.h:124 kernel/rcu/tree_nocb.h:513)
> > [ 315.569965][ T49] WARNING: CPU: 0 PID: 49 at kernel/rcu/tree_nocb.h:104 rcu_nocb_bypass_lock (kernel/rcu/tree_nocb.h:104 (discriminator 11))
> > [ 315.570472][ T16] Code: 41 0f b6 34 24 48 8b 54 24 08 e9 23 01 00 00 65 8b 05 32 7b f3 7e 3b 83 90 05 00 00 74 02 0f 0b 8b 83 48 02 00 00 85 c0 74 06 <0f> 0b f3 90 eb f0 48 89 df e8 44 7f ff ff 48 8b 3c 24 4c 8b a3 90
> > All code
> > ========
> > 0: 41 0f b6 34 24 movzbl (%r12),%esi
> > 5: 48 8b 54 24 08 mov 0x8(%rsp),%rdx
> > a: e9 23 01 00 00 jmp 0x132
> > f: 65 8b 05 32 7b f3 7e mov %gs:0x7ef37b32(%rip),%eax # 0x7ef37b48
> > 16: 3b 83 90 05 00 00 cmp 0x590(%rbx),%eax
> > 1c: 74 02 je 0x20
> > 1e: 0f 0b ud2
> > 20: 8b 83 48 02 00 00 mov 0x248(%rbx),%eax
> > 26: 85 c0 test %eax,%eax
> > 28: 74 06 je 0x30
> > 2a:* 0f 0b ud2 <-- trapping instruction
> > 2c: f3 90 pause
> > 2e: eb f0 jmp 0x20
> > 30: 48 89 df mov %rbx,%rdi
> > 33: e8 44 7f ff ff call 0xffffffffffff7f7c
> > 38: 48 8b 3c 24 mov (%rsp),%rdi
> > 3c: 4c rex.WR
> > 3d: 8b .byte 0x8b
> > 3e: a3 .byte 0xa3
> > 3f: 90 nop
> >
> > Code starting with the faulting instruction
> > ===========================================
> > 0: 0f 0b ud2
> > 2: f3 90 pause
> > 4: eb f0 jmp 0xfffffffffffffff6
> > 6: 48 89 df mov %rbx,%rdi
> > 9: e8 44 7f ff ff call 0xffffffffffff7f52
> > e: 48 8b 3c 24 mov (%rsp),%rdi
> > 12: 4c rex.WR
> > 13: 8b .byte 0x8b
> > 14: a3 .byte 0xa3
> > 15: 90 nop
> > [ 315.570981][ T49] Modules linked in: crc32c_intel
> > [ 315.571642][ T16] RSP: 0000:ffffc9000008bd60 EFLAGS: 00010002
> > [ 315.572102][ T49] polyval_clmulni
> > [ 315.572412][ T16]
> > [ 315.572413][ T16] RAX: 0000000000000001 RBX: ffff88842fd2e9c0 RCX: 0000000000000040
> > [ 315.572911][ T49] polyval_generic
> > [ 315.573917][ T16] RDX: 0000000100000eb8 RSI: ffff88842fd2ebe0 RDI: ffff88842fd2ea60
> > [ 315.574200][ T49] ghash_clmulni_intel
> > [ 315.574517][ T16] RBP: 0000000100000eb8 R08: 0000000000000001 R09: 0000000000000001
> > [ 315.574715][ T49] rapl qemu_fw_cfg
> > [ 315.574841][ T16] R10: 0000000000000000 R11: ffff88817e599608 R12: ffffc9000008bdcf
> > [ 315.575254][ T49] intel_agp
> > [ 315.575450][ T16] R13: 0000000000000001 R14: 0000000000000002 R15: 0000000000000002
> > [ 315.575863][ T49] intel_gtt
> > [ 315.576078][ T16] FS: 0000000000000000(0000) GS:ffff88842fd00000(0000) knlGS:0000000000000000
> > [ 315.576491][ T49]
> > [ 315.576694][ T16] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 315.577105][ T49] CPU: 0 PID: 49 Comm: kswapd0 Not tainted 6.4.0-rc1-00002-g762592608676 #1
> > [ 315.577277][ T16] CR2: 00000000f7f6f2e8 CR3: 0000000165fc4000 CR4: 00000000000406a0
> > [ 315.577689][ T49] RIP: 0010:rcu_nocb_bypass_lock (kernel/rcu/tree_nocb.h:104 (discriminator 11))
> > [ 315.577861][ T16] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [ 315.578340][ T49] Code: 0b 48 8d ab 40 03 00 00 48 89 ef e8 2f 78 af 00 85 c0 75 27 f0 ff 83 48 02 00 00 65 8b 05 85 fb f3 7e 39 83 90 05 00 00 74 02 <0f> 0b 48 89 ef e8 67 76 af 00 f0 ff 8b 48 02 00 00 5b 5d c3 cc 83
> > All code
> > ========
> > 0: 0b 48 8d or -0x73(%rax),%ecx
> > 3: ab stos %eax,%es:(%rdi)
> > 4: 40 03 00 rex add (%rax),%eax
> > 7: 00 48 89 add %cl,-0x77(%rax)
> > a: ef out %eax,(%dx)
> > b: e8 2f 78 af 00 call 0xaf783f
> > 10: 85 c0 test %eax,%eax
> > 12: 75 27 jne 0x3b
> > 14: f0 ff 83 48 02 00 00 lock incl 0x248(%rbx)
> > 1b: 65 8b 05 85 fb f3 7e mov %gs:0x7ef3fb85(%rip),%eax # 0x7ef3fba7
> > 22: 39 83 90 05 00 00 cmp %eax,0x590(%rbx)
> > 28: 74 02 je 0x2c
> > 2a:* 0f 0b ud2 <-- trapping instruction
> > 2c: 48 89 ef mov %rbp,%rdi
> > 2f: e8 67 76 af 00 call 0xaf769b
> > 34: f0 ff 8b 48 02 00 00 lock decl 0x248(%rbx)
> > 3b: 5b pop %rbx
> > 3c: 5d pop %rbp
> > 3d: c3 ret
> > 3e: cc int3
> > 3f: 83 .byte 0x83
> >
> > Code starting with the faulting instruction
> > ===========================================
> > 0: 0f 0b ud2
> > 2: 48 89 ef mov %rbp,%rdi
> > 5: e8 67 76 af 00 call 0xaf7671
> > a: f0 ff 8b 48 02 00 00 lock decl 0x248(%rbx)
> > 11: 5b pop %rbx
> > 12: 5d pop %rbp
> > 13: c3 ret
> > 14: cc int3
> > 15: 83 .byte 0x83
> > [ 315.578467][ T16] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > [ 315.578809][ T49] RSP: 0018:ffffc9000019bcb0 EFLAGS: 00010002
> > [ 315.579259][ T16] Call Trace:
> > [ 315.579261][ T16] <TASK>
> > [ 315.579673][ T49]
> > [ 315.579674][ T49] RAX: 0000000000000000 RBX: ffff88842fd2e9c0 RCX: 0000000000000000
> > [ 315.579980][ T16] ? find_next_bit (arch/x86/events/core.c:816 arch/x86/events/core.c:965)
> > [ 315.580390][ T49] RDX: ffff88842fd2ebe0 RSI: ffff88842fd2ebe0 RDI: ffff88842fd2ed00
> > [ 315.581398][ T16] __call_rcu_common (kernel/rcu/tree.c:2644)
> > [ 315.581812][ T49] RBP: ffff88842fd2ed00 R08: 0000000000000001 R09: 0000000000000001
> > [ 315.582136][ T16] slab_free+0x53/0xf7
> > [ 315.582311][ T49] R10: ffff88842fd2ebe0 R11: 0000000000000001 R12: 0000000000000000
> > [ 315.582469][ T16] rcu_do_batch (kernel/rcu/tree.c:2117)
> > [ 315.582594][ T49] R13: 0000000100000eb8 R14: ffffc9000019bd88 R15: 0000000000000202
> > [ 315.583009][ T16] nocb_cb_wait (kernel/rcu/tree_nocb.h:955)
> > [ 315.583301][ T49] FS: 0000000000000000(0000) GS:ffff88842fc00000(0000) knlGS:0000000000000000
> > [ 315.583716][ T16] ? nocb_cb_wait (kernel/rcu/tree_nocb.h:1003)
> > [ 315.583975][ T49] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 315.584388][ T16] rcu_nocb_cb_kthread (kernel/rcu/tree_nocb.h:1010 (discriminator 24))
> > [ 315.584686][ T49] CR2: 00000000590fb014 CR3: 0000000179d50000 CR4: 00000000000406b0
> > [ 315.585100][ T16] kthread (kernel/kthread.c:381)
> > [ 315.585339][ T49] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [ 315.585752][ T16] ? kthread_complete_and_exit (kernel/kthread.c:332)
> > [ 315.585990][ T49] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > [ 315.586462][ T16] ret_from_fork (arch/x86/entry/entry_64.S:314)
> > [ 315.586710][ T49] Call Trace:
> > [ 315.586711][ T49] <TASK>
> > [ 315.587058][ T16] </TASK>
> > [ 315.587313][ T49] rcu_nocb_flush_bypass (kernel/rcu/tree_nocb.h:381)
> > [ 315.587727][ T16] irq event stamp: 38560087
> > [ 315.587934][ T49] lazy_rcu_shrink_scan (kernel/rcu/tree_nocb.h:1367 (discriminator 6))
> > [ 315.588346][ T16] hardirqs last enabled at (38560086): _raw_spin_unlock_irqrestore (arch/x86/include/asm/irqflags.h:26 arch/x86/include/asm/irqflags.h:67 arch/x86/include/asm/irqflags.h:127 include/linux/spinlock_api_smp.h:151 kernel/locking/spinlock.c:194)
> > [ 315.588643][ T49] do_shrink_slab+0x1d0/0x2ea
> > [ 315.589056][ T16] hardirqs last disabled at (38560087): __call_rcu_common (kernel/rcu/tree.c:2629 (discriminator 3))
> > [ 315.589292][ T49] shrink_slab+0xa7/0x136
> > [ 315.589466][ T16] softirqs last enabled at (38560080): local_bh_enable (include/linux/bottom_half.h:33)
> > [ 315.589624][ T49] shrink_node (arch/x86/include/asm/current.h:41 mm/vmscan.c:565 mm/vmscan.c:6503)
> > [ 315.589784][ T16] softirqs last disabled at (38560082): local_bh_disable (include/linux/bottom_half.h:20)
> > [ 315.590054][ T49] balance_pgdat (mm/vmscan.c:7296 mm/vmscan.c:7477)
> > [ 315.590296][ T16] ---[ end trace 0000000000000000 ]---
> > [ 315.590570][ T49] kswapd (mm/vmscan.c:7737)
> > [ 315.594237][ T49] ? balance_pgdat (mm/vmscan.c:7670)
> > [ 315.594498][ T49] kthread (kernel/kthread.c:381)
> > [ 315.594711][ T49] ? kthread_complete_and_exit (kernel/kthread.c:332)
> > [ 315.595014][ T49] ret_from_fork (arch/x86/entry/entry_64.S:314)
> > [ 315.595260][ T49] </TASK>
> > [ 315.595427][ T49] irq event stamp: 123174
> > [ 315.595658][ T49] hardirqs last enabled at (123173): raw_spin_rq_unlock_irq (arch/x86/include/asm/irqflags.h:42 arch/x86/include/asm/irqflags.h:77 kernel/sched/sched.h:1378)
> > [ 315.596191][ T49] hardirqs last disabled at (123174): lazy_rcu_shrink_scan (kernel/rcu/tree_nocb.h:1366 (discriminator 3))
> > [ 315.596724][ T49] softirqs last enabled at (122534): __do_softirq (arch/x86/include/asm/preempt.h:27 kernel/softirq.c:415 kernel/softirq.c:600)
> > [ 315.597222][ T49] softirqs last disabled at (122527): __irq_exit_rcu (kernel/softirq.c:445 kernel/softirq.c:650)
> > [ 315.597720][ T49] ---[ end trace 0000000000000000 ]---
> > [ 315.622775][ T212] [main] kernel became tainted! (512/0) Last seed was 144492271
> > [ 315.622787][ T212]
> > [ 315.624666][ T212] trinity: Detected kernel tainting. Last seed was 144492271
> > [ 315.624673][ T212]
> > [ 315.626388][ T212] [main] 1282601 iterations. [F:915248 S:367378 HI:102957]
> >
> >
>
>
>
> The CONFIG_RCU_NOCB_CPU_DEFAULT_ALL=y
> WARNING: CPU: 1 PID: 16 at kernel/rcu/tree_nocb.h:124
> rcu_nocb_try_bypass+0x28d/0x3cc
> WARNING: CPU: 0 PID: 49 at kernel/rcu/tree_nocb.h:104
> rcu_nocb_bypass_lock+0x4f/0x64
>
> it looks like this:
>
> CPU0
>
> CPU1
> kswapd
> ->balance_pgdat
>
> rcu_nocb_cb_kthread()
> ->shrink_node
>
> ->nocb_cb_wait()
> ->shrink_slab
>
> ->rcu_do_batch()
> ->do_shrink_slab
>
> ->slab_free()
> ->lazy_rcu_shrink_scan
>
> ->__call_rcu_common()
> ->for_each_cpu(cpu, rcu_nocb_mask)
>
> ->rdp = this_cpu_ptr(&rcu_data) --->
> CPU1's rdp
> struct rcu_data *rdp =
> per_cpu_ptr(&rcu_data, CPU1);
> ->rcu_nocb_try_bypass()
> rcu_nocb_flush_bypass(rdp);
>
> .....
> rcu_nocb_bypass_lock(rdp)
> atomic_inc(&rdp->nocb_lock_contended);
>
> WARN_ON_ONCE(smp_processor_id() != rdp->cpu);
>
> ->rcu_nocb_wait_contended(rdp);
>
>
>
> atomic_read(&rdp->nocb_lock_contended))
>

kswapd run on CPU0 to access CPU1's rdp and inc
rdp->nocb_lock_contended, trigger WARN_ON_ONCE(smp_processor_id() !=
rdp->cpu),
CPU1 invoke rcu_nocb_try_bypass() trigger
WARN_ON_ONCE(atomic_read(&rdp->nocb_lock_contended).

> Should the WARN_ON_ONCE() check be removed?
>
>
> Thanks
> Zqiang
>
>
>
>
>
>
> >
> > To reproduce:
> >
> > # build kernel
> > cd linux
> > cp config-6.4.0-rc1-00002-g762592608676 .config
> > make HOSTCC=gcc-12 CC=gcc-12 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage modules
> > make HOSTCC=gcc-12 CC=gcc-12 ARCH=x86_64 INSTALL_MOD_PATH=<mod-install-dir> modules_install
> > cd <mod-install-dir>
> > find lib/ | cpio -o -H newc --quiet | gzip > modules.cgz
> >
> >
> > git clone https://github.com/intel/lkp-tests.git
> > cd lkp-tests
> > bin/lkp qemu -k <bzImage> -m modules.cgz job-script # job-script is attached in this email
> >
> > # if come across any failure that blocks the test,
> > # please remove ~/.lkp and /lkp dir to run from a clean state.
> >
> >
> >
> > --
> > 0-DAY CI Kernel Test Service
> > https://github.com/intel/lkp-tests/wiki
> >

Next message: James Clark: "[PATCH v3 5/5] perf vendor events arm64: Update N2-r0p0 metrics and events using Arm telemetry repo"
Previous message: James Clark: "[PATCH v3 4/5] perf vendor events arm64: Update N2-r0p3 and V2 metrics and events using Arm telemetry repo"
In reply to: Z qiang: "Re: [linus:master] [rcu/nocb] 7625926086: WARNING:at_kernel/rcu/tree_nocb.h:#rcu_nocb_try_bypass"
Next in thread: Frederic Weisbecker: "Re: [linus:master] [rcu/nocb] 7625926086: WARNING:at_kernel/rcu/tree_nocb.h:#rcu_nocb_try_bypass"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]