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:   Thu, 20 Oct 2022 16:09:01 +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: <Y1ECHVUHilqgKD9o@feng-clx>
References: <20221019230904.GA2502730@paulmck-ThinkPad-P17-Gen-1>
Content-Type: text/plain; charset="us-ascii"
Content-Disposition: inline
In-Reply-To: <20221019230904.GA2502730@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?PvIMFHcsW0jTZ/LNyKtrH+QKT5zZIrG2UwO7urGv6Y2g8gx2UT5NRxqSmKDT?=
 =?us-ascii?Q?QZt5moxpKmuapsRO3S7YjkwkcO1NAKr2fz5x//994PxEYYAL472+LUzBkEct?=
 =?us-ascii?Q?wLLvj+6KIvyujxDZCV4OpvvsZqyWyx3bDa5B9mYYl1mBizW/7zPdSE6LUWps?=
 =?us-ascii?Q?MhRhCBz4RzbTVFS4x3R5wiaf8Md7BzxtLd3q66giOKqXfnPF4JhEKBYspNGx?=
 =?us-ascii?Q?Kas2jGwXTJ6N3ORvVkCN7NaAS5WTdVdDKuO2qUPXLkIrTFdlbiT5BVwWNAfL?=
 =?us-ascii?Q?TrYDtK9RyEpYJNdnO4orI0X7Ur3zm8Yk2n2zGn2oPCQY1AGuPUrbNZQsaFx0?=
 =?us-ascii?Q?VE+bNYSZM6RpOJAwBRHWRzBIBucZcqbig0XfACe1IbJA7aiYHbj+zM3DayWc?=
 =?us-ascii?Q?XVjcz2qpAra6HfU8S0XuHRU5SHwIl14L3KLDzzcem7GUd6f9fbY0ktPWNJOU?=
 =?us-ascii?Q?soOteUg61a+zBEdr4IX+1gwf5tdl7NeRySIHa6UnpCpfgovXpV1rNoNIAd3Q?=
 =?us-ascii?Q?o8enuxPCsIchTKqVzQJUnAcKwzSC/frLHLKexAt0XqpZ1NFnmuZQgtrSQAWC?=
 =?us-ascii?Q?0z6mOU7owaToC9VvG4HLdJHXPA91qaaJkgNmGtkRPBVkBP3m1cEq0w7l7JD1?=
 =?us-ascii?Q?LaGjridp7zu7ijYQ5nH7lRWftB8Mh69a0yghqAc9KtluEQ0FDN3WVFlLM75n?=
 =?us-ascii?Q?CO/vug/z3ZhE4AhX6ImtKFGUPi1sW1g9grxAECZ92hRoIFZRdEuJ+d7YIQEY?=
 =?us-ascii?Q?vTj7aTtaHpFj6AgmM0AJ1WDLVQ5q7QMqIxOYOzzM+DEFpsgQmuyXo4q1Ur7p?=
 =?us-ascii?Q?+tnYM2Nse73715kKtJ44v06QRbXCUURULBHx33m65p1gqJMgcdc96xS075Hz?=
 =?us-ascii?Q?5KEXvj+NCulaBrhOYgse+PJEGyCDLK/EjUJGyYZYUlXPvGRzH3+Dw02qR2Yr?=
 =?us-ascii?Q?Lsi8AL+yvyl5vjg8tWfxIJ9pBWBQ2u++UTMiWOk4YIeUeEi7JONOJEhOv5qv?=
 =?us-ascii?Q?Btqv0jAgFxtRHTlKKjbHKGlBBAYb5dsPwP+sQh1RE1QMcxCJoZj7VKXK53PS?=
 =?us-ascii?Q?D1d9P83kZuDSlZ47ynFH3hpkjiJI+ZJSIeKtq1sb3dluyS3GK1N22QKXYgRE?=
 =?us-ascii?Q?A5sOd9DH0HD8KSKsiStoP9bb9cm8UXhgsFocEuTRAJxdKvNLx1KCPda5X+Ar?=
 =?us-ascii?Q?E40t8EoRvGh23E7yWRcqVwCqw58gm+juvM2CE/TFFjPngamoO7IE62/YI2QZ?=
 =?us-ascii?Q?Nfg4z5DI0WkKBOobN+7d2HR5HWZ6QK61oISsniTFAvW8bdJwR5squnCy34JA?=
 =?us-ascii?Q?EV4ddx5DgIX99sAixv9k0i4yLEpuIMhF0w4L1aovg3MuL8M96qToXaPO03Fo?=
 =?us-ascii?Q?u35XV0t4hVicjx/mUqZ3wYUJgsJ9itYDIefwj7oMg7wpomt+OPoM6W39y6b6?=
 =?us-ascii?Q?mOprJcfJScznIbNdGc5wKMuFs1Djo4GJShVqYoeqDEkcryhrIpuaxD3uzZwW?=
 =?us-ascii?Q?oWQtV+vacgC9gWaEpvHwrJ2b7ll54AFb/DlVixeWmPgtNipWdm8e7Tl9XjAK?=
 =?us-ascii?Q?7mDEDonDckeMy7uGIQb5GkklfwO0O8iCiSeoZ4vx?=
