Commit 2585014188d5 ("rcu-tasks: Be more patient for RCU Tasks
boot-time testing") fixes false positive rcu_tasks verification check
failure by repeating the test once every second until timeout using
schedule_timeout_uninterruptible().
Since rcu_tasks_verify_selft_tests() is called from do_initcalls()
as a late_initcall, this has the undesirable side effect of perhaps
delaying other late_initcall's queued after it by a second or more.
Fix this by using delayed_work to repeat the verification check instead.
Fixes: 2585014188d5 ("rcu-tasks: Be more patient for RCU Tasks boot-time testing")
Signed-off-by: Waiman Long <[email protected]>
---
kernel/rcu/tasks.h | 35 ++++++++++++++++++++++++++++++++---
1 file changed, 32 insertions(+), 3 deletions(-)
diff --git a/kernel/rcu/tasks.h b/kernel/rcu/tasks.h
index fcbd0ec33c86..e151cd5ae2bc 100644
--- a/kernel/rcu/tasks.h
+++ b/kernel/rcu/tasks.h
@@ -1832,6 +1832,11 @@ static void rcu_tasks_initiate_self_tests(void)
#endif
}
+/*
+ * Return: 0 - test passed
+ * 1 - test failed, but have not timed out yet
+ * -1 - test failed and timed out
+ */
static int rcu_tasks_verify_self_tests(void)
{
int ret = 0;
@@ -1847,16 +1852,40 @@ static int rcu_tasks_verify_self_tests(void)
ret = -1;
break;
}
- schedule_timeout_uninterruptible(1);
+ ret = 1;
+ break;
}
}
- if (ret)
+ if (ret < 0)
WARN_ON(1);
return ret;
}
-late_initcall(rcu_tasks_verify_self_tests);
+
+/*
+ * Repeat the rcu_tasks_verify_self_tests() call once every second until the
+ * test passes or has timed out.
+ */
+static struct delayed_work rcu_tasks_verify_work;
+static void rcu_tasks_verify_work_fn(struct work_struct *work __maybe_unused)
+{
+ int ret = rcu_tasks_verify_self_tests();
+
+ if (ret <= 0)
+ return;
+
+ /* Test fails but not timed out yet, reschedule another check */
+ schedule_delayed_work(&rcu_tasks_verify_work, HZ);
+}
+
+static int rcu_tasks_verify_schedule_work(void)
+{
+ INIT_DELAYED_WORK(&rcu_tasks_verify_work, rcu_tasks_verify_work_fn);
+ rcu_tasks_verify_work_fn(NULL);
+ return 0;
+}
+late_initcall(rcu_tasks_verify_schedule_work);
#else /* #ifdef CONFIG_PROVE_RCU */
static void rcu_tasks_initiate_self_tests(void) { }
#endif /* #else #ifdef CONFIG_PROVE_RCU */
--
2.31.1
On Tue, Jun 14, 2022 at 08:06:20AM -0400, Waiman Long wrote:
> Commit 2585014188d5 ("rcu-tasks: Be more patient for RCU Tasks
> boot-time testing") fixes false positive rcu_tasks verification check
> failure by repeating the test once every second until timeout using
> schedule_timeout_uninterruptible().
>
> Since rcu_tasks_verify_selft_tests() is called from do_initcalls()
> as a late_initcall, this has the undesirable side effect of perhaps
> delaying other late_initcall's queued after it by a second or more.
> Fix this by using delayed_work to repeat the verification check instead.
>
> Fixes: 2585014188d5 ("rcu-tasks: Be more patient for RCU Tasks boot-time testing")
> Signed-off-by: Waiman Long <[email protected]>
Applied, thank you!
Thanx, Paul
> ---
> kernel/rcu/tasks.h | 35 ++++++++++++++++++++++++++++++++---
> 1 file changed, 32 insertions(+), 3 deletions(-)
>
> diff --git a/kernel/rcu/tasks.h b/kernel/rcu/tasks.h
> index fcbd0ec33c86..e151cd5ae2bc 100644
> --- a/kernel/rcu/tasks.h
> +++ b/kernel/rcu/tasks.h
> @@ -1832,6 +1832,11 @@ static void rcu_tasks_initiate_self_tests(void)
> #endif
> }
>
> +/*
> + * Return: 0 - test passed
> + * 1 - test failed, but have not timed out yet
> + * -1 - test failed and timed out
> + */
> static int rcu_tasks_verify_self_tests(void)
> {
> int ret = 0;
> @@ -1847,16 +1852,40 @@ static int rcu_tasks_verify_self_tests(void)
> ret = -1;
> break;
> }
> - schedule_timeout_uninterruptible(1);
> + ret = 1;
> + break;
> }
> }
>
> - if (ret)
> + if (ret < 0)
> WARN_ON(1);
>
> return ret;
> }
> -late_initcall(rcu_tasks_verify_self_tests);
> +
> +/*
> + * Repeat the rcu_tasks_verify_self_tests() call once every second until the
> + * test passes or has timed out.
> + */
> +static struct delayed_work rcu_tasks_verify_work;
> +static void rcu_tasks_verify_work_fn(struct work_struct *work __maybe_unused)
> +{
> + int ret = rcu_tasks_verify_self_tests();
> +
> + if (ret <= 0)
> + return;
> +
> + /* Test fails but not timed out yet, reschedule another check */
> + schedule_delayed_work(&rcu_tasks_verify_work, HZ);
> +}
> +
> +static int rcu_tasks_verify_schedule_work(void)
> +{
> + INIT_DELAYED_WORK(&rcu_tasks_verify_work, rcu_tasks_verify_work_fn);
> + rcu_tasks_verify_work_fn(NULL);
> + return 0;
> +}
> +late_initcall(rcu_tasks_verify_schedule_work);
> #else /* #ifdef CONFIG_PROVE_RCU */
> static void rcu_tasks_initiate_self_tests(void) { }
> #endif /* #else #ifdef CONFIG_PROVE_RCU */
> --
> 2.31.1
>
Greeting,
FYI, we noticed the following commit (built with gcc-11):
commit: b709abb270544e45bbf3135c03fcfa916899f054 ("[PATCH-rcu] rcu-tasks: Use delayed_work to delay rcu_tasks_verify_self_tests()")
url: https://github.com/intel-lab-lkp/linux/commits/Waiman-Long/rcu-tasks-Use-delayed_work-to-delay-rcu_tasks_verify_self_tests/20220614-200840
base: https://git.kernel.org/cgit/linux/kernel/git/paulmck/linux-rcu.git dev
patch link: https://lore.kernel.org/rcu/[email protected]
in testcase: boot
on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>
[ 64.538953][ T1] ------------[ cut here ]------------
[ 64.538955][ T1] WARNING: CPU: 0 PID: 1 at kernel/rcu/tasks.h:1861 rcu_tasks_verify_work_fn+0xa2/0x140
[ 82.542308][ T1] Modules linked in:
[ 82.542852][ T1] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc1-00114-gb709abb27054 #1 5174fcc90ab2355d70d76459e249e6beb14aec72
[ 82.546011][ T1] RIP: 0010:rcu_tasks_verify_work_fn+0xa2/0x140
[ 82.546872][ T1] Code: fe 01 75 29 48 8b 35 fd fe ea 02 5b b9 fa 00 00 00 48 c7 c2 c0 86 4c 85 5d bf 01 00 00 00 41 5c 41 5d 41 5e e9 1f 88 fa ff 90 <
0f> 0b 90 5b 5d 41 5c 41 5d 41 5e 31 c0 89 c2 89 c1 89 c6 89 c7 c3
[ 82.550826][ T1] RSP: 0000:ffffc90000017e60 EFLAGS: 00010246
[ 82.552888][ T1] RAX: 000000000000002c RBX: 0000000000000003 RCX: 0000000000000000
[ 82.553917][ T1] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[ 82.554984][ T1] RBP: ffffffff83c38f58 R08: 0000000000000000 R09: 0000000000000000
[ 82.557733][ T1] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000002
[ 82.558808][ T1] R13: 0000000000001d4c R14: 00000000ffffffff R15: ffffffff8491b888
[ 82.561186][ T1] FS: 0000000000000000(0000) GS:ffffffff8388e000(0000) knlGS:0000000000000000
[ 82.562420][ T1] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 82.564635][ T1] CR2: ffff88843ffff000 CR3: 0000000003876000 CR4: 00000000000406b0
[ 82.565735][ T1] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 82.566827][ T1] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 82.569160][ T1] Call Trace:
[ 82.569637][ T1] <TASK>
[ 82.570049][ T1] ? rcu_tasks_verify_work_fn+0x140/0x140
[ 82.570816][ T1] rcu_tasks_verify_schedule_work+0x95/0xc0
[ 82.572939][ T1] do_one_initcall+0x6b/0x2c0
[ 82.573524][ T1] do_initcalls+0x127/0x148
[ 82.574155][ T1] kernel_init_freeable+0xcf/0xff
[ 82.574846][ T1] ? rest_init+0xc0/0xc0
[ 82.576733][ T1] kernel_init+0x15/0x140
[ 82.577335][ T1] ret_from_fork+0x22/0x30
[ 82.577959][ T1] </TASK>
[ 82.578375][ T1] irq event stamp: 1475417
[ 82.578987][ T1] hardirqs last enabled at (1475425): [<ffffffff811161cd>] __up_console_sem+0x4d/0x80
[ 82.581613][ T1] hardirqs last disabled at (1475436): [<ffffffff811161b2>] __up_console_sem+0x32/0x80
[ 82.582980][ T1] softirqs last enabled at (1475268): [<ffffffff828002c0>] __do_softirq+0x2c0/0x434
[ 82.585549][ T1] softirqs last disabled at (1475259): [<ffffffff810b57a0>] irq_exit_rcu+0xa0/0x100
[ 82.586852][ T1] ---[ end trace 0000000000000000 ]---
To reproduce:
# build kernel
cd linux
cp config-5.19.0-rc1-00114-gb709abb27054 .config
make HOSTCC=gcc-11 CC=gcc-11 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage modules
make HOSTCC=gcc-11 CC=gcc-11 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://01.org/lkp
On 6/20/22 21:09, kernel test robot wrote:
>
> Greeting,
>
> FYI, we noticed the following commit (built with gcc-11):
>
> commit: b709abb270544e45bbf3135c03fcfa916899f054 ("[PATCH-rcu] rcu-tasks: Use delayed_work to delay rcu_tasks_verify_self_tests()")
> url: https://github.com/intel-lab-lkp/linux/commits/Waiman-Long/rcu-tasks-Use-delayed_work-to-delay-rcu_tasks_verify_self_tests/20220614-200840
> base: https://git.kernel.org/cgit/linux/kernel/git/paulmck/linux-rcu.git dev
> patch link: https://lore.kernel.org/rcu/[email protected]
>
> in testcase: boot
>
> on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
>
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>
>
>
> If you fix the issue, kindly add following tag
> Reported-by: kernel test robot <[email protected]>
>
>
> [ 64.538953][ T1] ------------[ cut here ]------------
> [ 64.538955][ T1] WARNING: CPU: 0 PID: 1 at kernel/rcu/tasks.h:1861 rcu_tasks_verify_work_fn+0xa2/0x140
> [ 82.542308][ T1] Modules linked in:
> [ 82.542852][ T1] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc1-00114-gb709abb27054 #1 5174fcc90ab2355d70d76459e249e6beb14aec72
> [ 82.546011][ T1] RIP: 0010:rcu_tasks_verify_work_fn+0xa2/0x140
I believe the WARN_ON(1) in rcu_tasks_verify_self_tests() got triggered
30s after the first rcu_tasks_verify_work_fn() is called via
late_initcall. The timestamp here transition from the WARNING line to
the next one is more than 18s. I think the VM may have preempted heavily
by the host causing significant delay or the cpu and memory resource
available is being overpowered by the debugging code enabled in a kernel
that include this RCU test. Also the WARNING timestamp of 64.538955 is
way more than the 30s timeout of the verification test. So I think the
warning is expected.
Cheers,
Longman
> [ 82.546872][ T1] Code: fe 01 75 29 48 8b 35 fd fe ea 02 5b b9 fa 00 00 00 48 c7 c2 c0 86 4c 85 5d bf 01 00 00 00 41 5c 41 5d 41 5e e9 1f 88 fa ff 90 <
> 0f> 0b 90 5b 5d 41 5c 41 5d 41 5e 31 c0 89 c2 89 c1 89 c6 89 c7 c3
> [ 82.550826][ T1] RSP: 0000:ffffc90000017e60 EFLAGS: 00010246
> [ 82.552888][ T1] RAX: 000000000000002c RBX: 0000000000000003 RCX: 0000000000000000
> [ 82.553917][ T1] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
> [ 82.554984][ T1] RBP: ffffffff83c38f58 R08: 0000000000000000 R09: 0000000000000000
> [ 82.557733][ T1] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000002
> [ 82.558808][ T1] R13: 0000000000001d4c R14: 00000000ffffffff R15: ffffffff8491b888
> [ 82.561186][ T1] FS: 0000000000000000(0000) GS:ffffffff8388e000(0000) knlGS:0000000000000000
> [ 82.562420][ T1] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 82.564635][ T1] CR2: ffff88843ffff000 CR3: 0000000003876000 CR4: 00000000000406b0
> [ 82.565735][ T1] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 82.566827][ T1] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 82.569160][ T1] Call Trace:
> [ 82.569637][ T1] <TASK>
> [ 82.570049][ T1] ? rcu_tasks_verify_work_fn+0x140/0x140
> [ 82.570816][ T1] rcu_tasks_verify_schedule_work+0x95/0xc0
> [ 82.572939][ T1] do_one_initcall+0x6b/0x2c0
> [ 82.573524][ T1] do_initcalls+0x127/0x148
> [ 82.574155][ T1] kernel_init_freeable+0xcf/0xff
> [ 82.574846][ T1] ? rest_init+0xc0/0xc0
> [ 82.576733][ T1] kernel_init+0x15/0x140
> [ 82.577335][ T1] ret_from_fork+0x22/0x30
> [ 82.577959][ T1] </TASK>
> [ 82.578375][ T1] irq event stamp: 1475417
> [ 82.578987][ T1] hardirqs last enabled at (1475425): [<ffffffff811161cd>] __up_console_sem+0x4d/0x80
> [ 82.581613][ T1] hardirqs last disabled at (1475436): [<ffffffff811161b2>] __up_console_sem+0x32/0x80
> [ 82.582980][ T1] softirqs last enabled at (1475268): [<ffffffff828002c0>] __do_softirq+0x2c0/0x434
> [ 82.585549][ T1] softirqs last disabled at (1475259): [<ffffffff810b57a0>] irq_exit_rcu+0xa0/0x100
> [ 82.586852][ T1] ---[ end trace 0000000000000000 ]---
>
>
>
> To reproduce:
>
> # build kernel
> cd linux
> cp config-5.19.0-rc1-00114-gb709abb27054 .config
> make HOSTCC=gcc-11 CC=gcc-11 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage modules
> make HOSTCC=gcc-11 CC=gcc-11 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.
>
>
>