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;
Date:   Tue, 1 Nov 2022 13:43:32 +0800
From:   Feng Tang <feng.tang@intel.com>
To:     "Paul E. McKenney" <paulmck@kernel.org>
CC:     <linux-kernel@vger.kernel.org>, <clm@meta.com>,
        <jstultz@google.com>, <tglx@linutronix.de>, <sboyd@kernel.org>,
        <longman@redhat.com>
Subject: Re: [PATCH clocksource] Reject bogus watchdog clocksource
 measurements
Message-ID: <Y2CyBGNM0rMI6nCG@feng-clx>
References: <20221019230904.GA2502730@paulmck-ThinkPad-P17-Gen-1>
 <Y1ECHVUHilqgKD9o@feng-clx>
 <20221020140944.GK5600@paulmck-ThinkPad-P17-Gen-1>
 <Y1Hr6PNy9EJk245f@feng-clx>
 <20221028175245.GN5600@paulmck-ThinkPad-P17-Gen-1>
 <Y19kStu4zBFyvKPK@feng-clx>
 <20221031174212.GB5600@paulmck-ThinkPad-P17-Gen-1>
Content-Type: text/plain; charset="us-ascii"
Content-Disposition: inline
In-Reply-To: <20221031174212.GB5600@paulmck-ThinkPad-P17-Gen-1>
MIME-Version: 1.0
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0: =?us-ascii?Q?Nj6Ms4gdH/3Q2czeGuE8l2qQc87I6gw/YszpdCx3VzJmlOiwjCvkfwBGR2As?=
 =?us-ascii?Q?iSMP4SG6ZyyWf7aelZx8kAF6aL4VP3rh7gzKII4QiRfl3mTF7P27IVLDdlJF?=
 =?us-ascii?Q?JK0jOgYvEQgvM7NaUkbvq1xqOsuC2BZAAdeta0YoNGOfs59I5dvOT7PZxc9F?=
 =?us-ascii?Q?dZkIqDTSIli6j/yChucXRtwNBPCmnIkCBH2KC8/YiTV0VoHla+p+W+URAWtW?=
 =?us-ascii?Q?1BFtCq7bVXqRpn9/UfbPI9eoGTsb/TgwzZTB7xjORxJ0KdQrzd931F8rFPuV?=
 =?us-ascii?Q?m3/dqS1EdnOSBZk2ghdmOSJnyonJvMwZm/hjvO+orSWREovS0woFFSWChIRk?=
 =?us-ascii?Q?VnxVrBs+NlaZ4/nwj9illeYy/RVu44RUFDUJZJuR/LEnsVHIE4PuRd9sxpAS?=
 =?us-ascii?Q?3zm69PRz2JJOj1VYk1YOy5q+gfn01pGK3FLjR+3unqQFo1sN4L3zRYdWaxl9?=
 =?us-ascii?Q?w5RUVr63JJCCNicfFFCNYKHePaTmbqFY4pFdjkGdssIhvhGCePgIdYyOKiLs?=
 =?us-ascii?Q?zuIkFZMNMuwb9hyoFtuotTCYRu73TZHKzEtsklh30MLn5FQF76a8+wvySROV?=
 =?us-ascii?Q?nzvK8zuqAKNltK+Q5uRDHQK3UngW/9l/an0sbpGJ+wxV4Mcod+hUUQSzs4LC?=
 =?us-ascii?Q?2tgdNrLwEHcYIWWeOdTP0bUmyNP8GIyR+seXTgKefEmuh4J8Vz5imWg/AfVe?=
 =?us-ascii?Q?wORxdZRZ0J7qUJzs4DOJzkig5HgJV2RN8v6iIS9vaDntUIoferehMxgWjDUQ?=
 =?us-ascii?Q?B3JSoM1ghZoAm2xzWDDGX5TEUCJunIs+EDR08m538nWTZqnuA4ZIJHSRhbVf?=
 =?us-ascii?Q?5ZBc9sarUPyVLZPGdN0zoiWOAcHDG95FXL8kIBnCsEa69HxhxNhF1szzkPRj?=
 =?us-ascii?Q?XC8wIKcS7yBG86Bml/zK1x7k4+hP2ZaQ2GG2zudPg84UrZ6gybFS1Xz9jGZb?=
 =?us-ascii?Q?KT/z+kUHedMlzGEaJ2Vtj3WqANWzGoG3XFo4n+JNjQ9gn30oPMRJ5fGk01dS?=
 =?us-ascii?Q?0T3Z8XJ7Y/IkAASwEmXrlTv45mDLdjahY5DfTPI3Krj2slS47JILfx0HZk7M?=
 =?us-ascii?Q?rFKc6qvxRZRe6jHP7jS4gBguH94GDkx5d2v33cM3GD2yxZVvmo2pmCqV/tKZ?=
 =?us-ascii?Q?f26RLPDfWbP7k7RN14MvLXA9I1+1mY4QB1/cyFYfe8y5J9sZ+giuaiKv7lIM?=
 =?us-ascii?Q?kGdDaijQiI5d4Y4MUIMTcfcj+ToVtU7u7rq0uZ5sjP4YdgmNpDTkPubvf3an?=
 =?us-ascii?Q?5dEupJuhDq6UFJgXbWWH68MPOqSuKvyXlAd4xsslsKSwee3Fz3s1bFWKv2Wv?=
 =?us-ascii?Q?Uty+k4J23+aKClw+BIKtyO3u6fBn3wRwWlu0AHnvhGKN58o7aoYWSfKRS+lk?=
 =?us-ascii?Q?hxHdyrzAoaQbEdDw47hbBv8UNxmzPRG6jDO7b6NlNwz0GjdRI+gcIGtra+jx?=
 =?us-ascii?Q?4oKQqROvzZeYVwASVdGLgkFlyLT3pqnOmj3cqYaPCacprKK+875uSQdduNWg?=
 =?us-ascii?Q?li9GVig1Sdf8mvHOT6/OmooBbe8dNY1//vwpzuXJarklS7F1IZU7ysuMW9DV?=
 =?us-ascii?Q?4OFee0gVJBdPuEbsuEkJi7SLRtZar9losL26VyvK?=
