* [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]
@ 2025-04-21 7:39 kernel test robot
2025-04-21 16:34 ` Paul E. McKenney
0 siblings, 1 reply; 9+ messages in thread
From: kernel test robot @ 2025-04-21 7:39 UTC (permalink / raw)
To: Paul E. McKenney; +Cc: oe-lkp, lkp, Joel Fernandes, linux-kernel, oliver.sang
Hello,
kernel test robot noticed "WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]" on:
commit: ddd062f7536cc09fe7ff1a66816601984bc68af8 ("rcutorture: Complain if an ->up_read() is delayed more than 10 seconds")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
[test failed on linux-next/master f660850bc246fef15ba78c81f686860324396628]
in testcase: rcutorture
version:
with following parameters:
runtime: 300s
test: cpuhotplug
torture_type: srcud
config: x86_64-randconfig-123-20250415
compiler: clang-20
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
(please refer to attached dmesg/kmsg for entire log/backtrace)
+-------------------------------------------------------------------------+------------+------------+
| | 1b983c34d5 | ddd062f753 |
+-------------------------------------------------------------------------+------------+------------+
| WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture] | 0 | 24 |
| RIP:rcu_torture_updown[rcutorture] | 0 | 24 |
+-------------------------------------------------------------------------+------------+------------+
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@intel.com>
| Closes: https://lore.kernel.org/oe-lkp/202504211513.23f21a0-lkp@intel.com
The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20250421/202504211513.23f21a0-lkp@intel.com
[ 147.544571][ T727] ------------[ cut here ]------------
[ 147.545372][ T727] WARNING: CPU: 0 PID: 727 at kernel/rcu/rcutorture.c:2549 rcu_torture_updown+0xe0/0x430 [rcutorture]
[ 147.546643][ T727] Modules linked in: rcutorture torture
[ 147.547462][ T727] CPU: 0 UID: 0 PID: 727 Comm: rcu_torture_upd Not tainted 6.15.0-rc1-00008-gddd062f7536c #1 NONE 0a926b04a3771ed2623ec5d12c96d338a637f034
[ 147.549036][ T727] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 147.550241][ T727] RIP: 0010:rcu_torture_updown+0xe0/0x430 [rcutorture]
[ 147.551128][ T727] Code: 00 00 48 01 c3 48 8b 44 24 10 42 80 3c 20 00 74 0c 48 c7 c7 00 12 41 87 e8 fd 1b 49 e1 48 3b 1d a6 58 e0 e6 0f 89 84 01 00 00 <0f> 0b e9 7d 01 00 00 4c 89 7c 24 08 4f 8d 3c 2e 49 83 c7 60 4b 8d
[ 147.553366][ T727] RSP: 0000:ffff888150ebfe60 EFLAGS: 00210297
[ 147.554154][ T727] RAX: 1ffffffff0e82240 RBX: 00000000ffffc39e RCX: 0000000000000000
[ 147.555179][ T727] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff888150eb3450
[ 147.572489][ T727] RBP: ffff888150eb6bd8 R08: 0000000000000000 R09: 0000000000000000
[ 147.573518][ T727] R10: 0000000000000000 R11: 0000000000000000 R12: dffffc0000000000
[ 147.574582][ T727] R13: ffff888150eb0000 R14: 0000000000003408 R15: ffff888150eb3448
[ 147.577955][ T727] FS: 0000000000000000(0000) GS:ffff888424c90000(0000) knlGS:0000000000000000
[ 147.579066][ T727] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 147.579850][ T727] CR2: 00000000f729a000 CR3: 000000014d67f000 CR4: 00000000000406f0
[ 147.580851][ T727] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 147.581887][ T727] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 147.582799][ T727] Call Trace:
[ 147.583264][ T727] <TASK>
[ 147.583703][ T727] kthread+0x4b7/0x5e0
[ 147.584257][ T727] ? rcu_torture_updown_hrt+0x60/0x60 [rcutorture 02ecf78e8bf32d7a769b787a1e354f19e873c8f2]
[ 147.591263][ T727] ? kthread_unuse_mm+0x150/0x150
[ 147.591978][ T727] ret_from_fork+0x3c/0x70
[ 147.592545][ T727] ? kthread_unuse_mm+0x150/0x150
[ 147.593167][ T727] ret_from_fork_asm+0x11/0x20
[ 147.593805][ T727] </TASK>
[ 147.594276][ T727] irq event stamp: 340637
[ 147.597624][ T727] hardirqs last enabled at (340653): [<ffffffff815a4e82>] __console_unlock+0x72/0x80
[ 147.598763][ T727] hardirqs last disabled at (340662): [<ffffffff815a4e67>] __console_unlock+0x57/0x80
[ 147.599920][ T727] softirqs last enabled at (340578): [<ffffffff8148ecce>] handle_softirqs+0x5de/0x6e0
[ 147.601075][ T727] softirqs last disabled at (340569): [<ffffffff8148ef41>] __irq_exit_rcu+0x61/0xc0
[ 147.602178][ T727] ---[ end trace 0000000000000000 ]---
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]
2025-04-21 7:39 [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture] kernel test robot
@ 2025-04-21 16:34 ` Paul E. McKenney
2025-04-22 5:01 ` Oliver Sang
0 siblings, 1 reply; 9+ messages in thread
From: Paul E. McKenney @ 2025-04-21 16:34 UTC (permalink / raw)
To: kernel test robot; +Cc: oe-lkp, lkp, Joel Fernandes, linux-kernel
On Mon, Apr 21, 2025 at 03:39:41PM +0800, kernel test robot wrote:
>
>
> Hello,
>
> kernel test robot noticed "WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]" on:
>
> commit: ddd062f7536cc09fe7ff1a66816601984bc68af8 ("rcutorture: Complain if an ->up_read() is delayed more than 10 seconds")
> https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
>
> [test failed on linux-next/master f660850bc246fef15ba78c81f686860324396628]
>
> in testcase: rcutorture
> version:
> with following parameters:
>
> runtime: 300s
> test: cpuhotplug
> torture_type: srcud
>
>
>
> config: x86_64-randconfig-123-20250415
> compiler: clang-20
> test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
>
> (please refer to attached dmesg/kmsg for entire log/backtrace)
>
>
> +-------------------------------------------------------------------------+------------+------------+
> | | 1b983c34d5 | ddd062f753 |
> +-------------------------------------------------------------------------+------------+------------+
> | WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture] | 0 | 24 |
> | RIP:rcu_torture_updown[rcutorture] | 0 | 24 |
> +-------------------------------------------------------------------------+------------+------------+
>
>
> 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@intel.com>
> | Closes: https://lore.kernel.org/oe-lkp/202504211513.23f21a0-lkp@intel.com
>
>
> The kernel config and materials to reproduce are available at:
> https://download.01.org/0day-ci/archive/20250421/202504211513.23f21a0-lkp@intel.com
Good catch, and thank you for your testing efforts!
Does the patch at the end of this email help?
Thanx, Paul
> [ 147.544571][ T727] ------------[ cut here ]------------
> [ 147.545372][ T727] WARNING: CPU: 0 PID: 727 at kernel/rcu/rcutorture.c:2549 rcu_torture_updown+0xe0/0x430 [rcutorture]
> [ 147.546643][ T727] Modules linked in: rcutorture torture
> [ 147.547462][ T727] CPU: 0 UID: 0 PID: 727 Comm: rcu_torture_upd Not tainted 6.15.0-rc1-00008-gddd062f7536c #1 NONE 0a926b04a3771ed2623ec5d12c96d338a637f034
> [ 147.549036][ T727] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
> [ 147.550241][ T727] RIP: 0010:rcu_torture_updown+0xe0/0x430 [rcutorture]
> [ 147.551128][ T727] Code: 00 00 48 01 c3 48 8b 44 24 10 42 80 3c 20 00 74 0c 48 c7 c7 00 12 41 87 e8 fd 1b 49 e1 48 3b 1d a6 58 e0 e6 0f 89 84 01 00 00 <0f> 0b e9 7d 01 00 00 4c 89 7c 24 08 4f 8d 3c 2e 49 83 c7 60 4b 8d
> [ 147.553366][ T727] RSP: 0000:ffff888150ebfe60 EFLAGS: 00210297
> [ 147.554154][ T727] RAX: 1ffffffff0e82240 RBX: 00000000ffffc39e RCX: 0000000000000000
> [ 147.555179][ T727] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff888150eb3450
> [ 147.572489][ T727] RBP: ffff888150eb6bd8 R08: 0000000000000000 R09: 0000000000000000
> [ 147.573518][ T727] R10: 0000000000000000 R11: 0000000000000000 R12: dffffc0000000000
> [ 147.574582][ T727] R13: ffff888150eb0000 R14: 0000000000003408 R15: ffff888150eb3448
> [ 147.577955][ T727] FS: 0000000000000000(0000) GS:ffff888424c90000(0000) knlGS:0000000000000000
> [ 147.579066][ T727] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 147.579850][ T727] CR2: 00000000f729a000 CR3: 000000014d67f000 CR4: 00000000000406f0
> [ 147.580851][ T727] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 147.581887][ T727] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 147.582799][ T727] Call Trace:
> [ 147.583264][ T727] <TASK>
> [ 147.583703][ T727] kthread+0x4b7/0x5e0
> [ 147.584257][ T727] ? rcu_torture_updown_hrt+0x60/0x60 [rcutorture 02ecf78e8bf32d7a769b787a1e354f19e873c8f2]
> [ 147.591263][ T727] ? kthread_unuse_mm+0x150/0x150
> [ 147.591978][ T727] ret_from_fork+0x3c/0x70
> [ 147.592545][ T727] ? kthread_unuse_mm+0x150/0x150
> [ 147.593167][ T727] ret_from_fork_asm+0x11/0x20
> [ 147.593805][ T727] </TASK>
> [ 147.594276][ T727] irq event stamp: 340637
> [ 147.597624][ T727] hardirqs last enabled at (340653): [<ffffffff815a4e82>] __console_unlock+0x72/0x80
> [ 147.598763][ T727] hardirqs last disabled at (340662): [<ffffffff815a4e67>] __console_unlock+0x57/0x80
> [ 147.599920][ T727] softirqs last enabled at (340578): [<ffffffff8148ecce>] handle_softirqs+0x5de/0x6e0
> [ 147.601075][ T727] softirqs last disabled at (340569): [<ffffffff8148ef41>] __irq_exit_rcu+0x61/0xc0
> [ 147.602178][ T727] ---[ end trace 0000000000000000 ]---
>
>
> --
> 0-DAY CI Kernel Test Service
> https://github.com/intel/lkp-tests/wiki
diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index 3dd213bfc6662..53f0860b3748d 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -2557,6 +2557,7 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
static int
rcu_torture_updown(void *arg)
{
+ unsigned long j;
struct rcu_torture_one_read_state_updown *rtorsup;
VERBOSE_TOROUT_STRING("rcu_torture_updown task started");
@@ -2564,8 +2565,9 @@ rcu_torture_updown(void *arg)
for (rtorsup = updownreaders; rtorsup < &updownreaders[n_up_down]; rtorsup++) {
if (torture_must_stop())
break;
+ j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
- WARN_ON_ONCE(time_after(jiffies, rtorsup->rtorsu_j + 10 * HZ));
+ WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
continue;
}
rcu_torture_updown_one(rtorsup);
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]
2025-04-21 16:34 ` Paul E. McKenney
@ 2025-04-22 5:01 ` Oliver Sang
2025-04-22 17:54 ` Paul E. McKenney
0 siblings, 1 reply; 9+ messages in thread
From: Oliver Sang @ 2025-04-22 5:01 UTC (permalink / raw)
To: Paul E. McKenney; +Cc: oe-lkp, lkp, Joel Fernandes, linux-kernel, oliver.sang
[-- Attachment #1: Type: text/plain, Size: 8997 bytes --]
hi, Paul,
On Mon, Apr 21, 2025 at 09:34:34AM -0700, Paul E. McKenney wrote:
> On Mon, Apr 21, 2025 at 03:39:41PM +0800, kernel test robot wrote:
> >
> >
> > Hello,
> >
> > kernel test robot noticed "WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]" on:
> >
> > commit: ddd062f7536cc09fe7ff1a66816601984bc68af8 ("rcutorture: Complain if an ->up_read() is delayed more than 10 seconds")
> > https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
> >
> > [test failed on linux-next/master f660850bc246fef15ba78c81f686860324396628]
> >
> > in testcase: rcutorture
> > version:
> > with following parameters:
> >
> > runtime: 300s
> > test: cpuhotplug
> > torture_type: srcud
> >
> >
> >
> > config: x86_64-randconfig-123-20250415
> > compiler: clang-20
> > test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
> >
> > (please refer to attached dmesg/kmsg for entire log/backtrace)
> >
> >
> > +-------------------------------------------------------------------------+------------+------------+
> > | | 1b983c34d5 | ddd062f753 |
> > +-------------------------------------------------------------------------+------------+------------+
> > | WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture] | 0 | 24 |
> > | RIP:rcu_torture_updown[rcutorture] | 0 | 24 |
> > +-------------------------------------------------------------------------+------------+------------+
> >
> >
> > 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@intel.com>
> > | Closes: https://lore.kernel.org/oe-lkp/202504211513.23f21a0-lkp@intel.com
> >
> >
> > The kernel config and materials to reproduce are available at:
> > https://download.01.org/0day-ci/archive/20250421/202504211513.23f21a0-lkp@intel.com
>
> Good catch, and thank you for your testing efforts!
>
> Does the patch at the end of this email help?
sorry but the patch does not help. one dmesg is attached.
[ 107.907141][ T690] ------------[ cut here ]------------
[ 107.907879][ T690] WARNING: CPU: 1 PID: 690 at kernel/rcu/rcutorture.c:2551 rcu_torture_updown+0xe7/0x440 [rcutorture]
[ 107.909122][ T690] Modules linked in: rcutorture torture
[ 107.909866][ T690] CPU: 1 UID: 0 PID: 690 Comm: rcu_torture_upd Not tainted 6.15.0-rc1-00009-g1539a7e7b61a #1 NONE 80728dbb8fc06cc6d40cbe8225bf0332ec562ffc
[ 107.911393][ T690] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 107.912576][ T690] RIP: 0010:rcu_torture_updown+0xe7/0x440 [rcutorture]
[ 107.913397][ T690] Code: 83 c7 48 48 89 f8 48 c1 e8 03 42 80 3c 20 00 74 05 e8 fd 1b 49 e1 4b 8b 44 35 48 4c 29 f8 48 05 e8 03 00 00 0f 89 83 01 00 00 <0f> 0b e9 7c 01 00 00 48 89 14 24 4f 8d 3c 2e 49 83 c7 60 4b 8d 34
[ 107.915455][ T690] RSP: 0000:ffff88814faffe58 EFLAGS: 00010286
[ 107.916177][ T690] RAX: ffffffffffffffff RBX: 1ffff11029f5d0e6 RCX: 0000000000000000
[ 107.917147][ T690] RDX: ffff88814fae8730 RSI: 0000000000000000 RDI: ffff88814fae8738
[ 107.918090][ T690] RBP: 1ffffffff0e82240 R08: 0000000000000000 R09: 0000000000000000
[ 107.919037][ T690] R10: 0000000000000000 R11: 0000000000000000 R12: dffffc0000000000
[ 107.919951][ T690] R13: ffff88814fae8000 R14: 00000000000006f0 R15: 00000000ffffb465
[ 107.920887][ T690] FS: 0000000000000000(0000) GS:ffff888424d90000(0000) knlGS:0000000000000000
[ 107.921860][ T690] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 107.922580][ T690] CR2: 0000000000000000 CR3: 00000000074c7000 CR4: 00000000000406f0
[ 107.923440][ T690] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 107.924399][ T690] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 107.930033][ T690] Call Trace:
[ 107.931026][ T690] <TASK>
[ 107.932020][ T690] kthread+0x4b7/0x5e0
[ 107.933172][ T690] ? rcu_torture_updown_hrt+0x60/0x60 [rcutorture c962c7aca4575a73724d201f7e88cd5b0e155a86]
[ 107.935470][ T690] ? kthread_unuse_mm+0x150/0x150
[ 107.936721][ T690] ret_from_fork+0x3c/0x70
[ 107.937838][ T690] ? kthread_unuse_mm+0x150/0x150
[ 107.939068][ T690] ret_from_fork_asm+0x11/0x20
[ 107.939985][ T690] </TASK>
[ 107.940827][ T690] irq event stamp: 83209
[ 107.941950][ T690] hardirqs last enabled at (83219): [<ffffffff815a4e82>] __console_unlock+0x72/0x80
[ 107.944134][ T690] hardirqs last disabled at (83228): [<ffffffff815a4e67>] __console_unlock+0x57/0x80
[ 107.946289][ T690] softirqs last enabled at (83174): [<ffffffff8148ecce>] handle_softirqs+0x5de/0x6e0
[ 107.948395][ T690] softirqs last disabled at (83169): [<ffffffff8148ef41>] __irq_exit_rcu+0x61/0xc0
[ 107.950232][ T690] ---[ end trace 0000000000000000 ]---
>
> Thanx, Paul
>
> > [ 147.544571][ T727] ------------[ cut here ]------------
> > [ 147.545372][ T727] WARNING: CPU: 0 PID: 727 at kernel/rcu/rcutorture.c:2549 rcu_torture_updown+0xe0/0x430 [rcutorture]
> > [ 147.546643][ T727] Modules linked in: rcutorture torture
> > [ 147.547462][ T727] CPU: 0 UID: 0 PID: 727 Comm: rcu_torture_upd Not tainted 6.15.0-rc1-00008-gddd062f7536c #1 NONE 0a926b04a3771ed2623ec5d12c96d338a637f034
> > [ 147.549036][ T727] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
> > [ 147.550241][ T727] RIP: 0010:rcu_torture_updown+0xe0/0x430 [rcutorture]
> > [ 147.551128][ T727] Code: 00 00 48 01 c3 48 8b 44 24 10 42 80 3c 20 00 74 0c 48 c7 c7 00 12 41 87 e8 fd 1b 49 e1 48 3b 1d a6 58 e0 e6 0f 89 84 01 00 00 <0f> 0b e9 7d 01 00 00 4c 89 7c 24 08 4f 8d 3c 2e 49 83 c7 60 4b 8d
> > [ 147.553366][ T727] RSP: 0000:ffff888150ebfe60 EFLAGS: 00210297
> > [ 147.554154][ T727] RAX: 1ffffffff0e82240 RBX: 00000000ffffc39e RCX: 0000000000000000
> > [ 147.555179][ T727] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff888150eb3450
> > [ 147.572489][ T727] RBP: ffff888150eb6bd8 R08: 0000000000000000 R09: 0000000000000000
> > [ 147.573518][ T727] R10: 0000000000000000 R11: 0000000000000000 R12: dffffc0000000000
> > [ 147.574582][ T727] R13: ffff888150eb0000 R14: 0000000000003408 R15: ffff888150eb3448
> > [ 147.577955][ T727] FS: 0000000000000000(0000) GS:ffff888424c90000(0000) knlGS:0000000000000000
> > [ 147.579066][ T727] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 147.579850][ T727] CR2: 00000000f729a000 CR3: 000000014d67f000 CR4: 00000000000406f0
> > [ 147.580851][ T727] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [ 147.581887][ T727] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > [ 147.582799][ T727] Call Trace:
> > [ 147.583264][ T727] <TASK>
> > [ 147.583703][ T727] kthread+0x4b7/0x5e0
> > [ 147.584257][ T727] ? rcu_torture_updown_hrt+0x60/0x60 [rcutorture 02ecf78e8bf32d7a769b787a1e354f19e873c8f2]
> > [ 147.591263][ T727] ? kthread_unuse_mm+0x150/0x150
> > [ 147.591978][ T727] ret_from_fork+0x3c/0x70
> > [ 147.592545][ T727] ? kthread_unuse_mm+0x150/0x150
> > [ 147.593167][ T727] ret_from_fork_asm+0x11/0x20
> > [ 147.593805][ T727] </TASK>
> > [ 147.594276][ T727] irq event stamp: 340637
> > [ 147.597624][ T727] hardirqs last enabled at (340653): [<ffffffff815a4e82>] __console_unlock+0x72/0x80
> > [ 147.598763][ T727] hardirqs last disabled at (340662): [<ffffffff815a4e67>] __console_unlock+0x57/0x80
> > [ 147.599920][ T727] softirqs last enabled at (340578): [<ffffffff8148ecce>] handle_softirqs+0x5de/0x6e0
> > [ 147.601075][ T727] softirqs last disabled at (340569): [<ffffffff8148ef41>] __irq_exit_rcu+0x61/0xc0
> > [ 147.602178][ T727] ---[ end trace 0000000000000000 ]---
> >
> >
> > --
> > 0-DAY CI Kernel Test Service
> > https://github.com/intel/lkp-tests/wiki
>
> diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> index 3dd213bfc6662..53f0860b3748d 100644
> --- a/kernel/rcu/rcutorture.c
> +++ b/kernel/rcu/rcutorture.c
> @@ -2557,6 +2557,7 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> static int
> rcu_torture_updown(void *arg)
> {
> + unsigned long j;
> struct rcu_torture_one_read_state_updown *rtorsup;
>
> VERBOSE_TOROUT_STRING("rcu_torture_updown task started");
> @@ -2564,8 +2565,9 @@ rcu_torture_updown(void *arg)
> for (rtorsup = updownreaders; rtorsup < &updownreaders[n_up_down]; rtorsup++) {
> if (torture_must_stop())
> break;
> + j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
> if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
> - WARN_ON_ONCE(time_after(jiffies, rtorsup->rtorsu_j + 10 * HZ));
> + WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
> continue;
> }
> rcu_torture_updown_one(rtorsup);
[-- Attachment #2: dmesg.xz --]
[-- Type: application/x-xz, Size: 32172 bytes --]
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]
2025-04-22 5:01 ` Oliver Sang
@ 2025-04-22 17:54 ` Paul E. McKenney
2025-04-24 1:50 ` Oliver Sang
0 siblings, 1 reply; 9+ messages in thread
From: Paul E. McKenney @ 2025-04-22 17:54 UTC (permalink / raw)
To: Oliver Sang; +Cc: oe-lkp, lkp, Joel Fernandes, linux-kernel
On Tue, Apr 22, 2025 at 01:01:58PM +0800, Oliver Sang wrote:
> hi, Paul,
>
> On Mon, Apr 21, 2025 at 09:34:34AM -0700, Paul E. McKenney wrote:
> > On Mon, Apr 21, 2025 at 03:39:41PM +0800, kernel test robot wrote:
> > >
> > >
> > > Hello,
> > >
> > > kernel test robot noticed "WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]" on:
> > >
> > > commit: ddd062f7536cc09fe7ff1a66816601984bc68af8 ("rcutorture: Complain if an ->up_read() is delayed more than 10 seconds")
> > > https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
> > >
> > > [test failed on linux-next/master f660850bc246fef15ba78c81f686860324396628]
> > >
> > > in testcase: rcutorture
> > > version:
> > > with following parameters:
> > >
> > > runtime: 300s
> > > test: cpuhotplug
> > > torture_type: srcud
> > >
> > >
> > >
> > > config: x86_64-randconfig-123-20250415
> > > compiler: clang-20
> > > test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
> > >
> > > (please refer to attached dmesg/kmsg for entire log/backtrace)
> > >
> > >
> > > +-------------------------------------------------------------------------+------------+------------+
> > > | | 1b983c34d5 | ddd062f753 |
> > > +-------------------------------------------------------------------------+------------+------------+
> > > | WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture] | 0 | 24 |
> > > | RIP:rcu_torture_updown[rcutorture] | 0 | 24 |
> > > +-------------------------------------------------------------------------+------------+------------+
> > >
> > >
> > > 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@intel.com>
> > > | Closes: https://lore.kernel.org/oe-lkp/202504211513.23f21a0-lkp@intel.com
> > >
> > >
> > > The kernel config and materials to reproduce are available at:
> > > https://download.01.org/0day-ci/archive/20250421/202504211513.23f21a0-lkp@intel.com
> >
> > Good catch, and thank you for your testing efforts!
> >
> > Does the patch at the end of this email help?
>
> sorry but the patch does not help. one dmesg is attached.
And idiot here failed to check for the exact same problem at the point
where the timer is queued, so thank you for bearing with me.
Does the patch at the end of this email (in addition to the previous
patch) get the job done?
Thanx, Paul
[ . . . ]
> > diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> > index 3dd213bfc6662..53f0860b3748d 100644
> > --- a/kernel/rcu/rcutorture.c
> > +++ b/kernel/rcu/rcutorture.c
> > @@ -2557,6 +2557,7 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> > static int
> > rcu_torture_updown(void *arg)
> > {
> > + unsigned long j;
> > struct rcu_torture_one_read_state_updown *rtorsup;
> >
> > VERBOSE_TOROUT_STRING("rcu_torture_updown task started");
> > @@ -2564,8 +2565,9 @@ rcu_torture_updown(void *arg)
> > for (rtorsup = updownreaders; rtorsup < &updownreaders[n_up_down]; rtorsup++) {
> > if (torture_must_stop())
> > break;
> > + j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
> > if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
> > - WARN_ON_ONCE(time_after(jiffies, rtorsup->rtorsu_j + 10 * HZ));
> > + WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
> > continue;
> > }
> > rcu_torture_updown_one(rtorsup);
diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index abe48ff48f54c..7268e33086eb4 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -2449,6 +2449,7 @@ struct rcu_torture_one_read_state_updown {
struct hrtimer rtorsu_hrt;
bool rtorsu_inuse;
int rtorsu_cpu;
+ ktime_t rtorsu_kt;
unsigned long rtorsu_j;
unsigned long rtorsu_ndowns;
unsigned long rtorsu_nups;
@@ -2548,12 +2549,14 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
schedule_timeout_idle(HZ);
return;
}
- rtorsup->rtorsu_j = jiffies;
smp_store_release(&rtorsup->rtorsu_inuse, true);
t = torture_random(&rtorsup->rtorsu_trs) & 0xfffff; // One per million.
if (t < 10 * 1000)
t = 200 * 1000 * 1000;
hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
+ smp_mb(); // Sample jiffies after posting hrtimer.
+ rtorsup->rtorsu_j = jiffies; // Not used by hrtimer handler.
+ rtorsup->rtorsu_kt = t;
}
/*
@@ -2574,7 +2577,8 @@ rcu_torture_updown(void *arg)
break;
j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
- WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
+ WARN_ONCE(time_after(j, rtorsup->rtorsu_j + 1 + HZ * 10),
+ "hrtimer queued at jiffies %lu for %lld ns took %lu jiffies\n", rtorsup->rtorsu_j, rtorsup->rtorsu_kt, j - rtorsup->rtorsu_j);
continue;
}
rcu_torture_updown_one(rtorsup);
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]
2025-04-22 17:54 ` Paul E. McKenney
@ 2025-04-24 1:50 ` Oliver Sang
2025-04-24 3:05 ` Paul E. McKenney
0 siblings, 1 reply; 9+ messages in thread
From: Oliver Sang @ 2025-04-24 1:50 UTC (permalink / raw)
To: Paul E. McKenney; +Cc: oe-lkp, lkp, Joel Fernandes, linux-kernel, oliver.sang
[-- Attachment #1: Type: text/plain, Size: 9487 bytes --]
hi, Paul,
On Tue, Apr 22, 2025 at 10:54:10AM -0700, Paul E. McKenney wrote:
[...]
> > > >
> > > > 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@intel.com>
> > > > | Closes: https://lore.kernel.org/oe-lkp/202504211513.23f21a0-lkp@intel.com
> > > >
> > > >
> > > > The kernel config and materials to reproduce are available at:
> > > > https://download.01.org/0day-ci/archive/20250421/202504211513.23f21a0-lkp@intel.com
> > >
> > > Good catch, and thank you for your testing efforts!
> > >
> > > Does the patch at the end of this email help?
> >
> > sorry but the patch does not help. one dmesg is attached.
>
> And idiot here failed to check for the exact same problem at the point
> where the timer is queued, so thank you for bearing with me.
>
> Does the patch at the end of this email (in addition to the previous
> patch) get the job done?
unfortunately, it still doesn't fix, one dmesg is attached. part of is as [2]
but I applied your two patches directly upon ddd062f753, like below:
* 1c91d0bd4809f (linux-devel/fixup-1539a7e7b61a9) further patch for ddd062f753 from Paul
* 1539a7e7b61a9 (linux-devel/fixup-ddd062f753) fix for ddd062f753 from Paul E. McKenney
* ddd062f7536cc rcutorture: Complain if an ->up_read() is delayed more than 10 seconds
* 1b983c34d5695 rcutorture: Comment invocations of tick_dep_set_task()
I noticed there are some conflicts while applying your second patch, the
1c91d0bd4809f looks like [1]. there is no "int rtorsu_cpu;" before line:
+ ktime_t rtorsu_kt;
seems your patch has a different base? I worried if my applyment has
problems. if so, could you tell me the correct base? thanks!
[1]
commit 1c91d0bd4809f9f12e61f25d881a02f25c473702 (linux-devel/fixup-1539a7e7b61a9)
Author: 0day robot <lkp@intel.com>
Date: Wed Apr 23 10:27:51 2025 +0800
further patch for ddd062f753 from Paul
Signed-off-by: 0day robot <lkp@intel.com>
diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index e7b5811e0e456..14cc67d436c97 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -2438,6 +2438,7 @@ rcu_torture_reader(void *arg)
struct rcu_torture_one_read_state_updown {
struct hrtimer rtorsu_hrt;
bool rtorsu_inuse;
+ ktime_t rtorsu_kt;
unsigned long rtorsu_j;
struct torture_random_state rtorsu_trs;
struct rcu_torture_one_read_state rtorsu_rtors;
@@ -2522,12 +2523,14 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
schedule_timeout_idle(HZ);
return;
}
- rtorsup->rtorsu_j = jiffies;
smp_store_release(&rtorsup->rtorsu_inuse, true);
t = torture_random(&rtorsup->rtorsu_trs) & 0xfffff; // One per million.
if (t < 10 * 1000)
t = 200 * 1000 * 1000;
hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
+ smp_mb(); // Sample jiffies after posting hrtimer.
+ rtorsup->rtorsu_j = jiffies; // Not used by hrtimer handler.
+ rtorsup->rtorsu_kt = t;
}
/*
@@ -2548,7 +2551,9 @@ rcu_torture_updown(void *arg)
break;
j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
- WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
+ WARN_ONCE(time_after(j, rtorsup->rtorsu_j + 1 + HZ * 10),
+ "hrtimer queued at jiffies %lu for %lld ns took %lu jiffies\n", rtorsup->rtorsu_j, rtorsup->rtorsu_kt, j - rtorsup->rtorsu_j);
continue;
}
rcu_torture_updown_one(rtorsup);
[2]
[ 168.048387][ T796] ------------[ cut here ]------------
[ 168.049342][ T796] hrtimer queued at jiffies 4294952214 for 200000000 ns took 1502 jiffies
[ 168.050699][ T796] WARNING: CPU: 0 PID: 796 at kernel/rcu/rcutorture.c:2555 rcu_torture_updown+0x143/0x4f0 [rcutorture]
[ 168.052702][ T796] Modules linked in: rcutorture torture
[ 168.054084][ T796] CPU: 0 UID: 0 PID: 796 Comm: rcu_torture_upd Not tainted 6.15.0-rc1-00010-g1c91d0bd4809 #1 NONE e0cf54ed16af150d49bfa95e1fe661f9e9161d42
[ 168.056119][ T796] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 168.058045][ T796] RIP: 0010:rcu_torture_updown+0x143/0x4f0 [rcutorture]
[ 168.059229][ T796] Code: 48 c1 e8 03 42 80 3c 38 00 74 05 e8 a7 1b 49 e1 49 8b 54 2d 48 49 29 de 48 c7 c7 c0 9e 5e a0 48 89 de 4c 89 f1 e8 dd 6a c4 e0 <0f> 0b e9 d2 01 00 00 4c 89 24 24 4c 8d 34 2d 68 00 00 00 4d 01 ee
[ 168.061887][ T796] RSP: 0000:ffff888152bf7e60 EFLAGS: 00210246
[ 168.062804][ T796] RAX: 0000000000000000 RBX: 00000000ffffc516 RCX: 0000000000000000
[ 168.064097][ T796] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[ 168.065436][ T796] RBP: 0000000000002a00 R08: 0000000000000000 R09: 0000000000000000
[ 168.066674][ T796] R10: 0000000000000000 R11: 0000000000000000 R12: ffff888150812a40
[ 168.067932][ T796] R13: ffff888150810000 R14: 00000000000005de R15: dffffc0000000000
[ 168.069302][ T796] FS: 0000000000000000(0000) GS:ffff888424c90000(0000) knlGS:0000000000000000
[ 168.070729][ T796] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 168.071772][ T796] CR2: 000000000805b740 CR3: 000000014b9ef000 CR4: 00000000000406f0
[ 168.073736][ T796] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 168.075050][ T796] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 168.076319][ T796] Call Trace:
[ 168.076954][ T796] <TASK>
[ 168.077552][ T796] kthread+0x4b7/0x5e0
[ 168.079269][ T796] ? rcu_torture_updown_hrt+0x60/0x60 [rcutorture e5c5209c38907516252542c1d07dd3e619a57f4e]
[ 168.080832][ T796] ? kthread_unuse_mm+0x150/0x150
[ 168.081731][ T796] ret_from_fork+0x3c/0x70
[ 168.082491][ T796] ? kthread_unuse_mm+0x150/0x150
[ 168.083328][ T796] ret_from_fork_asm+0x11/0x20
[ 168.084182][ T796] </TASK>
[ 168.084826][ T796] irq event stamp: 90885
[ 168.085562][ T796] hardirqs last enabled at (90895): [<ffffffff815a4e82>] __console_unlock+0x72/0x80
[ 168.086968][ T796] hardirqs last disabled at (90904): [<ffffffff815a4e67>] __console_unlock+0x57/0x80
[ 168.088472][ T796] softirqs last enabled at (90738): [<ffffffff8148ecce>] handle_softirqs+0x5de/0x6e0
[ 168.089989][ T796] softirqs last disabled at (90729): [<ffffffff8148ef41>] __irq_exit_rcu+0x61/0xc0
[ 168.091310][ T796] ---[ end trace 0000000000000000 ]---
>
> Thanx, Paul
>
> [ . . . ]
>
> > > diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> > > index 3dd213bfc6662..53f0860b3748d 100644
> > > --- a/kernel/rcu/rcutorture.c
> > > +++ b/kernel/rcu/rcutorture.c
> > > @@ -2557,6 +2557,7 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> > > static int
> > > rcu_torture_updown(void *arg)
> > > {
> > > + unsigned long j;
> > > struct rcu_torture_one_read_state_updown *rtorsup;
> > >
> > > VERBOSE_TOROUT_STRING("rcu_torture_updown task started");
> > > @@ -2564,8 +2565,9 @@ rcu_torture_updown(void *arg)
> > > for (rtorsup = updownreaders; rtorsup < &updownreaders[n_up_down]; rtorsup++) {
> > > if (torture_must_stop())
> > > break;
> > > + j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
> > > if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
> > > - WARN_ON_ONCE(time_after(jiffies, rtorsup->rtorsu_j + 10 * HZ));
> > > + WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
> > > continue;
> > > }
> > > rcu_torture_updown_one(rtorsup);
>
>
> diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> index abe48ff48f54c..7268e33086eb4 100644
> --- a/kernel/rcu/rcutorture.c
> +++ b/kernel/rcu/rcutorture.c
> @@ -2449,6 +2449,7 @@ struct rcu_torture_one_read_state_updown {
> struct hrtimer rtorsu_hrt;
> bool rtorsu_inuse;
> int rtorsu_cpu;
> + ktime_t rtorsu_kt;
> unsigned long rtorsu_j;
> unsigned long rtorsu_ndowns;
> unsigned long rtorsu_nups;
> @@ -2548,12 +2549,14 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> schedule_timeout_idle(HZ);
> return;
> }
> - rtorsup->rtorsu_j = jiffies;
> smp_store_release(&rtorsup->rtorsu_inuse, true);
> t = torture_random(&rtorsup->rtorsu_trs) & 0xfffff; // One per million.
> if (t < 10 * 1000)
> t = 200 * 1000 * 1000;
> hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
> + smp_mb(); // Sample jiffies after posting hrtimer.
> + rtorsup->rtorsu_j = jiffies; // Not used by hrtimer handler.
> + rtorsup->rtorsu_kt = t;
> }
>
> /*
> @@ -2574,7 +2577,8 @@ rcu_torture_updown(void *arg)
> break;
> j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
> if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
> - WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
> + WARN_ONCE(time_after(j, rtorsup->rtorsu_j + 1 + HZ * 10),
> + "hrtimer queued at jiffies %lu for %lld ns took %lu jiffies\n", rtorsup->rtorsu_j, rtorsup->rtorsu_kt, j - rtorsup->rtorsu_j);
> continue;
> }
> rcu_torture_updown_one(rtorsup);
[-- Attachment #2: dmesg.xz --]
[-- Type: application/x-xz, Size: 32448 bytes --]
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]
2025-04-24 1:50 ` Oliver Sang
@ 2025-04-24 3:05 ` Paul E. McKenney
2025-04-24 22:56 ` Paul E. McKenney
0 siblings, 1 reply; 9+ messages in thread
From: Paul E. McKenney @ 2025-04-24 3:05 UTC (permalink / raw)
To: Oliver Sang; +Cc: oe-lkp, lkp, Joel Fernandes, linux-kernel
On Thu, Apr 24, 2025 at 09:50:04AM +0800, Oliver Sang wrote:
> hi, Paul,
>
> On Tue, Apr 22, 2025 at 10:54:10AM -0700, Paul E. McKenney wrote:
>
> [...]
>
> > > > >
> > > > > 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@intel.com>
> > > > > | Closes: https://lore.kernel.org/oe-lkp/202504211513.23f21a0-lkp@intel.com
> > > > >
> > > > >
> > > > > The kernel config and materials to reproduce are available at:
> > > > > https://download.01.org/0day-ci/archive/20250421/202504211513.23f21a0-lkp@intel.com
> > > >
> > > > Good catch, and thank you for your testing efforts!
> > > >
> > > > Does the patch at the end of this email help?
> > >
> > > sorry but the patch does not help. one dmesg is attached.
> >
> > And idiot here failed to check for the exact same problem at the point
> > where the timer is queued, so thank you for bearing with me.
> >
> > Does the patch at the end of this email (in addition to the previous
> > patch) get the job done?
>
> unfortunately, it still doesn't fix, one dmesg is attached. part of is as [2]
>
> but I applied your two patches directly upon ddd062f753, like below:
>
> * 1c91d0bd4809f (linux-devel/fixup-1539a7e7b61a9) further patch for ddd062f753 from Paul
> * 1539a7e7b61a9 (linux-devel/fixup-ddd062f753) fix for ddd062f753 from Paul E. McKenney
> * ddd062f7536cc rcutorture: Complain if an ->up_read() is delayed more than 10 seconds
> * 1b983c34d5695 rcutorture: Comment invocations of tick_dep_set_task()
>
>
> I noticed there are some conflicts while applying your second patch, the
> 1c91d0bd4809f looks like [1]. there is no "int rtorsu_cpu;" before line:
> + ktime_t rtorsu_kt;
>
> seems your patch has a different base? I worried if my applyment has
> problems. if so, could you tell me the correct base? thanks!
It looks correct to me. I will rebase at my end to make it apply cleanly
by the end of my tomorrow at the latest. Attempting it now would likely
just make a mess. :-/
And thank you very much for your help with this because...
> [1]
> commit 1c91d0bd4809f9f12e61f25d881a02f25c473702 (linux-devel/fixup-1539a7e7b61a9)
> Author: 0day robot <lkp@intel.com>
> Date: Wed Apr 23 10:27:51 2025 +0800
>
> further patch for ddd062f753 from Paul
>
> Signed-off-by: 0day robot <lkp@intel.com>
>
> diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> index e7b5811e0e456..14cc67d436c97 100644
> --- a/kernel/rcu/rcutorture.c
> +++ b/kernel/rcu/rcutorture.c
> @@ -2438,6 +2438,7 @@ rcu_torture_reader(void *arg)
> struct rcu_torture_one_read_state_updown {
> struct hrtimer rtorsu_hrt;
> bool rtorsu_inuse;
> + ktime_t rtorsu_kt;
> unsigned long rtorsu_j;
> struct torture_random_state rtorsu_trs;
> struct rcu_torture_one_read_state rtorsu_rtors;
> @@ -2522,12 +2523,14 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> schedule_timeout_idle(HZ);
> return;
> }
> - rtorsup->rtorsu_j = jiffies;
> smp_store_release(&rtorsup->rtorsu_inuse, true);
> t = torture_random(&rtorsup->rtorsu_trs) & 0xfffff; // One per million.
> if (t < 10 * 1000)
> t = 200 * 1000 * 1000;
> hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
> + smp_mb(); // Sample jiffies after posting hrtimer.
> + rtorsup->rtorsu_j = jiffies; // Not used by hrtimer handler.
> + rtorsup->rtorsu_kt = t;
> }
>
> /*
> @@ -2548,7 +2551,9 @@ rcu_torture_updown(void *arg)
> break;
> j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
> if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
> - WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
> + WARN_ONCE(time_after(j, rtorsup->rtorsu_j + 1 + HZ * 10),
> + "hrtimer queued at jiffies %lu for %lld ns took %lu jiffies\n", rtorsup->rtorsu_j, rtorsup->rtorsu_kt, j - rtorsup->rtorsu_j);
> continue;
> }
> rcu_torture_updown_one(rtorsup);
>
>
>
> [2]
>
> [ 168.048387][ T796] ------------[ cut here ]------------
> [ 168.049342][ T796] hrtimer queued at jiffies 4294952214 for 200000000 ns took 1502 jiffies
... I am quite surprised by the 1502 jiffies. On a HZ=1000 system,
I would have expected this value to be at least 10,000. I clearly need
to dig into this code much more carefully.
So thank you again for your testing efforts!
Thanx, Paul
> [ 168.050699][ T796] WARNING: CPU: 0 PID: 796 at kernel/rcu/rcutorture.c:2555 rcu_torture_updown+0x143/0x4f0 [rcutorture]
> [ 168.052702][ T796] Modules linked in: rcutorture torture
> [ 168.054084][ T796] CPU: 0 UID: 0 PID: 796 Comm: rcu_torture_upd Not tainted 6.15.0-rc1-00010-g1c91d0bd4809 #1 NONE e0cf54ed16af150d49bfa95e1fe661f9e9161d42
> [ 168.056119][ T796] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
> [ 168.058045][ T796] RIP: 0010:rcu_torture_updown+0x143/0x4f0 [rcutorture]
> [ 168.059229][ T796] Code: 48 c1 e8 03 42 80 3c 38 00 74 05 e8 a7 1b 49 e1 49 8b 54 2d 48 49 29 de 48 c7 c7 c0 9e 5e a0 48 89 de 4c 89 f1 e8 dd 6a c4 e0 <0f> 0b e9 d2 01 00 00 4c 89 24 24 4c 8d 34 2d 68 00 00 00 4d 01 ee
> [ 168.061887][ T796] RSP: 0000:ffff888152bf7e60 EFLAGS: 00210246
> [ 168.062804][ T796] RAX: 0000000000000000 RBX: 00000000ffffc516 RCX: 0000000000000000
> [ 168.064097][ T796] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
> [ 168.065436][ T796] RBP: 0000000000002a00 R08: 0000000000000000 R09: 0000000000000000
> [ 168.066674][ T796] R10: 0000000000000000 R11: 0000000000000000 R12: ffff888150812a40
> [ 168.067932][ T796] R13: ffff888150810000 R14: 00000000000005de R15: dffffc0000000000
> [ 168.069302][ T796] FS: 0000000000000000(0000) GS:ffff888424c90000(0000) knlGS:0000000000000000
> [ 168.070729][ T796] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 168.071772][ T796] CR2: 000000000805b740 CR3: 000000014b9ef000 CR4: 00000000000406f0
> [ 168.073736][ T796] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 168.075050][ T796] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 168.076319][ T796] Call Trace:
> [ 168.076954][ T796] <TASK>
> [ 168.077552][ T796] kthread+0x4b7/0x5e0
> [ 168.079269][ T796] ? rcu_torture_updown_hrt+0x60/0x60 [rcutorture e5c5209c38907516252542c1d07dd3e619a57f4e]
> [ 168.080832][ T796] ? kthread_unuse_mm+0x150/0x150
> [ 168.081731][ T796] ret_from_fork+0x3c/0x70
> [ 168.082491][ T796] ? kthread_unuse_mm+0x150/0x150
> [ 168.083328][ T796] ret_from_fork_asm+0x11/0x20
> [ 168.084182][ T796] </TASK>
> [ 168.084826][ T796] irq event stamp: 90885
> [ 168.085562][ T796] hardirqs last enabled at (90895): [<ffffffff815a4e82>] __console_unlock+0x72/0x80
> [ 168.086968][ T796] hardirqs last disabled at (90904): [<ffffffff815a4e67>] __console_unlock+0x57/0x80
> [ 168.088472][ T796] softirqs last enabled at (90738): [<ffffffff8148ecce>] handle_softirqs+0x5de/0x6e0
> [ 168.089989][ T796] softirqs last disabled at (90729): [<ffffffff8148ef41>] __irq_exit_rcu+0x61/0xc0
> [ 168.091310][ T796] ---[ end trace 0000000000000000 ]---
>
> >
> > Thanx, Paul
> >
> > [ . . . ]
> >
> > > > diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> > > > index 3dd213bfc6662..53f0860b3748d 100644
> > > > --- a/kernel/rcu/rcutorture.c
> > > > +++ b/kernel/rcu/rcutorture.c
> > > > @@ -2557,6 +2557,7 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> > > > static int
> > > > rcu_torture_updown(void *arg)
> > > > {
> > > > + unsigned long j;
> > > > struct rcu_torture_one_read_state_updown *rtorsup;
> > > >
> > > > VERBOSE_TOROUT_STRING("rcu_torture_updown task started");
> > > > @@ -2564,8 +2565,9 @@ rcu_torture_updown(void *arg)
> > > > for (rtorsup = updownreaders; rtorsup < &updownreaders[n_up_down]; rtorsup++) {
> > > > if (torture_must_stop())
> > > > break;
> > > > + j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
> > > > if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
> > > > - WARN_ON_ONCE(time_after(jiffies, rtorsup->rtorsu_j + 10 * HZ));
> > > > + WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
> > > > continue;
> > > > }
> > > > rcu_torture_updown_one(rtorsup);
> >
> >
> > diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> > index abe48ff48f54c..7268e33086eb4 100644
> > --- a/kernel/rcu/rcutorture.c
> > +++ b/kernel/rcu/rcutorture.c
> > @@ -2449,6 +2449,7 @@ struct rcu_torture_one_read_state_updown {
> > struct hrtimer rtorsu_hrt;
> > bool rtorsu_inuse;
> > int rtorsu_cpu;
> > + ktime_t rtorsu_kt;
> > unsigned long rtorsu_j;
> > unsigned long rtorsu_ndowns;
> > unsigned long rtorsu_nups;
> > @@ -2548,12 +2549,14 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> > schedule_timeout_idle(HZ);
> > return;
> > }
> > - rtorsup->rtorsu_j = jiffies;
> > smp_store_release(&rtorsup->rtorsu_inuse, true);
> > t = torture_random(&rtorsup->rtorsu_trs) & 0xfffff; // One per million.
> > if (t < 10 * 1000)
> > t = 200 * 1000 * 1000;
> > hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
> > + smp_mb(); // Sample jiffies after posting hrtimer.
> > + rtorsup->rtorsu_j = jiffies; // Not used by hrtimer handler.
> > + rtorsup->rtorsu_kt = t;
> > }
> >
> > /*
> > @@ -2574,7 +2577,8 @@ rcu_torture_updown(void *arg)
> > break;
> > j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
> > if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
> > - WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
> > + WARN_ONCE(time_after(j, rtorsup->rtorsu_j + 1 + HZ * 10),
> > + "hrtimer queued at jiffies %lu for %lld ns took %lu jiffies\n", rtorsup->rtorsu_j, rtorsup->rtorsu_kt, j - rtorsup->rtorsu_j);
> > continue;
> > }
> > rcu_torture_updown_one(rtorsup);
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]
2025-04-24 3:05 ` Paul E. McKenney
@ 2025-04-24 22:56 ` Paul E. McKenney
2025-04-27 5:31 ` Oliver Sang
0 siblings, 1 reply; 9+ messages in thread
From: Paul E. McKenney @ 2025-04-24 22:56 UTC (permalink / raw)
To: Oliver Sang; +Cc: oe-lkp, lkp, Joel Fernandes, linux-kernel
On Wed, Apr 23, 2025 at 08:05:53PM -0700, Paul E. McKenney wrote:
> On Thu, Apr 24, 2025 at 09:50:04AM +0800, Oliver Sang wrote:
> > hi, Paul,
> >
> > On Tue, Apr 22, 2025 at 10:54:10AM -0700, Paul E. McKenney wrote:
> >
> > [...]
> >
> > > > > >
> > > > > > 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@intel.com>
> > > > > > | Closes: https://lore.kernel.org/oe-lkp/202504211513.23f21a0-lkp@intel.com
> > > > > >
> > > > > >
> > > > > > The kernel config and materials to reproduce are available at:
> > > > > > https://download.01.org/0day-ci/archive/20250421/202504211513.23f21a0-lkp@intel.com
> > > > >
> > > > > Good catch, and thank you for your testing efforts!
> > > > >
> > > > > Does the patch at the end of this email help?
> > > >
> > > > sorry but the patch does not help. one dmesg is attached.
> > >
> > > And idiot here failed to check for the exact same problem at the point
> > > where the timer is queued, so thank you for bearing with me.
> > >
> > > Does the patch at the end of this email (in addition to the previous
> > > patch) get the job done?
> >
> > unfortunately, it still doesn't fix, one dmesg is attached. part of is as [2]
> >
> > but I applied your two patches directly upon ddd062f753, like below:
> >
> > * 1c91d0bd4809f (linux-devel/fixup-1539a7e7b61a9) further patch for ddd062f753 from Paul
> > * 1539a7e7b61a9 (linux-devel/fixup-ddd062f753) fix for ddd062f753 from Paul E. McKenney
> > * ddd062f7536cc rcutorture: Complain if an ->up_read() is delayed more than 10 seconds
> > * 1b983c34d5695 rcutorture: Comment invocations of tick_dep_set_task()
> >
> >
> > I noticed there are some conflicts while applying your second patch, the
> > 1c91d0bd4809f looks like [1]. there is no "int rtorsu_cpu;" before line:
> > + ktime_t rtorsu_kt;
> >
> > seems your patch has a different base? I worried if my applyment has
> > problems. if so, could you tell me the correct base? thanks!
>
> It looks correct to me. I will rebase at my end to make it apply cleanly
> by the end of my tomorrow at the latest. Attempting it now would likely
> just make a mess. :-/
>
> And thank you very much for your help with this because...
>
> > [1]
> > commit 1c91d0bd4809f9f12e61f25d881a02f25c473702 (linux-devel/fixup-1539a7e7b61a9)
> > Author: 0day robot <lkp@intel.com>
> > Date: Wed Apr 23 10:27:51 2025 +0800
> >
> > further patch for ddd062f753 from Paul
> >
> > Signed-off-by: 0day robot <lkp@intel.com>
> >
> > diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> > index e7b5811e0e456..14cc67d436c97 100644
> > --- a/kernel/rcu/rcutorture.c
> > +++ b/kernel/rcu/rcutorture.c
> > @@ -2438,6 +2438,7 @@ rcu_torture_reader(void *arg)
> > struct rcu_torture_one_read_state_updown {
> > struct hrtimer rtorsu_hrt;
> > bool rtorsu_inuse;
> > + ktime_t rtorsu_kt;
> > unsigned long rtorsu_j;
> > struct torture_random_state rtorsu_trs;
> > struct rcu_torture_one_read_state rtorsu_rtors;
> > @@ -2522,12 +2523,14 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> > schedule_timeout_idle(HZ);
> > return;
> > }
> > - rtorsup->rtorsu_j = jiffies;
> > smp_store_release(&rtorsup->rtorsu_inuse, true);
> > t = torture_random(&rtorsup->rtorsu_trs) & 0xfffff; // One per million.
> > if (t < 10 * 1000)
> > t = 200 * 1000 * 1000;
> > hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
> > + smp_mb(); // Sample jiffies after posting hrtimer.
> > + rtorsup->rtorsu_j = jiffies; // Not used by hrtimer handler.
> > + rtorsup->rtorsu_kt = t;
> > }
> >
> > /*
> > @@ -2548,7 +2551,9 @@ rcu_torture_updown(void *arg)
> > break;
> > j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
> > if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
> > - WARN_ON_ONCE(time_after(j, rtorsup->rtorsu_j + 10 * HZ));
> > + WARN_ONCE(time_after(j, rtorsup->rtorsu_j + 1 + HZ * 10),
> > + "hrtimer queued at jiffies %lu for %lld ns took %lu jiffies\n", rtorsup->rtorsu_j, rtorsup->rtorsu_kt, j - rtorsup->rtorsu_j);
> > continue;
> > }
> > rcu_torture_updown_one(rtorsup);
> >
> >
> >
> > [2]
> >
> > [ 168.048387][ T796] ------------[ cut here ]------------
> > [ 168.049342][ T796] hrtimer queued at jiffies 4294952214 for 200000000 ns took 1502 jiffies
>
> ... I am quite surprised by the 1502 jiffies. On a HZ=1000 system,
> I would have expected this value to be at least 10,000. I clearly need
> to dig into this code much more carefully.
And upon looking at the dmesg.xz that you attached, I see that HZ=100.
So there really is a 15-second delay, which is intended to trip this
10-second timeout.
So I guess is it no more Mr. Nice Guy for hrtimers, and therefore
HRTIMER_MODE_HARD it is! ;-)
Once again, thank you for your testing efforts!
I also rebased my fixup patches to the bottom of my development stack,
so the combined patch shown below should apply cleanly. Here is hoping
that the third time is a charm. ;-)
Thanx, Paul
------------------------------------------------------------------------
diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index 88d9f5298c3d8..1ebeef8019b86 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -2445,6 +2445,7 @@ rcu_torture_reader(void *arg)
struct rcu_torture_one_read_state_updown {
struct hrtimer rtorsu_hrt;
bool rtorsu_inuse;
+ ktime_t rtorsu_kt;
unsigned long rtorsu_j;
unsigned long rtorsu_ndowns;
unsigned long rtorsu_nups;
@@ -2488,7 +2489,7 @@ static int rcu_torture_updown_init(void)
for (i = 0; i < n_up_down; i++) {
init_rcu_torture_one_read_state(&updownreaders[i].rtorsu_rtors, rand);
hrtimer_setup(&updownreaders[i].rtorsu_hrt, rcu_torture_updown_hrt, CLOCK_MONOTONIC,
- HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
+ HRTIMER_MODE_REL | HRTIMER_MODE_HARD);
torture_random_init(&updownreaders[i].rtorsu_trs);
init_rcu_torture_one_read_state(&updownreaders[i].rtorsu_rtors,
&updownreaders[i].rtorsu_trs);
@@ -2539,12 +2540,14 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
schedule_timeout_idle(HZ);
return;
}
- rtorsup->rtorsu_j = jiffies;
smp_store_release(&rtorsup->rtorsu_inuse, true);
t = torture_random(&rtorsup->rtorsu_trs) & 0xfffff; // One per million.
if (t < 10 * 1000)
t = 200 * 1000 * 1000;
- hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
+ hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_HARD);
+ smp_mb(); // Sample jiffies after posting hrtimer.
+ rtorsup->rtorsu_j = jiffies; // Not used by hrtimer handler.
+ rtorsup->rtorsu_kt = t;
}
/*
@@ -2555,6 +2558,7 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
static int
rcu_torture_updown(void *arg)
{
+ unsigned long j;
struct rcu_torture_one_read_state_updown *rtorsup;
VERBOSE_TOROUT_STRING("rcu_torture_updown task started");
@@ -2562,8 +2566,10 @@ rcu_torture_updown(void *arg)
for (rtorsup = updownreaders; rtorsup < &updownreaders[n_up_down]; rtorsup++) {
if (torture_must_stop())
break;
+ j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
- WARN_ON_ONCE(time_after(jiffies, rtorsup->rtorsu_j + 10 * HZ));
+ WARN_ONCE(time_after(j, rtorsup->rtorsu_j + 1 + HZ * 10),
+ "hrtimer queued at jiffies %lu for %lld ns took %lu jiffies\n", rtorsup->rtorsu_j, rtorsup->rtorsu_kt, j - rtorsup->rtorsu_j);
continue;
}
rcu_torture_updown_one(rtorsup);
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]
2025-04-24 22:56 ` Paul E. McKenney
@ 2025-04-27 5:31 ` Oliver Sang
2025-04-27 15:51 ` Paul E. McKenney
0 siblings, 1 reply; 9+ messages in thread
From: Oliver Sang @ 2025-04-27 5:31 UTC (permalink / raw)
To: Paul E. McKenney; +Cc: oe-lkp, lkp, Joel Fernandes, linux-kernel, oliver.sang
hi, Paul,
On Thu, Apr 24, 2025 at 03:56:09PM -0700, Paul E. McKenney wrote:
> On Wed, Apr 23, 2025 at 08:05:53PM -0700, Paul E. McKenney wrote:
> > On Thu, Apr 24, 2025 at 09:50:04AM +0800, Oliver Sang wrote:
> > > hi, Paul,
> > >
> > > On Tue, Apr 22, 2025 at 10:54:10AM -0700, Paul E. McKenney wrote:
> > >
> > > [...]
> > >
> > > > > > >
> > > > > > > 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@intel.com>
> > > > > > > | Closes: https://lore.kernel.org/oe-lkp/202504211513.23f21a0-lkp@intel.com
> > > > > > >
> > > > > > >
> > > > > > > The kernel config and materials to reproduce are available at:
> > > > > > > https://download.01.org/0day-ci/archive/20250421/202504211513.23f21a0-lkp@intel.com
> > > > > >
> > > > > > Good catch, and thank you for your testing efforts!
> > > > > >
> > > > > > Does the patch at the end of this email help?
> > > > >
> > > > > sorry but the patch does not help. one dmesg is attached.
> > > >
> > > > And idiot here failed to check for the exact same problem at the point
> > > > where the timer is queued, so thank you for bearing with me.
> > > >
> > > > Does the patch at the end of this email (in addition to the previous
> > > > patch) get the job done?
> > >
> > > unfortunately, it still doesn't fix, one dmesg is attached. part of is as [2]
> > >
> > > but I applied your two patches directly upon ddd062f753, like below:
> > >
> > > * 1c91d0bd4809f (linux-devel/fixup-1539a7e7b61a9) further patch for ddd062f753 from Paul
> > > * 1539a7e7b61a9 (linux-devel/fixup-ddd062f753) fix for ddd062f753 from Paul E. McKenney
> > > * ddd062f7536cc rcutorture: Complain if an ->up_read() is delayed more than 10 seconds
> > > * 1b983c34d5695 rcutorture: Comment invocations of tick_dep_set_task()
> > >
> > >
> > > I noticed there are some conflicts while applying your second patch, the
> > > 1c91d0bd4809f looks like [1]. there is no "int rtorsu_cpu;" before line:
> > > + ktime_t rtorsu_kt;
> > >
> > > seems your patch has a different base? I worried if my applyment has
> > > problems. if so, could you tell me the correct base? thanks!
> >
> > It looks correct to me. I will rebase at my end to make it apply cleanly
> > by the end of my tomorrow at the latest. Attempting it now would likely
> > just make a mess. :-/
> >
> > And thank you very much for your help with this because...
> >
[...]
> > >
> > > [ 168.048387][ T796] ------------[ cut here ]------------
> > > [ 168.049342][ T796] hrtimer queued at jiffies 4294952214 for 200000000 ns took 1502 jiffies
> >
> > ... I am quite surprised by the 1502 jiffies. On a HZ=1000 system,
> > I would have expected this value to be at least 10,000. I clearly need
> > to dig into this code much more carefully.
>
> And upon looking at the dmesg.xz that you attached, I see that HZ=100.
> So there really is a 15-second delay, which is intended to trip this
> 10-second timeout.
>
> So I guess is it no more Mr. Nice Guy for hrtimers, and therefore
> HRTIMER_MODE_HARD it is! ;-)
>
> Once again, thank you for your testing efforts!
you are welcome!
>
> I also rebased my fixup patches to the bottom of my development stack,
> so the combined patch shown below should apply cleanly. Here is hoping
> that the third time is a charm. ;-)
we confirm it fixes the WARNING we reported. thanks!
Tested-by: kernel test robot <oliver.sang@intel.com>
>
> Thanx, Paul
>
> ------------------------------------------------------------------------
>
> diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> index 88d9f5298c3d8..1ebeef8019b86 100644
> --- a/kernel/rcu/rcutorture.c
> +++ b/kernel/rcu/rcutorture.c
> @@ -2445,6 +2445,7 @@ rcu_torture_reader(void *arg)
> struct rcu_torture_one_read_state_updown {
> struct hrtimer rtorsu_hrt;
> bool rtorsu_inuse;
> + ktime_t rtorsu_kt;
> unsigned long rtorsu_j;
> unsigned long rtorsu_ndowns;
> unsigned long rtorsu_nups;
> @@ -2488,7 +2489,7 @@ static int rcu_torture_updown_init(void)
> for (i = 0; i < n_up_down; i++) {
> init_rcu_torture_one_read_state(&updownreaders[i].rtorsu_rtors, rand);
> hrtimer_setup(&updownreaders[i].rtorsu_hrt, rcu_torture_updown_hrt, CLOCK_MONOTONIC,
> - HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
> + HRTIMER_MODE_REL | HRTIMER_MODE_HARD);
> torture_random_init(&updownreaders[i].rtorsu_trs);
> init_rcu_torture_one_read_state(&updownreaders[i].rtorsu_rtors,
> &updownreaders[i].rtorsu_trs);
> @@ -2539,12 +2540,14 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> schedule_timeout_idle(HZ);
> return;
> }
> - rtorsup->rtorsu_j = jiffies;
> smp_store_release(&rtorsup->rtorsu_inuse, true);
> t = torture_random(&rtorsup->rtorsu_trs) & 0xfffff; // One per million.
> if (t < 10 * 1000)
> t = 200 * 1000 * 1000;
> - hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
> + hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_HARD);
> + smp_mb(); // Sample jiffies after posting hrtimer.
> + rtorsup->rtorsu_j = jiffies; // Not used by hrtimer handler.
> + rtorsup->rtorsu_kt = t;
> }
>
> /*
> @@ -2555,6 +2558,7 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> static int
> rcu_torture_updown(void *arg)
> {
> + unsigned long j;
> struct rcu_torture_one_read_state_updown *rtorsup;
>
> VERBOSE_TOROUT_STRING("rcu_torture_updown task started");
> @@ -2562,8 +2566,10 @@ rcu_torture_updown(void *arg)
> for (rtorsup = updownreaders; rtorsup < &updownreaders[n_up_down]; rtorsup++) {
> if (torture_must_stop())
> break;
> + j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
> if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
> - WARN_ON_ONCE(time_after(jiffies, rtorsup->rtorsu_j + 10 * HZ));
> + WARN_ONCE(time_after(j, rtorsup->rtorsu_j + 1 + HZ * 10),
> + "hrtimer queued at jiffies %lu for %lld ns took %lu jiffies\n", rtorsup->rtorsu_j, rtorsup->rtorsu_kt, j - rtorsup->rtorsu_j);
> continue;
> }
> rcu_torture_updown_one(rtorsup);
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture]
2025-04-27 5:31 ` Oliver Sang
@ 2025-04-27 15:51 ` Paul E. McKenney
0 siblings, 0 replies; 9+ messages in thread
From: Paul E. McKenney @ 2025-04-27 15:51 UTC (permalink / raw)
To: Oliver Sang; +Cc: oe-lkp, lkp, Joel Fernandes, linux-kernel
On Sun, Apr 27, 2025 at 01:31:11PM +0800, Oliver Sang wrote:
> hi, Paul,
>
> On Thu, Apr 24, 2025 at 03:56:09PM -0700, Paul E. McKenney wrote:
> > On Wed, Apr 23, 2025 at 08:05:53PM -0700, Paul E. McKenney wrote:
> > > On Thu, Apr 24, 2025 at 09:50:04AM +0800, Oliver Sang wrote:
> > > > hi, Paul,
> > > >
> > > > On Tue, Apr 22, 2025 at 10:54:10AM -0700, Paul E. McKenney wrote:
> > > >
> > > > [...]
> > > >
> > > > > > > >
> > > > > > > > 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@intel.com>
> > > > > > > > | Closes: https://lore.kernel.org/oe-lkp/202504211513.23f21a0-lkp@intel.com
> > > > > > > >
> > > > > > > >
> > > > > > > > The kernel config and materials to reproduce are available at:
> > > > > > > > https://download.01.org/0day-ci/archive/20250421/202504211513.23f21a0-lkp@intel.com
> > > > > > >
> > > > > > > Good catch, and thank you for your testing efforts!
> > > > > > >
> > > > > > > Does the patch at the end of this email help?
> > > > > >
> > > > > > sorry but the patch does not help. one dmesg is attached.
> > > > >
> > > > > And idiot here failed to check for the exact same problem at the point
> > > > > where the timer is queued, so thank you for bearing with me.
> > > > >
> > > > > Does the patch at the end of this email (in addition to the previous
> > > > > patch) get the job done?
> > > >
> > > > unfortunately, it still doesn't fix, one dmesg is attached. part of is as [2]
> > > >
> > > > but I applied your two patches directly upon ddd062f753, like below:
> > > >
> > > > * 1c91d0bd4809f (linux-devel/fixup-1539a7e7b61a9) further patch for ddd062f753 from Paul
> > > > * 1539a7e7b61a9 (linux-devel/fixup-ddd062f753) fix for ddd062f753 from Paul E. McKenney
> > > > * ddd062f7536cc rcutorture: Complain if an ->up_read() is delayed more than 10 seconds
> > > > * 1b983c34d5695 rcutorture: Comment invocations of tick_dep_set_task()
> > > >
> > > >
> > > > I noticed there are some conflicts while applying your second patch, the
> > > > 1c91d0bd4809f looks like [1]. there is no "int rtorsu_cpu;" before line:
> > > > + ktime_t rtorsu_kt;
> > > >
> > > > seems your patch has a different base? I worried if my applyment has
> > > > problems. if so, could you tell me the correct base? thanks!
> > >
> > > It looks correct to me. I will rebase at my end to make it apply cleanly
> > > by the end of my tomorrow at the latest. Attempting it now would likely
> > > just make a mess. :-/
> > >
> > > And thank you very much for your help with this because...
> > >
>
> [...]
>
> > > >
> > > > [ 168.048387][ T796] ------------[ cut here ]------------
> > > > [ 168.049342][ T796] hrtimer queued at jiffies 4294952214 for 200000000 ns took 1502 jiffies
> > >
> > > ... I am quite surprised by the 1502 jiffies. On a HZ=1000 system,
> > > I would have expected this value to be at least 10,000. I clearly need
> > > to dig into this code much more carefully.
> >
> > And upon looking at the dmesg.xz that you attached, I see that HZ=100.
> > So there really is a 15-second delay, which is intended to trip this
> > 10-second timeout.
> >
> > So I guess is it no more Mr. Nice Guy for hrtimers, and therefore
> > HRTIMER_MODE_HARD it is! ;-)
> >
> > Once again, thank you for your testing efforts!
>
> you are welcome!
>
> > I also rebased my fixup patches to the bottom of my development stack,
> > so the combined patch shown below should apply cleanly. Here is hoping
> > that the third time is a charm. ;-)
>
> we confirm it fixes the WARNING we reported. thanks!
>
> Tested-by: kernel test robot <oliver.sang@intel.com>
Thank you for bearing with me on this one!
Thanx, Paul
> > ------------------------------------------------------------------------
> >
> > diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> > index 88d9f5298c3d8..1ebeef8019b86 100644
> > --- a/kernel/rcu/rcutorture.c
> > +++ b/kernel/rcu/rcutorture.c
> > @@ -2445,6 +2445,7 @@ rcu_torture_reader(void *arg)
> > struct rcu_torture_one_read_state_updown {
> > struct hrtimer rtorsu_hrt;
> > bool rtorsu_inuse;
> > + ktime_t rtorsu_kt;
> > unsigned long rtorsu_j;
> > unsigned long rtorsu_ndowns;
> > unsigned long rtorsu_nups;
> > @@ -2488,7 +2489,7 @@ static int rcu_torture_updown_init(void)
> > for (i = 0; i < n_up_down; i++) {
> > init_rcu_torture_one_read_state(&updownreaders[i].rtorsu_rtors, rand);
> > hrtimer_setup(&updownreaders[i].rtorsu_hrt, rcu_torture_updown_hrt, CLOCK_MONOTONIC,
> > - HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
> > + HRTIMER_MODE_REL | HRTIMER_MODE_HARD);
> > torture_random_init(&updownreaders[i].rtorsu_trs);
> > init_rcu_torture_one_read_state(&updownreaders[i].rtorsu_rtors,
> > &updownreaders[i].rtorsu_trs);
> > @@ -2539,12 +2540,14 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> > schedule_timeout_idle(HZ);
> > return;
> > }
> > - rtorsup->rtorsu_j = jiffies;
> > smp_store_release(&rtorsup->rtorsu_inuse, true);
> > t = torture_random(&rtorsup->rtorsu_trs) & 0xfffff; // One per million.
> > if (t < 10 * 1000)
> > t = 200 * 1000 * 1000;
> > - hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_SOFT);
> > + hrtimer_start(&rtorsup->rtorsu_hrt, t, HRTIMER_MODE_REL | HRTIMER_MODE_HARD);
> > + smp_mb(); // Sample jiffies after posting hrtimer.
> > + rtorsup->rtorsu_j = jiffies; // Not used by hrtimer handler.
> > + rtorsup->rtorsu_kt = t;
> > }
> >
> > /*
> > @@ -2555,6 +2558,7 @@ static void rcu_torture_updown_one(struct rcu_torture_one_read_state_updown *rto
> > static int
> > rcu_torture_updown(void *arg)
> > {
> > + unsigned long j;
> > struct rcu_torture_one_read_state_updown *rtorsup;
> >
> > VERBOSE_TOROUT_STRING("rcu_torture_updown task started");
> > @@ -2562,8 +2566,10 @@ rcu_torture_updown(void *arg)
> > for (rtorsup = updownreaders; rtorsup < &updownreaders[n_up_down]; rtorsup++) {
> > if (torture_must_stop())
> > break;
> > + j = smp_load_acquire(&jiffies); // Time before ->rtorsu_inuse.
> > if (smp_load_acquire(&rtorsup->rtorsu_inuse)) {
> > - WARN_ON_ONCE(time_after(jiffies, rtorsup->rtorsu_j + 10 * HZ));
> > + WARN_ONCE(time_after(j, rtorsup->rtorsu_j + 1 + HZ * 10),
> > + "hrtimer queued at jiffies %lu for %lld ns took %lu jiffies\n", rtorsup->rtorsu_j, rtorsup->rtorsu_kt, j - rtorsup->rtorsu_j);
> > continue;
> > }
> > rcu_torture_updown_one(rtorsup);
^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2025-04-27 15:51 UTC | newest]
Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2025-04-21 7:39 [linux-next:master] [rcutorture] ddd062f753: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_updown[rcutorture] kernel test robot
2025-04-21 16:34 ` Paul E. McKenney
2025-04-22 5:01 ` Oliver Sang
2025-04-22 17:54 ` Paul E. McKenney
2025-04-24 1:50 ` Oliver Sang
2025-04-24 3:05 ` Paul E. McKenney
2025-04-24 22:56 ` Paul E. McKenney
2025-04-27 5:31 ` Oliver Sang
2025-04-27 15:51 ` Paul E. McKenney
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox
all inboxes | Powered by JetHome®