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:   Fri, 4 Nov 2022 10:16:53 +0800
From:   Feng Tang <feng.tang@intel.com>
To:     "Paul E. McKenney" <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>,
        <zhengjun.xing@intel.com>, Waiman Long <longman@redhat.com>,
        John Stultz <jstultz@google.com>
Subject: Re: [PATCH clocksource 2/2] clocksource: Exponential backoff for
 load-induced bogus watchdog reads
Message-ID: <Y2R2Fbuef2APXhU3@feng-clx>
References: <20221102184001.GA1306489@paulmck-ThinkPad-P17-Gen-1>
 <20221102184009.1306751-2-paulmck@kernel.org>
Content-Type: text/plain; charset="us-ascii"
Content-Disposition: inline
In-Reply-To: <20221102184009.1306751-2-paulmck@kernel.org>
MIME-Version: 1.0
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0: =?us-ascii?Q?4dAuxGC9bdboUYaOkGrMUMYCi2eEMWExtIIxrB0DeRapdUoIAKjxarwI4WW0?=
 =?us-ascii?Q?fTSFJS56o/sGJTTISKKqn9z8zJICBtu/kdXtIDdgxJ2UtSZv0Ku4s39lDKtR?=
 =?us-ascii?Q?fS9XKdSAIOtPf0wyPRMeiO8Wifbkdw2EnsJXx2WZqfV5IzmmXdvdpnmNhRI+?=
 =?us-ascii?Q?/Nu/C4Ukv6mvA4cEENG8hhwGTBWGjpQ11F3mAE/+ftP/DcSlegRkZx/jktsG?=
 =?us-ascii?Q?qg55G877dPMQAdsxKBbWGePJjZZ7UghupTeiLV52nfXKhCpRXkDp9lOiGU0I?=
 =?us-ascii?Q?00Mn+eq9v8qJGI6M6gSCLdF8OWu9YUn/ZIO8/HyOh5A5JXY4mQ4oGe5YaIFq?=
 =?us-ascii?Q?NQT1kYtiJsc7DL1rnrS/LbDarVaovv82H9j4VmGgok1n3xZ3eCoFy5yJtgHh?=
 =?us-ascii?Q?t387xYjh6yDKokDjMhYlmLNwESFDOcHAlgtwbrdzqmn3WEDIx9VqZT+ltktn?=
 =?us-ascii?Q?8XaB9vbbrYoPzJphczE2K+c32nyaBw0DN+qlBeoGoCYMzYYlTlXW2ZhjTERv?=
 =?us-ascii?Q?0Zwwo6qJFjcMnMr66ZIaIPv6XLoSJQm8SkvBZVO29l8tyeUpCHk0tFLzGuk7?=
 =?us-ascii?Q?QXILkjCjK5o12rDiXnb+ck6op2aG/H70XGFcWEemXUzjczkxTM9Og+LyDSX0?=
 =?us-ascii?Q?xoLb3Urvwmc7vatAWGhufU4rqq88vnjzz735P91lWMlf3lafHIoM5Ozaq1/m?=
 =?us-ascii?Q?Vww+Kg5v5OjFDl+nol+fvdmoEBy1UNvE+BYvtv4Th4AXyWrORqwwfBcxb1gD?=
 =?us-ascii?Q?AUZ9pU+WQekXP0LrdM4ilLbugOeCQ3gnGtaCPm8f7IR/hAhMbhJQmjFZee5U?=
 =?us-ascii?Q?cqvBjEgCxs4DOxGS1D/VFVO1t8NQdcw3CvrfR2a8lpfulawnwl+vq1+MVFwE?=
 =?us-ascii?Q?ftzwRECA0Teyc0NgE6pPGV0nWtI030n16GKoJ4CHSBf2uiU5QMZAnTtVzEo+?=
 =?us-ascii?Q?oldfmKkby2CBBWIA2Z4gZ8mHbou6C5lXFr41HJHxniagP0sjBkQgOuwefgZ+?=
 =?us-ascii?Q?aoDc1j9JHxUvY3CJFBXUKhzwIOP0TCcc/tijU1jOekuvnvhGqzWkklh8+5pY?=
 =?us-ascii?Q?ob7iooT9GLRsvAXPVUO8ZCD8SKIC+Y25Lp/KbuwBSoSWEppBhT2OJ6GEf5w7?=
 =?us-ascii?Q?xdMRNyQFe7lBO+6pVflhBXxFAe94rFBhlta2ZP0fUjHWXo5iUqfDYMbF0gc8?=
 =?us-ascii?Q?q9jhPdYGq1DW6eN/w7ZWwKmvXZ84/abEcqD8wR//DoFOlAjMPtG+sTam/4ck?=
 =?us-ascii?Q?LBrniKQSE7gXRAnp9lXc+8qe/1BDCaceMj9tTdizrvEdLdSr1QA0LhkjF/Iz?=
 =?us-ascii?Q?wknwHhKsmqxfA+RjS5kzX9lY3LReAZynQcCDmUTP1q7VlaeH1YweRdEwc9D5?=
 =?us-ascii?Q?rUwJgJ4uADsUPhVnF1WI4480HSTQLX3YSru+80C8P15WrRABQWYJ8WVeM5hY?=
 =?us-ascii?Q?Hr4vrDuQWidnRNHvCBlDn202zz/ifn8NKTpWMgIZbIlWhRqIu2NmhqC3gFwo?=
 =?us-ascii?Q?Q5yD2Z9wfGEZaf1Ard0whqMLSG+xBKDKYmd57bez/pLDIc2rRGdP99kTvosv?=
 =?us-ascii?Q?PiaUxShLX4DyZEagDNULIMbtuTSopYkB8RnNkwQl?=
X-MS-Exchange-CrossTenant-Network-Message-Id: 7130fde5-8746-42cd-10f4-08dabe0b162c
X-MS-Exchange-CrossTenant-AuthSource: MN0PR11MB6304.namprd11.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 04 Nov 2022 02:20:05.3344
 (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: dBWjPL6iDqG/qH3w8aT/4tOyzsZcf6oHfYfDCV6c2KEgTSmQpe/DS6XkijJkvkDk82WtWlF+J8g5k0HRGC7QGA==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: SA1PR11MB5946
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,
        RCVD_IN_MSPIKE_H3,RCVD_IN_MSPIKE_WL,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 Wed, Nov 02, 2022 at 11:40:09AM -0700, Paul E. McKenney wrote:
> 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.

I saw there is ongoing discussion about some wording, overall it
looks good to me, thanks!

Reviewed-by: Feng Tang <feng.tang@intel.com>

> [ paulmck: Apply Feng Tang 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>
> ---
>  include/linux/clocksource.h |  4 ++++
>  kernel/time/clocksource.c   | 31 +++++++++++++++++++++++++------
>  2 files changed, 29 insertions(+), 6 deletions(-)
> 
> diff --git a/include/linux/clocksource.h b/include/linux/clocksource.h
> index 1d42d4b173271..daac05aedf56a 100644
> --- a/include/linux/clocksource.h
> +++ b/include/linux/clocksource.h
> @@ -125,6 +125,10 @@ 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;
>  #endif
>  	struct module		*owner;
>  };
> diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
> index 3f5317faf891f..de8047b6720f5 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 - 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;
>  		}
> -		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;
>  		}
>  
> -- 
> 2.31.1.189.g2e36527f23
>