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

[Paul E. McKenney]

On Fri, Nov 04, 2022 at 10:49:13PM -0400, Waiman Long wrote:
> 
> On 11/4/22 22:38, Paul E. McKenney wrote:
> > On Fri, Nov 04, 2022 at 09:55:02AM -0400, Waiman Long wrote:
> > > 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:
> > [ . . . ]
> > 
> > > > > > > > +					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.
> > Thank you, and please see below for the updated patch.
> > 
> > 							Thanx, Paul
> > 
> > ------------------------------------------------------------------------
> > 
> > commit a7dc308e8359eafb58df360e06b66ecbf79a4d0b
> > Author: Paul E. McKenney <paulmck@xxxxxxxxxx>
> > 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@xxxxxxxxxx>
> >      Reported-by: Feng Tang <feng.tang@xxxxxxxxx>
> >      Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxx>
> >      Reviewed-by: Feng Tang <feng.tang@xxxxxxxxx>
> >      Cc: John Stultz <jstultz@xxxxxxxxxx>
> >      Cc: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
> >      Cc: Stephen Boyd <sboyd@xxxxxxxxxx>
> >      Cc: Waiman Long <longman@xxxxxxxxxx>
> > 
> > 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..4015ec6503a52 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 since last message), probable CPU overutilization, skipping watchdog check.\n", smp_processor_id(), watchdog->name, wd_nsec, WATCHDOG_INTERVAL, cs->wd_bogus_count);
> > +				cs->wd_last_bogus = wdnow;
> > +				if (cs->wd_bogus_shift < 10)
> > +					cs->wd_bogus_shift++;
> > +				cs->wd_bogus_count = 0;
> > +			}
> >   			continue;
> >   		}
> > -		if (wd_nsec > (wdi << 2)) {
> > -			/* 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, probable CPU overutilization, skipping watchdog check.\n", smp_processor_id(), watchdog->name, wd_nsec, WATCHDOG_INTERVAL);
> > +		/* Check too-short measurements second to handle wrap. */
> > +		if (wd_nsec < (wdi >> 2) || cs_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);
> >   			continue;
> >   		}
> > 
> Looks good to me.
> 
> Reviewed-by: Waiman Long <longman@xxxxxxxxxx>

Thank you!  I will apply this on my next rebase.

							Thanx, Paul