Re: [PATCH] sched: Warn on long periods of pending need_resched

From: Ingo Molnar <mingo@kernel.org>
To: Josh Don <joshdon@google.com>
Cc: Ingo Molnar <mingo@redhat.com>,
	Peter Zijlstra <peterz@infradead.org>,
	Juri Lelli <juri.lelli@redhat.com>,
	Vincent Guittot <vincent.guittot@linaro.org>,
	Dietmar Eggemann <dietmar.eggemann@arm.com>,
	Steven Rostedt <rostedt@goodmis.org>,
	Ben Segall <bsegall@google.com>, Mel Gorman <mgorman@suse.de>,
	Daniel Bristot de Oliveira <bristot@redhat.com>,
	Luis Chamberlain <mcgrof@kernel.org>,
	Kees Cook <keescook@chromium.org>,
	Iurii Zaikin <yzaikin@google.com>,
	linux-kernel@vger.kernel.org, linux-fsdevel@vger.kernel.org,
	David Rientjes <rientjes@google.com>,
	Oleg Rombakh <olegrom@google.com>, Paul Turner <pjt@google.com>
Subject: Re: [PATCH] sched: Warn on long periods of pending need_resched
Date: Wed, 17 Mar 2021 09:25:50 +0100	[thread overview]
Message-ID: <20210317082550.GA3881262@gmail.com> (raw)
In-Reply-To: <20210317045949.1584952-1-joshdon@google.com>

* Josh Don <joshdon@google.com> wrote:

> From: Paul Turner <pjt@google.com>
> 
> CPU scheduler marks need_resched flag to signal a schedule() on a
> particular CPU. But, schedule() may not happen immediately in cases
> where the current task is executing in the kernel mode (no
> preemption state) for extended periods of time.
> 
> This patch adds a warn_on if need_resched is pending for more than the
> time specified in sysctl resched_latency_warn_ms. Monitoring is done via
> the tick and the accuracy is hence limited to jiffy scale. This also
> means that we won't trigger the warning if the tick is disabled.

Looks useful.

> If resched_latency_warn_ms is set to the default value, only one warning
> will be produced per boot.

Looks like a value hack, should probably be a separate flag, 
defaulting to warn-once.

> This warning only exists under CONFIG_SCHED_DEBUG. If it goes off, it is
> likely that there is a missing cond_resched() somewhere.

CONFIG_SCHED_DEBUG is default-y, so most distros have it enabled.

> +/*
> + * Print a warning if need_resched is set for at least this long. At the
> + * default value, only a single warning will be printed per boot.
> + *
> + * Values less than 2 disable the feature.
> + *
> + * A kernel compiled with CONFIG_KASAN tends to run more slowly on average.
> + * Increase the need_resched timeout to reduce false alarms.
> + */
> +#ifdef CONFIG_KASAN
> +#define RESCHED_DEFAULT_WARN_LATENCY_MS 101
> +#define RESCHED_BOOT_QUIET_SEC 600
> +#else
> +#define RESCHED_DEFAULT_WARN_LATENCY_MS 51
> +#define RESCHED_BOOT_QUIET_SEC 300
>  #endif
> +int sysctl_resched_latency_warn_ms = RESCHED_DEFAULT_WARN_LATENCY_MS;
> +#endif /* CONFIG_SCHED_DEBUG */

I'd really just make this a single value - say 100 or 200 msecs.

> +static inline void resched_latency_warn(int cpu, u64 latency)
> +{
> +	static DEFINE_RATELIMIT_STATE(latency_check_ratelimit, 60 * 60 * HZ, 1);
> +
> +	WARN(__ratelimit(&latency_check_ratelimit),
> +	     "CPU %d: need_resched set for > %llu ns (%d ticks) "
> +	     "without schedule\n",
> +	     cpu, latency, cpu_rq(cpu)->ticks_without_resched);
> +}

Could you please put the 'sched:' prefix into scheduler warnings. 
Let's have a bit of a namespace structure in new warnings.

Thanks,

	Ingo