Re: [PATCH clocksource 2/2] clocksource: Exponential backoff for load-induced bogus watchdog reads

[Waiman Long <longman@redhat.com>]

On 11/3/22 22:23, Paul E. McKenney wrote:
> On Thu, Nov 03, 2022 at 09:01:45PM -0400, Waiman Long wrote:
>> On 11/3/22 20:26, Paul E. McKenney wrote:
>>> On Thu, Nov 03, 2022 at 08:20:27PM -0400, Waiman Long wrote:
>>>> On 11/3/22 16:49, Paul E. McKenney wrote:
>>>>> commit da44b8af99222ff8761a98ca8c00837a7d607d28
>>>>> Author: Paul E. McKenney<paulmck@kernel.org>
>>>>> Date:   Fri Oct 28 10:38:58 2022 -0700
>>>>>
>>>>>        clocksource: Exponential backoff for load-induced bogus watchdog reads
>>>>>        The clocksource watchdog will reject measurements that are excessively
>>>>>        delayed, that is, by more than 1.5 seconds beyond the intended 0.5-second
>>>>>        watchdog interval.  On an extremely busy system, this can result in a
>>>>>        console message being printed every two seconds.  This is excessively
>>>>>        noisy for a non-error condition.
>>>>>        Therefore, apply exponential backoff to these messages.  This exponential
>>>>>        backoff is capped at 1024 times the watchdog interval, which comes to
>>>>>        not quite one message per ten minutes.
>>>>>        Please note that the bogus watchdog reads that occur when the watchdog
>>>>>        interval is less than 0.125 seconds are still printed unconditionally
>>>>>        because these likely correspond to a serious error condition in the
>>>>>        timer code or hardware.
>>>>>        [ paulmck: Apply Feng Tang feedback. ]
>>>>>        [ paulmck: Apply Waiman Long feedback. ]
>>>>>        Reported-by: Waiman Long<longman@redhat.com>
>>>>>        Reported-by: Feng Tang<feng.tang@intel.com>
>>>>>        Signed-off-by: Paul E. McKenney<paulmck@kernel.org>
>>>>>        Cc: John Stultz<jstultz@google.com>
>>>>>        Cc: Thomas Gleixner<tglx@linutronix.de>
>>>>>        Cc: Stephen Boyd<sboyd@kernel.org>
>>>>>        Cc: Feng Tang<feng.tang@intel.com>
>>>>>        Cc: Waiman Long<longman@redhat.com>
>>>>>
>>>>> diff --git a/include/linux/clocksource.h b/include/linux/clocksource.h
>>>>> index 1d42d4b173271..23b73f2293d6d 100644
>>>>> --- a/include/linux/clocksource.h
>>>>> +++ b/include/linux/clocksource.h
>>>>> @@ -125,6 +125,9 @@ struct clocksource {
>>>>>     	struct list_head	wd_list;
>>>>>     	u64			cs_last;
>>>>>     	u64			wd_last;
>>>>> +	u64			wd_last_bogus;
>>>>> +	int			wd_bogus_shift;
>>>>> +	unsigned long		wd_bogus_count;
>>>>>     #endif
>>>>>     	struct module		*owner;
>>>>>     };
>>>>> diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
>>>>> index 3f5317faf891f..1eefb56505350 100644
>>>>> --- a/kernel/time/clocksource.c
>>>>> +++ b/kernel/time/clocksource.c
>>>>> @@ -442,14 +442,33 @@ static void clocksource_watchdog(struct timer_list *unused)
>>>>>     		/* Check for bogus measurements. */
>>>>>     		wdi = jiffies_to_nsecs(WATCHDOG_INTERVAL);
>>>>> -		if (wd_nsec < (wdi >> 2)) {
>>>>> -			/* This usually indicates broken timer code or hardware. */
>>>>> -			pr_warn("timekeeping watchdog on CPU%d: Watchdog clocksource '%s' advanced only %lld ns during %d-jiffy time interval, skipping watchdog check.\n", smp_processor_id(), watchdog->name, wd_nsec, WATCHDOG_INTERVAL);
>>>>> +		if (wd_nsec > (wdi << 2) || cs_nsec > (wdi << 2)) {
>>>>> +			bool needwarn = false;
>>>>> +			u64 wd_lb;
>>>>> +
>>>>> +			cs->wd_bogus_count++;
>>>>> +			if (!cs->wd_bogus_shift) {
>>>>> +				needwarn = true;
>>>>> +			} else {
>>>>> +				delta = clocksource_delta(wdnow, cs->wd_last_bogus, watchdog->mask);
>>>>> +				wd_lb = clocksource_cyc2ns(delta, watchdog->mult, watchdog->shift);
>>>>> +				if ((1 << cs->wd_bogus_shift) * wdi <= wd_lb)
>>>>> +					needwarn = true;
>>>>> +			}
>>>>> +			if (needwarn) {
>>>>> +				/* This can happen on busy systems, which can delay the watchdog. */
>>>>> +				pr_warn("timekeeping watchdog on CPU%d: Watchdog clocksource '%s' advanced an excessive %lld ns during %d-jiffy time interval (%lu additional), probable CPU overutilization, skipping watchdog check.\n", smp_processor_id(), watchdog->name, wd_nsec, WATCHDOG_INTERVAL, cs->wd_bogus_count);
>>>> Just one question, does "%lu additional" means the number of bogus count
>>>> that doesn't meet the needwarn requirement and hence skipped. If so, I think
>>>> you have to use "cs->wd_bogus_cnt - 1". Other than that, the change looks
>>>> good to me.
>>> It means the number since the last report, or, for the first report,
>>> the number since boot.
>>>
>>> Does that work for you?
>> OK, I think the word "additional" tricks me into thinking about extra bogus
>> messages in additional to the current one. Using another word like "total"
>> may be less confusing.
> My concern with "total" is that people might think that the numbers
> meant the total number of instances since boot.
>
> So how about "(9 since last message)" or similar?
>
> 							Thanx, Paul

Yes, that looks good to me.

Thanks!
Longman