Hi Paul,
On Tue, Jun 07, 2022 at 04:42:09PM -0700, Paul E. McKenney wrote:
> On Fri, May 27, 2022 at 08:39:09AM +0800, Zhouyi Zhou wrote:
> > Sometimes, the kernel will boot too fast for rcu_tasks_verify_self_tests
> > to have all required grace periods.
As mentioned on IRC, with v5.19-rc2 I consistently see this on arm64 at boot
time, e.g.
| call_rcu_tasks() has been failed.
| ------------[ cut here ]------------
| WARNING: CPU: 0 PID: 1 at kernel/rcu/tasks.h:1751 rcu_tasks_verify_self_tests+0x48/0x74
| Modules linked in:
| CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.19.0-rc2 #2
| Hardware name: linux,dummy-virt (DT)
| pstate: 60400005 (nZCv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
| pc : rcu_tasks_verify_self_tests+0x48/0x74
| lr : rcu_tasks_verify_self_tests+0x6c/0x74
| sp : ffff80000800bd70
| x29: ffff80000800bd70 x28: 0000000000000000 x27: ffffbd05c97904c8
| x26: ffffbd05c98610a0 x25: 0000000000000007 x24: 0000000000000000
| x23: ffffbd05c9fa0b38 x22: ffffbd05ca42f000 x21: ffffbd05c9514ac0
| x20: ffffbd05ca038808 x19: ffffbd05ca038808 x18: 0000000000000030
| x17: 00000000808cf272 x16: 00000000b4c3fe3b x15: fffffffffffe4328
| x14: 0000000000000001 x13: 2e64656c69616620 x12: 6e65656220736168
| x11: 202928736b736174 x10: 5f7563725f6c6c61 x9 : 64656c696166206e
| x8 : 6565622073616820 x7 : 2928736b7361745f x6 : 7563725f6c6c6163
| x5 : ffff3f48ffbc0c80 x4 : 0000000000000000 x3 : 0000000000000000
| x2 : 0000000000000000 x1 : 0000000000000001 x0 : 00000000ffffffff
| Call trace:
| rcu_tasks_verify_self_tests+0x48/0x74
| do_one_initcall+0x74/0x400
| kernel_init_freeable+0x2fc/0x384
| kernel_init+0x28/0x130
| ret_from_fork+0x10/0x20
| irq event stamp: 188396
| hardirqs last enabled at (188395): [<ffffbd05c7d2b4f4>] vprintk_store+0x3e4/0x4b0
| hardirqs last disabled at (188396): [<ffffbd05c8d9a494>] el1_dbg+0x24/0x90
| softirqs last enabled at (188302): [<ffffbd05c8b95910>] release_sock+0xac/0xd0
| softirqs last disabled at (188300): [<ffffbd05c8b9588c>] release_sock+0x28/0xd0
| ---[ end trace 0000000000000000 ]---
| registered taskstats version 1
I gave the below diff a go with:
* 100 UP boots
* 100 64-CPU SMP boots
... in a KVM VM on a ThunderX2 host, and out of those 200 boots I never saw the
warning.
So FWIW:
Tested-by: Mark Rutland <mark.rutland@xxxxxxx>
Thanks for this!
Just as an aside, I had to grab this thread from lore as I'm not subscribed to
the RCU list, so there might be others who haven't seen this thread.
Mark.
> commit 3e95d4b287b37ee5f7f82e5ebd749ab89fd706c2
> Author: Paul E. McKenney <paulmck@xxxxxxxxxx>
> Date: Tue Jun 7 15:23:52 2022 -0700
>
> rcu-tasks: Be more patient for RCU Tasks boot-time testing
>
> The RCU-Tasks family of grace-period primitives can take some time to
> complete, and the amount of time can depend on the exact hardware and
> software configuration. Some configurations boot up fast enough that the
> RCU-Tasks verification process gets false-positive failures. This commit
> therefore allows up to 30 seconds for the grace periods to complete, with
> this value adjustable downwards using the rcupdate.rcu_task_stall_timeout
> kernel boot parameter.
>
> Reported-by: Matthew Wilcox <willy@xxxxxxxxxxxxx>
> Reported-by: Zhouyi Zhou <zhouzhouyi@xxxxxxxxx>
> Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxx>
>
> diff --git a/kernel/rcu/tasks.h b/kernel/rcu/tasks.h
> index f1209ce621c51..1a4c3adc5c397 100644
> --- a/kernel/rcu/tasks.h
> +++ b/kernel/rcu/tasks.h
> @@ -145,6 +145,7 @@ static int rcu_task_ipi_delay __read_mostly = RCU_TASK_IPI_DELAY;
> module_param(rcu_task_ipi_delay, int, 0644);
>
> /* Control stall timeouts. Disable with <= 0, otherwise jiffies till stall. */
> +#define RCU_TASK_BOOT_STALL_TIMEOUT (HZ * 30)
> #define RCU_TASK_STALL_TIMEOUT (HZ * 60 * 10)
> static int rcu_task_stall_timeout __read_mostly = RCU_TASK_STALL_TIMEOUT;
> module_param(rcu_task_stall_timeout, int, 0644);
> @@ -1778,23 +1779,24 @@ struct rcu_tasks_test_desc {
> struct rcu_head rh;
> const char *name;
> bool notrun;
> + unsigned long runstart;
> };
>
> static struct rcu_tasks_test_desc tests[] = {
> {
> .name = "call_rcu_tasks()",
> /* If not defined, the test is skipped. */
> - .notrun = !IS_ENABLED(CONFIG_TASKS_RCU),
> + .notrun = IS_ENABLED(CONFIG_TASKS_RCU),
> },
> {
> .name = "call_rcu_tasks_rude()",
> /* If not defined, the test is skipped. */
> - .notrun = !IS_ENABLED(CONFIG_TASKS_RUDE_RCU),
> + .notrun = IS_ENABLED(CONFIG_TASKS_RUDE_RCU),
> },
> {
> .name = "call_rcu_tasks_trace()",
> /* If not defined, the test is skipped. */
> - .notrun = !IS_ENABLED(CONFIG_TASKS_TRACE_RCU)
> + .notrun = IS_ENABLED(CONFIG_TASKS_TRACE_RCU)
> }
> };
>
> @@ -1805,23 +1807,28 @@ static void test_rcu_tasks_callback(struct rcu_head *rhp)
>
> pr_info("Callback from %s invoked.\n", rttd->name);
>
> - rttd->notrun = true;
> + rttd->notrun = false;
> }
>
> static void rcu_tasks_initiate_self_tests(void)
> {
> + unsigned long j = jiffies;
> +
> pr_info("Running RCU-tasks wait API self tests\n");
> #ifdef CONFIG_TASKS_RCU
> + tests[0].runstart = j;
> synchronize_rcu_tasks();
> call_rcu_tasks(&tests[0].rh, test_rcu_tasks_callback);
> #endif
>
> #ifdef CONFIG_TASKS_RUDE_RCU
> + tests[1].runstart = j;
> synchronize_rcu_tasks_rude();
> call_rcu_tasks_rude(&tests[1].rh, test_rcu_tasks_callback);
> #endif
>
> #ifdef CONFIG_TASKS_TRACE_RCU
> + tests[2].runstart = j;
> synchronize_rcu_tasks_trace();
> call_rcu_tasks_trace(&tests[2].rh, test_rcu_tasks_callback);
> #endif
> @@ -1831,11 +1838,18 @@ static int rcu_tasks_verify_self_tests(void)
> {
> int ret = 0;
> int i;
> + unsigned long bst = rcu_task_stall_timeout;
>
> + if (bst <= 0 || bst > RCU_TASK_BOOT_STALL_TIMEOUT)
> + bst = RCU_TASK_BOOT_STALL_TIMEOUT;
> for (i = 0; i < ARRAY_SIZE(tests); i++) {
> - if (!tests[i].notrun) { // still hanging.
> - pr_err("%s has been failed.\n", tests[i].name);
> - ret = -1;
> + while (tests[i].notrun) { // still hanging.
> + if (time_after(jiffies, tests[i].runstart + bst)) {
> + pr_err("%s has failed boot-time tests.\n", tests[i].name);
> + ret = -1;
> + break;
> + }
> + schedule_timeout_uninterruptible(1);
> }
> }
>
>