X-MS-Exchange-CrossTenant-Network-Message-Id: fde34ff4-d0b8-42b1-588c-08dabbcc071e
X-MS-Exchange-CrossTenant-AuthSource: CY5PR11MB6308.namprd11.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 01 Nov 2022 05:43:39.4904
 (UTC)
X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted
X-MS-Exchange-CrossTenant-Id: 46c98d88-e344-4ed4-8496-4ed7712e255d
X-MS-Exchange-CrossTenant-MailboxType: HOSTED
X-MS-Exchange-CrossTenant-UserPrincipalName: cuFmhXoYdQ1zbwed2j8jq5YLCvgqISN+Thwi04v1cJpNI5NRobWHa5ql/njRmB+1W8VEEyKsG1jzMkMTLdgKTg==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: DM6PR11MB4708
X-OriginatorOrg: intel.com
X-Spam-Status: No, score=-5.4 required=5.0 tests=BAYES_00,DKIMWL_WL_HIGH,
        DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,RCVD_IN_DNSWL_MED,
        SPF_HELO_NONE,SPF_NONE autolearn=ham autolearn_force=no version=3.4.6
X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on
        lindbergh.monkeyblade.net
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

On Mon, Oct 31, 2022 at 10:42:12AM -0700, Paul E. McKenney wrote:

