Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Message-ID: <d6e2029d-8390-908b-577d-8724706ee652@redhat.com>
Date:   Thu, 3 Nov 2022 21:01:45 -0400
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.3.0
Subject: Re: [PATCH clocksource 2/2] clocksource: Exponential backoff for
 load-induced bogus watchdog reads
Content-Language: en-US
To:     paulmck@kernel.org
Cc:     tglx@linutronix.de, linux-kernel@vger.kernel.org,
        john.stultz@linaro.org, sboyd@kernel.org, corbet@lwn.net,
        Mark.Rutland@arm.com, maz@kernel.org, kernel-team@meta.com,
        neeraju@codeaurora.org, ak@linux.intel.com, feng.tang@intel.com,
        zhengjun.xing@intel.com, John Stultz <jstultz@google.com>
References: <20221102184001.GA1306489@paulmck-ThinkPad-P17-Gen-1>
 <20221102184009.1306751-2-paulmck@kernel.org>
 <1fdbdf78-cdca-975f-7f57-e391263d0aec@redhat.com>
 <20221103204910.GF5600@paulmck-ThinkPad-P17-Gen-1>
 <61470eb8-fc3c-7f95-881e-03da1805b5ac@redhat.com>
 <20221104002616.GH5600@paulmck-ThinkPad-P17-Gen-1>
From:   Waiman Long <longman@redhat.com>
In-Reply-To: <20221104002616.GH5600@paulmck-ThinkPad-P17-Gen-1>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit
Precedence: bulk

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.

Cheers,
Longman