X-MS-Exchange-CrossTenant-Network-Message-Id: 36818e28-26d6-4305-2a39-08dab2725fb9
X-MS-Exchange-CrossTenant-AuthSource: MN0PR11MB6304.namprd11.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 20 Oct 2022 08:09:13.0051
 (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: NlyLxEJ7cOLvH24WhGw3nODdlQ+pExRChm0dYoceCcxudQxfcFSqEo7lw5W7Yy25Q6Pak/clacWaM3KPl1mybQ==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: DS0PR11MB7630
X-OriginatorOrg: intel.com
X-Spam-Status: No, score=-4.6 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,URIBL_BLOCKED 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 Wed, Oct 19, 2022 at 04:09:04PM -0700, Paul E. McKenney wrote:
> One remaining clocksource-skew issue involves extreme CPU overcommit,
> which can cause the clocksource watchdog measurements to be delayed by
> tens of seconds.  This in turn means that a clock-skew criterion that
> is appropriate for a 500-millisecond interval will instead give lots of
> false positives.

I remembered I saw logs that the watchdog were delayed to dozens of
or hundreds of seconds. 

Thanks for the fix which makes sense to me! with some nits below.

> Therefore, check for the watchdog clocksource reporting much larger or
> much less than the time specified by WATCHDOG_INTERVAL.  In these cases,
> print a pr_warn() warning and refrain from marking the clocksource under
> test as being unstable.
> 
> Reported-by: Chris Mason <clm@meta.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/kernel/time/clocksource.c b/kernel/time/clocksource.c
> index 8058bec87acee..dcaf38c062161 100644
> --- a/kernel/time/clocksource.c
> +++ b/kernel/time/clocksource.c
> @@ -386,7 +386,7 @@ EXPORT_SYMBOL_GPL(clocksource_verify_percpu);
>  
>  static void clocksource_watchdog(struct timer_list *unused)
>  {
> -	u64 csnow, wdnow, cslast, wdlast, delta;
> +	u64 csnow, wdnow, cslast, wdlast, delta, wdi;
>  	int next_cpu, reset_pending;
>  	int64_t wd_nsec, cs_nsec;
>  	struct clocksource *cs;
> @@ -440,6 +440,17 @@ static void clocksource_watchdog(struct timer_list *unused)
>  		if (atomic_read(&watchdog_reset_pending))
>  			continue;
>  
> +		/* Check for bogus measurements. */
> +		wdi = jiffies_to_nsecs(WATCHDOG_INTERVAL);
> +		if (wd_nsec < (wdi >> 2)) {
> +			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;
> +		}

If this happens (500ms timer happens only after less than 125ms),
there is some severe problem with timer/interrupt system. 

> +		if (wd_nsec > (wdi << 2)) {
> +			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);
> +			continue;
> +		}

I agree with Waiman that some rate limiting may be needed. As there
were reports of hundreds of seconds of delay, 2 seconds delay could
easily happen if a system is too busy or misbehave to trigger this
problem.

Thanks,
Feng