[...]
> > > @@ -448,8 +448,26 @@ static void clocksource_watchdog(struct timer_list *unused)
> > >  			continue;
> > >  		}
> > >  		if (wd_nsec > (wdi << 2)) {
> > 
> > Just recalled one thing, that it may be better to check 'cs_nsec' 
> > instead of 'wd_nsec', as some watchdog may have small wrap-around
> > value. IIRC, HPET's counter is 32 bits long and wraps at about
> > 300 seconds, and PMTIMER's counter is 24 bits which wraps at about
> > 3 ~ 4 seconds. So when a long stall of the watchdog timer happens,
> > the watchdog's value could 'overflow' many times.
> > 
> > And usually the 'current' closcksource has longer wrap time than
> > the watchdog.
> 
> Why not both?

You mean checking both clocksource and the watchdog? It's fine for
me, though I still trust clocksource more.

I checked some old emails and found some long stall logs for reference.

* one stall of 471 seconds

 [ 2410.694068] clocksource: timekeeping watchdog on CPU262: Marking clocksource 'tsc' as unstable because the skew is too large:
 [ 2410.706920] clocksource:                       'hpet' wd_nsec: 0 wd_now: ffd70be2 wd_last: 40da633b mask: ffffffff
 [ 2410.718583] clocksource:                       'tsc' cs_nsec: 471766594285 cs_now: 44f62c184e9 cs_last: 394a7a43771 mask: ffffffffffffffff
 [ 2410.732568] clocksource:                       'tsc' is current clocksource.
 [ 2410.740553] tsc: Marking TSC unstable due to clocksource watchdog
 [ 2410.747611] TSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.
 [ 2410.757321] sched_clock: Marking unstable (2398804490960, 11943006672)<-(2419023952548, -8276474713)
 [ 2410.767741] clocksource: Checking clocksource tsc synchronization from CPU 233 to CPUs 0,73,93-94,226,454,602,821.
 [ 2410.784045] clocksource: Switched to clocksource hpet


* another one of 5 seconds

 [ 3302.211708] clocksource: timekeeping watchdog on CPU9: Marking clocksource 'tsc' as unstable because the skew is too large:
 [ 3302.211710] clocksource:                       'acpi_pm' wd_nsec: 312227950 wd_now: 92367f wd_last: 8128bd mask: ffffff
 [ 3302.211712] clocksource:                       'tsc' cs_nsec: 4999196389 cs_now: 9e811223a9754 cs_last: 9e80e767df194 mask: ffffffffffffffff
 [ 3302.211714] clocksource:                       'tsc' is current clocksource.
 [ 3302.211716] tsc: Marking TSC unstable due to clocksource watchdog


> 
>  		if (wd_nsec > (wdi << 2) || cs_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);
> > > +			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;
> > 
> > I'm not sure if we need to check the last_bogus counter, or just
> > the current interval 'cs_nsec' is what we care, and some code
> > like this ?
> 
> I thought we wanted exponential backoff?  Do you really get that from
> the changes below?

Aha, I misunderstood your words. I thought to only report one time for
each 2, 4, 8, ... 256 seconds stall, and after that only report stall
of 512+ seconds. So your approach looks good to me, as our intention is
to avoid the flood of warning message.

Thanks,
Feng

> And should we be using something like the jiffies counter to measure the
> exponential backoff?
> 
> 							Thanx, Paul
> 
> > diff --git a/include/linux/clocksource.h b/include/linux/clocksource.h
> > index daac05aedf56..3910dbb9b960 100644
> > --- a/include/linux/clocksource.h
> > +++ b/include/linux/clocksource.h
> > @@ -125,7 +125,6 @@ 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;
> >  	unsigned long		wd_bogus_count_last;
> > diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
> > index 6537ffa02e44..8e6d498b1492 100644
> > --- a/kernel/time/clocksource.c
> > +++ b/kernel/time/clocksource.c
> > @@ -442,28 +442,18 @@ static void clocksource_watchdog(struct timer_list *unused)
> >  
> >  		/* Check for bogus measurements. */
> >  		wdi = jiffies_to_nsecs(WATCHDOG_INTERVAL);
> > -		if (wd_nsec < (wdi >> 2)) {
> > +		if (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);
> > +			pr_warn("timekeeping watchdog on CPU%d: clocksource '%s' advanced only %lld ns during %d-jiffy time interval, skipping watchdog check.\n", smp_processor_id(), cs->name, wd_nsec, WATCHDOG_INTERVAL);
> >  			continue;
> >  		}
> > -		if (wd_nsec > (wdi << 2)) {
> > -			bool needwarn = false;
> > -			u64 wd_lb;
> > -
> > +		if (cs_nsec > (wdi << 2)) {
> >  			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) {
> > +			if (!cs->wd_bogus_shift ||
> > +			    (1 << cs->wd_bogus_shift) * wdi <= cs_nsec) {
> >  				/* 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 - cs->wd_bogus_count_last);
> > -				cs->wd_last_bogus = wdnow;
> > +				pr_warn("timekeeping watchdog on CPU%d: clocksource '%s' advanced an excessive %lld ns during %d-jiffy time interval (%lu additional), probable CPU overutilization, skipping watchdog check.\n", smp_processor_id(), cs->name, cs_nsec, WATCHDOG_INTERVAL, cs->wd_bogus_count - cs->wd_bogus_count_last);
> > +
> >  				if (cs->wd_bogus_shift < 10)
> >  					cs->wd_bogus_shift++;
> >  				cs->wd_bogus_count_last = cs->wd_bogus_count;
> > 
> > Thanks,
> > Feng
> > 
> > 
> > > +			}
> > > +			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 - cs->wd_bogus_count_last);
> > > +				cs->wd_last_bogus = wdnow;
> > > +				if (cs->wd_bogus_shift < 10)
> > > +					cs->wd_bogus_shift++;
> > > +				cs->wd_bogus_count_last = cs->wd_bogus_count;
> > > +			}
> > >  			continue;
> > >  		}
> > >