sched: warn/panic upon excessive scheduling latency

Add new tunables /proc/sys/kernel/sched_latency_warn_threshold_us and
/proc/sys/kernel/sched_latency_panic_threshold_us to warn or panic for the
cases that tasks are runnable but not scheduled more than configured time.

This helps to find out unacceptably high scheduling latency more easily.

Change-Id: If077aba6211062cf26ee289970c5abcd1c218c82
[joonwoop@codeaurora.org: fixed conflict in update_stats_wait_end().]
Signed-off-by: Joonwoo Park <joonwoop@codeaurora.org>

4 files changed, 56 insertions, 0 deletions

diff --git a/Documentation/scheduler/sched-stats.txt b/Documentation/scheduler/sched-stats.txt
index 8259b34a66ae..30635c5ac2f5 100644
--- a/Documentation/scheduler/sched-stats.txt
+++ b/Documentation/scheduler/sched-stats.txt
@@ -147,6 +147,15 @@ this file correlating for that process to:
      2) time spent waiting on a runqueue
      3) # of timeslices run on this cpu
 
+/proc/sys/kernel/{sched_latency_warn_threshold_us,sched_latency_panic_threshold_us}
+----------------
+schedstats provides procfs nodes /proc/sys/kernel/sched_latency_warn_threshold_us
+and /proc/sys/kernel/sched_latency_panic_threshold_us.  These can be configured
+to detect unreasonably high scheduling latency.
+Set sched_latency_warn_threshold_us or sched_latency_panic_threshold_us with
+non-zero threshold to warn or panic system when scheduling latency higher than
+configured threshold is detected.  Default is 0 (disabled) for both.
+
 A program could be easily written to make use of these extra fields to
 report on how well a particular process or set of processes is faring
 under the scheduler's policies.  A simple version of such a program is
diff --git a/include/linux/sched/sysctl.h b/include/linux/sched/sysctl.h
index ce23dcd70b98..fdb75cab5243 100644
--- a/include/linux/sched/sysctl.h
+++ b/include/linux/sched/sysctl.h
@@ -129,6 +129,11 @@ extern unsigned int sysctl_sched_cfs_bandwidth_slice;
 extern unsigned int sysctl_sched_autogroup_enabled;
 #endif
 
+#ifdef CONFIG_SCHEDSTATS
+extern unsigned int sysctl_sched_latency_panic_threshold;
+extern unsigned int sysctl_sched_latency_warn_threshold;
+#endif
+
 extern int sched_rr_timeslice;
 
 extern int sched_rr_handler(struct ctl_table *table, int write,
diff --git a/kernel/sched/fair.c b/kernel/sched/fair.c
index 98740228ed32..1da6091b54f3 100644
--- a/kernel/sched/fair.c
+++ b/kernel/sched/fair.c
@@ -30,6 +30,7 @@
 #include <linux/mempolicy.h>
 #include <linux/migrate.h>
 #include <linux/task_work.h>
+#include <linux/ratelimit.h>
 
 #include <trace/events/sched.h>
 
@@ -122,6 +123,11 @@ unsigned int __read_mostly sysctl_sched_shares_window = 10000000UL;
 unsigned int sysctl_sched_cfs_bandwidth_slice = 5000UL;
 #endif
 
+#ifdef CONFIG_SCHEDSTATS
+unsigned int sysctl_sched_latency_panic_threshold;
+unsigned int sysctl_sched_latency_warn_threshold;
+#endif /* CONFIG_SCHEDSTATS */
+
 static inline void update_load_add(struct load_weight *lw, unsigned long inc)
 {
 	lw->weight += inc;
@@ -750,6 +756,25 @@ static void update_curr_fair(struct rq *rq)
 }
 
 #ifdef CONFIG_SCHEDSTATS
+static inline void check_for_high_latency(struct task_struct *p, u64 latency_us)
+{
+	int do_warn, do_panic;
+	const char *fmt = "excessive latency comm=%s pid=%d latency=%llu(us)\n";
+	static DEFINE_RATELIMIT_STATE(rs, DEFAULT_RATELIMIT_INTERVAL,
+				      DEFAULT_RATELIMIT_BURST);
+
+	do_warn = (sysctl_sched_latency_warn_threshold &&
+		   latency_us > sysctl_sched_latency_warn_threshold);
+	do_panic = (sysctl_sched_latency_panic_threshold &&
+		    latency_us > sysctl_sched_latency_panic_threshold);
+	if (unlikely(do_panic || (do_warn && __ratelimit(&rs)))) {
+		if (do_panic)
+			panic(fmt, p->comm, p->pid, latency_us);
+		else
+			printk_deferred(fmt, p->comm, p->pid, latency_us);
+	}
+}
+
 static inline void
 update_stats_wait_start(struct cfs_rq *cfs_rq, struct sched_entity *se)
 {
@@ -780,6 +805,7 @@ update_stats_wait_end(struct cfs_rq *cfs_rq, struct sched_entity *se)
 			return;
 		}
 		trace_sched_stat_wait(p, delta);
+		check_for_high_latency(p, delta >> 10);
 	}
 
 	se->statistics.wait_max = max(se->statistics.wait_max, delta);
diff --git a/kernel/sysctl.c b/kernel/sysctl.c
index 16e465103020..188c7fabeec0 100644
--- a/kernel/sysctl.c
+++ b/kernel/sysctl.c
@@ -593,6 +593,22 @@ static struct ctl_table kern_table[] = {
 		.extra1		= &one,
 	},
 #endif
+#ifdef CONFIG_SCHEDSTATS
+	{
+		.procname	= "sched_latency_panic_threshold_us",
+		.data		= &sysctl_sched_latency_panic_threshold,
+		.maxlen		= sizeof(unsigned int),
+		.mode		= 0644,
+		.proc_handler	= proc_dointvec_minmax,
+	},
+	{
+		.procname	= "sched_latency_warn_threshold_us",
+		.data		= &sysctl_sched_latency_warn_threshold,
+		.maxlen		= sizeof(unsigned int),
+		.mode		= 0644,
+		.proc_handler	= proc_dointvec_minmax,
+	},
+#endif
 #ifdef CONFIG_PROVE_LOCKING
 	{
 		.procname	= "prove_locking",