Re: [PATCH] rcu-tasks: Delay rcu_tasks_verify_self_tests() to avoid missed callbacks

[Waiman Long <longman@redhat.com>]

On 6/10/22 16:58, Paul E. McKenney wrote:
> On Fri, Jun 10, 2022 at 02:42:12PM -0400, Waiman Long wrote:
>> Even though rcu_tasks selftest is initiated early in the boot process,
>> the verification done at late initcall time may not be late enough to
>> catch all the callbacks especially on systems with just a few cpus and
>> small memory.
>>
>> After 12 bootup's On a s390x system, 1 of them had failed rcu_tasks
>> verification test.
>>
>> [    8.183013] call_rcu_tasks() has been failed.
>> [    8.183041] WARNING: CPU: 0 PID: 1 at kernel/rcu/tasks.h:1696 rcu_tasks_verify_self_tests+0x64/0xd0
>> [    8.203246] Callback from call_rcu_tasks() invoked.
>>
>> In this particular case, the callback missed the check by about
>> 20ms. Similar rcu_tasks selftest failures are also seen in ppc64le
>> systems.
>>
>> [    0.313391] call_rcu_tasks() has been failed.
>> [    0.313407] WARNING: CPU: 0 PID: 1 at kernel/rcu/tasks.h:1696 rcu_tasks_verify_self_tests+0x5c/0xa0
>> [    0.335569] Callback from call_rcu_tasks() invoked.
>>
>> Avoid this missed callback by delaying the verification using
>> delayed_work. The delay is set to be about 0.1s which hopefully will
>> be long enough to catch all the callbacks on systems with few cpus and
>> small memory.
>>
>> Fixes: bfba7ed084f8 ("rcu-tasks: Add RCU-tasks self tests")
>> Signed-off-by: Waiman Long <longman@redhat.com>
> Good catch, thank you!
>
> A few days ago, I queued this:
>
> 2585014188d5 ("rcu-tasks: Be more patient for RCU Tasks boot-time testing")
>
> This is shown in full at the end of this email.  Does this fix this
> problem for you?

I think your patch should fix the false positive warning and it give 
plenty of time for this to happen.

I do have one question though. rcu_tasks_verify_selft_tests() is called 
from do_initcalls(). Since it may not be the last late initcall, does 
that mean other late initcalls queued after that may be delayed by a 
second or more?

Thanks,
Longman

> 							Thanx, Paul
>
>> ---
>>   kernel/rcu/tasks.h | 19 ++++++++++++++++---
>>   1 file changed, 16 insertions(+), 3 deletions(-)
>>
>> diff --git a/kernel/rcu/tasks.h b/kernel/rcu/tasks.h
>> index 3925e32159b5..25f964a671ba 100644s
>> --- a/kernel/rcu/tasks.h
>> +++ b/kernel/rcu/tasks.h
>> @@ -1735,7 +1735,7 @@ static void rcu_tasks_initiate_self_tests(void)
>>   #endif
>>   }
>>   
>> -static int rcu_tasks_verify_self_tests(void)
>> +static void rcu_tasks_verify_self_tests(struct work_struct *work __maybe_unused)
>>   {
>>   	int ret = 0;
>>   	int i;
>> @@ -1749,10 +1749,23 @@ static int rcu_tasks_verify_self_tests(void)
>>   
>>   	if (ret)
>>   		WARN_ON(1);
>> +}
>> +
>> +static struct delayed_work rcu_tasks_verify_work;
>>   
>> -	return ret;
>> +/*
>> + * The rcu_tasks verification is done indirectly via the work queue to
>> + * introduce an additional 0.1s delay to catch all the callbacks before
>> + * the verification is done as late_initcall time may not be late enough
>> + * to have all the callbacks fired.
>> + */
>> +static int rcu_tasks_verify_schedule_work(void)
>> +{
>> +	INIT_DELAYED_WORK(&rcu_tasks_verify_work, rcu_tasks_verify_self_tests);
>> +	schedule_delayed_work(&rcu_tasks_verify_work, HZ/10);
>> +	return 0;
>>   }
>> -late_initcall(rcu_tasks_verify_self_tests);
>> +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
> ------------------------------------------------------------------------
>
> commit 2585014188d5e66052b4226b42602b6f3d921389
> Author: Paul E. McKenney <paulmck@kernel.org>
> 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@infradead.org>
>      Reported-by: Zhouyi Zhou <zhouzhouyi@gmail.com>
>      Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
>      Tested-by: Zhouyi Zhou <zhouzhouyi@gmail.com>
>
> diff --git a/kernel/rcu/tasks.h b/kernel/rcu/tasks.h
> index df6b2cb2f205d..fcbd0ec33c866 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);
> @@ -1776,23 +1777,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)
>   	}
>   };
>   
> @@ -1803,23 +1805,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
> @@ -1829,11 +1836,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);
>   		}
>   	}
>   
>