Merge "sched/tracing: GKI friendly long preempt/irq disable traces"

include/linux/sched/sysctl.h

@@ -82,16 +82,6 @@ extern int sched_busy_hyst_handler(struct ctl_table *table, int write,
 			void __user *buffer, size_t *lenp, loff_t *ppos);
 #endif
 
-#if defined(CONFIG_PREEMPTIRQ_EVENTS) || defined(CONFIG_PREEMPT_TRACER)
-extern unsigned int sysctl_preemptoff_tracing_threshold_ns;
-#endif
-#if defined(CONFIG_PREEMPTIRQ_EVENTS) && defined(CONFIG_IRQSOFF_TRACER)
-extern unsigned int sysctl_irqsoff_tracing_threshold_ns;
-extern unsigned int sysctl_irqsoff_dmesg_output_enabled;
-extern unsigned int sysctl_irqsoff_crash_sentinel_value;
-extern unsigned int sysctl_irqsoff_crash_threshold_ns;
-#endif
-
 enum sched_tunable_scaling {
 	SCHED_TUNABLESCALING_NONE,
 	SCHED_TUNABLESCALING_LOG,

include/trace/events/preemptirq.h

@@ -62,73 +62,6 @@ DEFINE_EVENT(preemptirq_template, preempt_enable,
 #define trace_preempt_disable_rcuidle(...)
 #endif
 
-TRACE_EVENT(irqs_disable,
-
-	TP_PROTO(u64 delta, unsigned long caddr0, unsigned long caddr1,
-				unsigned long caddr2, unsigned long caddr3,
-				unsigned long caddr4),
-
-	TP_ARGS(delta, caddr0, caddr1, caddr2, caddr3, caddr4),
-
-	TP_STRUCT__entry(
-		__field(u64, delta)
-		__field(void*, caddr0)
-		__field(void*, caddr1)
-		__field(void*, caddr2)
-		__field(void*, caddr3)
-		__field(void*, caddr4)
-	),
-
-	TP_fast_assign(
-		__entry->delta = delta;
-		__entry->caddr0 = (void *)caddr0;
-		__entry->caddr1 = (void *)caddr1;
-		__entry->caddr2 = (void *)caddr2;
-		__entry->caddr3 = (void *)caddr3;
-		__entry->caddr4 = (void *)caddr4;
-	),
-
-	TP_printk("delta=%llu(ns) Callers:(%ps<-%ps<-%ps<-%ps<-%ps)",
-					__entry->delta, __entry->caddr0,
-					__entry->caddr1, __entry->caddr2,
-					__entry->caddr3, __entry->caddr4)
-);
-
-TRACE_EVENT(sched_preempt_disable,
-
-	TP_PROTO(u64 delta, bool irqs_disabled,	unsigned long caddr0,
-			unsigned long caddr1, unsigned long caddr2,
-			unsigned long caddr3, unsigned long caddr4),
-
-	TP_ARGS(delta, irqs_disabled, caddr0, caddr1, caddr2, caddr3, caddr4),
-
-	TP_STRUCT__entry(
-		__field(u64, delta)
-		__field(bool, irqs_disabled)
-		__field(void*, caddr0)
-		__field(void*, caddr1)
-		__field(void*, caddr2)
-		__field(void*, caddr3)
-		__field(void*, caddr4)
-	),
-
-	TP_fast_assign(
-		__entry->delta = delta;
-		__entry->irqs_disabled = irqs_disabled;
-		__entry->caddr0 = (void *)caddr0;
-		__entry->caddr1 = (void *)caddr1;
-		__entry->caddr2 = (void *)caddr2;
-		__entry->caddr3 = (void *)caddr3;
-		__entry->caddr4 = (void *)caddr4;
-	),
-
-	TP_printk("delta=%llu(ns) irqs_d=%d Callers:(%ps<-%ps<-%ps<-%ps<-%ps)",
-				__entry->delta, __entry->irqs_disabled,
-				__entry->caddr0, __entry->caddr1,
-				__entry->caddr2, __entry->caddr3,
-				__entry->caddr4)
-);
-
 #endif /* _TRACE_PREEMPTIRQ_H */
 
 #include <trace/define_trace.h>

include/trace/events/preemptirq_long.h

@@ -0,0 +1,42 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Copyright (c) 2020 The Linux Foundation. All rights reserved.
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM preemptirq_long
+
+#if !defined(_TRACE_PREEMPTIRQ_LONG_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_PREEMPTIRQ_LONG_H
+
+#include <linux/tracepoint.h>
+
+DECLARE_EVENT_CLASS(preemptirq_long_template,
+
+	TP_PROTO(u64 delta),
+
+	TP_ARGS(delta),
+
+	TP_STRUCT__entry(
+		__field(u64, delta)
+	),
+
+	TP_fast_assign(
+		__entry->delta = delta;
+	),
+
+	TP_printk("delta=%llu(ns)", __entry->delta)
+);
+
+DEFINE_EVENT(preemptirq_long_template, irq_disable_long,
+	     TP_PROTO(u64 delta),
+	     TP_ARGS(delta));
+
+DEFINE_EVENT(preemptirq_long_template, preempt_disable_long,
+	     TP_PROTO(u64 delta),
+	     TP_ARGS(delta));
+
+#endif /* _TRACE_PREEMPTIRQ_LONG_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

kernel/sysctl.c

@@ -140,9 +140,6 @@ static int ten_thousand = 10000;
 #ifdef CONFIG_PERF_EVENTS
 static int six_hundred_forty_kb = 640 * 1024;
 #endif
-static unsigned int __maybe_unused half_million = 500000;
-static unsigned int __maybe_unused one_hundred_million = 100000000;
-static unsigned int __maybe_unused one_million = 1000000;
 static int __maybe_unused max_kswapd_threads = MAX_KSWAPD_THREADS;
 
 #ifdef CONFIG_SCHED_WALT
@@ -340,49 +337,6 @@ static struct ctl_table kern_table[] = {
 		.mode		= 0644,
 		.proc_handler	= proc_dointvec,
 	},
-#if defined(CONFIG_PREEMPT_TRACER) && defined(CONFIG_PREEMPTIRQ_EVENTS)
-	{
-		.procname	= "preemptoff_tracing_threshold_ns",
-		.data		= &sysctl_preemptoff_tracing_threshold_ns,
-		.maxlen		= sizeof(unsigned int),
-		.mode		= 0644,
-		.proc_handler	= proc_dointvec,
-	},
-#endif
-#if defined(CONFIG_IRQSOFF_TRACER) && defined(CONFIG_PREEMPTIRQ_EVENTS)
-	{
-		.procname	= "irqsoff_tracing_threshold_ns",
-		.data		= &sysctl_irqsoff_tracing_threshold_ns,
-		.maxlen		= sizeof(unsigned int),
-		.mode		= 0644,
-		.proc_handler	= proc_douintvec_minmax,
-		.extra1		= &half_million,
-		.extra2		= &one_hundred_million,
-	},
-	{
-		.procname	= "irqsoff_dmesg_output_enabled",
-		.data		= &sysctl_irqsoff_dmesg_output_enabled,
-		.maxlen		= sizeof(unsigned int),
-		.mode		= 0644,
-		.proc_handler	= proc_dointvec,
-	},
-	{
-		.procname	= "irqsoff_crash_sentinel_value",
-		.data		= &sysctl_irqsoff_crash_sentinel_value,
-		.maxlen		= sizeof(unsigned int),
-		.mode		= 0644,
-		.proc_handler	= proc_dointvec,
-	},
-	{
-		.procname	= "irqsoff_crash_threshold_ns",
-		.data		= &sysctl_irqsoff_crash_threshold_ns,
-		.maxlen		= sizeof(unsigned int),
-		.mode		= 0644,
-		.proc_handler	= proc_douintvec_minmax,
-		.extra1		= &one_million,
-		.extra2		= &one_hundred_million,
-	},
-#endif
 #ifdef CONFIG_SCHED_WALT
 	{
 		.procname	= "sched_user_hint",

kernel/trace/Makefile

@@ -91,3 +91,5 @@ ifdef CONFIG_DEBUG_FS
 obj-$(CONFIG_IPC_LOGGING) += ipc_logging_debug.o
 endif
 libftrace-y := ftrace.o
+
+obj-$(CONFIG_PREEMPTIRQ_TRACEPOINTS) += preemptirq_long.o

kernel/trace/preemptirq_long.c

@@ -0,0 +1,165 @@
+// SPDX-License-Identifier: GPL-2.0-only
+/*
+ * Copyright (c) 2020, The Linux Foundation. All rights reserved.
+ */
+
+#include <linux/module.h>
+#include <linux/ftrace.h>
+#include <linux/sched.h>
+#include <linux/sysctl.h>
+#include <linux/printk.h>
+#include <linux/sched/clock.h>
+
+#include <trace/events/preemptirq.h>
+#include <trace/events/sched.h>
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/preemptirq_long.h>
+
+#define IRQSOFF_SENTINEL 0x0fffDEAD
+
+static unsigned int sysctl_preemptoff_tracing_threshold_ns = 1000000;
+static unsigned int sysctl_irqsoff_tracing_threshold_ns = 5000000;
+static unsigned int sysctl_irqsoff_dmesg_output_enabled;
+static unsigned int sysctl_irqsoff_crash_sentinel_value;
+static unsigned int sysctl_irqsoff_crash_threshold_ns = 10000000;
+
+static unsigned int half_million = 500000;
+static unsigned int one_hundred_million = 100000000;
+static unsigned int one_million = 1000000;
+
+static DEFINE_PER_CPU(u64, irq_disabled_ts);
+static DEFINE_PER_CPU(u64, preempt_disabled_ts);
+
+static void note_irq_disable(void *u1, unsigned long u2, unsigned long u3)
+{
+	if (is_idle_task(current))
+		return;
+
+	/*
+	 * We just have to note down the time stamp here. We
+	 * use stacktrace trigger feature to print the stacktrace.
+	 */
+	this_cpu_write(irq_disabled_ts, sched_clock());
+}
+
+static void test_irq_disable_long(void *u1, unsigned long u2, unsigned long u3)
+{
+	u64 ts = this_cpu_read(irq_disabled_ts);
+
+	if (!ts)
+		return;
+
+	this_cpu_write(irq_disabled_ts, 0);
+	ts = sched_clock() - ts;
+
+	if (ts > sysctl_irqsoff_tracing_threshold_ns) {
+		trace_irq_disable_long(ts);
+
+		if (sysctl_irqsoff_dmesg_output_enabled == IRQSOFF_SENTINEL)
+			printk_deferred("D=%llu C:(%ps<-%ps<-%ps<-%ps)\n",
+					ts, CALLER_ADDR2, CALLER_ADDR3,
+					CALLER_ADDR4, CALLER_ADDR5);
+	}
+
+	if (sysctl_irqsoff_crash_sentinel_value == IRQSOFF_SENTINEL &&
+			ts > sysctl_irqsoff_crash_threshold_ns) {
+		printk_deferred("delta=%llu(ns) > crash_threshold=%llu(ns) Task=%s\n",
+				ts, sysctl_irqsoff_crash_threshold_ns,
+				current->comm);
+		BUG_ON(1);
+	}
+}
+
+static void note_preempt_disable(void *u1, unsigned long u2, unsigned long u3)
+{
+	this_cpu_write(preempt_disabled_ts, sched_clock());
+}
+
+static void test_preempt_disable_long(void *u1, unsigned long u2,
+				      unsigned long u3)
+{
+	u64 ts = this_cpu_read(preempt_disabled_ts);
+
+	if (!ts)
+		return;
+
+	this_cpu_write(preempt_disabled_ts, 0);
+	ts = sched_clock() - ts;
+
+	if (ts > sysctl_preemptoff_tracing_threshold_ns)
+		trace_preempt_disable_long(ts);
+}
+
+static void note_context_switch(void *u1, bool u2, struct task_struct *u3,
+				struct task_struct *next)
+{
+	/*
+	 * Discard false positives during context switch to idle.
+	 */
+	if (is_idle_task(next))
+		this_cpu_write(preempt_disabled_ts, 0);
+}
+
+static struct ctl_table preemptirq_long_table[] = {
+	{
+		.procname       = "preemptoff_tracing_threshold_ns",
+		.data           = &sysctl_preemptoff_tracing_threshold_ns,
+		.maxlen         = sizeof(unsigned int),
+		.mode           = 0644,
+		.proc_handler   = proc_dointvec,
+	},
+	{
+		.procname	= "irqsoff_tracing_threshold_ns",
+		.data		= &sysctl_irqsoff_tracing_threshold_ns,
+		.maxlen		= sizeof(unsigned int),
+		.mode		= 0644,
+		.proc_handler	= proc_douintvec_minmax,
+		.extra1		= &half_million,
+		.extra2		= &one_hundred_million,
+	},
+	{
+		.procname	= "irqsoff_dmesg_output_enabled",
+		.data		= &sysctl_irqsoff_dmesg_output_enabled,
+		.maxlen		= sizeof(unsigned int),
+		.mode		= 0644,
+		.proc_handler	= proc_dointvec,
+	},
+	{
+		.procname	= "irqsoff_crash_sentinel_value",
+		.data		= &sysctl_irqsoff_crash_sentinel_value,
+		.maxlen		= sizeof(unsigned int),
+		.mode		= 0644,
+		.proc_handler	= proc_dointvec,
+	},
+	{
+		.procname	= "irqsoff_crash_threshold_ns",
+		.data		= &sysctl_irqsoff_crash_threshold_ns,
+		.maxlen		= sizeof(unsigned int),
+		.mode		= 0644,
+		.proc_handler	= proc_douintvec_minmax,
+		.extra1		= &one_million,
+		.extra2		= &one_hundred_million,
+	},
+	{ }
+};
+
+static int preemptirq_long_init(void)
+{
+	if (!register_sysctl("preemptirq", preemptirq_long_table)) {
+		pr_err("Fail to register sysctl table\n");
+		return -EPERM;
+	}
+
+	register_trace_irq_disable(note_irq_disable, NULL);
+	register_trace_irq_enable(test_irq_disable_long, NULL);
+
+	register_trace_preempt_disable(note_preempt_disable, NULL);
+	register_trace_preempt_enable(test_preempt_disable_long, NULL);
+
+	register_trace_sched_switch(note_context_switch, NULL);
+	return 0;
+}
+
+module_init(preemptirq_long_init);
+MODULE_LICENSE("GPL v2");

kernel/trace/trace_irqsoff.c

@@ -607,70 +607,12 @@ static void irqsoff_tracer_stop(struct trace_array *tr)
 }
 
 #ifdef CONFIG_IRQSOFF_TRACER
-#ifdef CONFIG_PREEMPTIRQ_EVENTS
-#define IRQSOFF_SENTINEL 0x0fffDEAD
-/*
- * irqsoff stack tracing threshold in ns.
- * default: 5ms
- */
-unsigned int sysctl_irqsoff_tracing_threshold_ns = 5000000UL;
-/*
- * Enable irqsoff tracing to dmesg
- */
-unsigned int sysctl_irqsoff_dmesg_output_enabled;
-/*
- * Sentinel value to prevent unnecessary irqsoff crash
- */
-unsigned int sysctl_irqsoff_crash_sentinel_value;
-/*
- * Irqsoff warning threshold to trigger crash
- */
-unsigned int sysctl_irqsoff_crash_threshold_ns = 10000000UL;
-
-struct irqsoff_store {
-	u64 ts;
-	unsigned long caddr[5];
-};
-
-static DEFINE_PER_CPU(struct irqsoff_store, the_irqsoff);
-#endif /* CONFIG_PREEMPTIRQ_EVENTS */
-
 /*
  * We are only interested in hardirq on/off events:
  */
 void tracer_hardirqs_on(unsigned long a0, unsigned long a1)
 {
 	unsigned int pc = preempt_count();
-#ifdef CONFIG_PREEMPTIRQ_EVENTS
-	struct irqsoff_store *is;
-	u64 delta;
-
-	lockdep_off();
-	is = &per_cpu(the_irqsoff, raw_smp_processor_id());
-	delta = sched_clock() - is->ts;
-
-	if (!is_idle_task(current) &&
-			delta > sysctl_irqsoff_tracing_threshold_ns) {
-		trace_irqs_disable(delta, is->caddr[0], is->caddr[1],
-					is->caddr[2], is->caddr[3],
-					is->caddr[4]);
-		if (sysctl_irqsoff_dmesg_output_enabled == IRQSOFF_SENTINEL)
-			printk_deferred(KERN_ERR "D=%llu C:(%ps<-%ps<-%ps<-%ps)\n",
-				delta, is->caddr[0], is->caddr[1],
-					is->caddr[2], is->caddr[3]);
-		if (sysctl_irqsoff_crash_sentinel_value == IRQSOFF_SENTINEL &&
-			delta > sysctl_irqsoff_crash_threshold_ns) {
-			printk_deferred(KERN_ERR
-			"delta=%llu(ns) > crash_threshold=%llu(ns) Task=%s\n",
-				delta, sysctl_irqsoff_crash_threshold_ns,
-					current->comm);
-			BUG_ON(1);
-		}
-	}
-
-	is->ts = 0;
-	lockdep_on();
-#endif /* CONFIG_PREEMPTIRQ_EVENTS */
 
 	if (!preempt_trace(pc) && irq_trace())
 		stop_critical_timing(a0, a1, pc);
@@ -680,19 +622,6 @@ NOKPROBE_SYMBOL(tracer_hardirqs_on);
 void tracer_hardirqs_off(unsigned long a0, unsigned long a1)
 {
 	unsigned int pc = preempt_count();
-#ifdef CONFIG_PREEMPTIRQ_EVENTS
-	struct irqsoff_store *is;
-
-	lockdep_off();
-	is = &per_cpu(the_irqsoff, raw_smp_processor_id());
-	is->ts = sched_clock();
-	is->caddr[0] = CALLER_ADDR1;
-	is->caddr[1] = CALLER_ADDR2;
-	is->caddr[2] = CALLER_ADDR3;
-	is->caddr[3] = CALLER_ADDR4;
-	is->caddr[4] = CALLER_ADDR5;
-	lockdep_on();
-#endif /* CONFIG_PREEMPTIRQ_EVENTS */
 
 	if (!preempt_trace(pc) && irq_trace())
 		start_critical_timing(a0, a1, pc);
@@ -733,57 +662,9 @@ static struct tracer irqsoff_tracer __read_mostly =
 #endif /*  CONFIG_IRQSOFF_TRACER */
 
 #ifdef CONFIG_PREEMPT_TRACER
-#ifdef CONFIG_PREEMPTIRQ_EVENTS
-/*
- * preemptoff stack tracing threshold in ns.
- * default: 1ms
- */
-unsigned int sysctl_preemptoff_tracing_threshold_ns = 1000000UL;
-
-struct preempt_store {
-	u64 ts;
-	unsigned long caddr[5];
-	bool irqs_disabled;
-	int pid;
-	unsigned long ncsw;
-};
-
-static DEFINE_PER_CPU(struct preempt_store, the_ps);
-#endif /* CONFIG_PREEMPTIRQ_EVENTS */
-
 void tracer_preempt_on(unsigned long a0, unsigned long a1)
 {
 	int pc = preempt_count();
-#ifdef CONFIG_PREEMPTIRQ_EVENTS
-	struct preempt_store *ps;
-	u64 delta = 0;
-
-	lockdep_off();
-	ps = &per_cpu(the_ps, raw_smp_processor_id());
-
-	/*
-	 * schedule() calls __schedule() with preemption disabled.
-	 * if we had entered idle and exiting idle now, we think
-	 * preemption is disabled the whole time. Detect this by
-	 * checking if the preemption is disabled across the same
-	 * task. There is a possiblity that the same task is scheduled
-	 * after idle. To rule out this possibility, compare the
-	 * context switch count also.
-	 */
-	if (ps->ts && ps->pid == current->pid && (ps->ncsw ==
-			current->nvcsw + current->nivcsw))
-		delta = sched_clock() - ps->ts;
-	/*
-	 * Trace preempt disable stack if preemption
-	 * is disabled for more than the threshold.
-	 */
-	if (delta > sysctl_preemptoff_tracing_threshold_ns)
-		trace_sched_preempt_disable(delta, ps->irqs_disabled,
-				ps->caddr[0], ps->caddr[1],
-				ps->caddr[2], ps->caddr[3], ps->caddr[4]);
-	ps->ts = 0;
-	lockdep_on();
-#endif /* CONFIG_PREEMPTIRQ_EVENTS */
 
 	if (preempt_trace(pc) && !irq_trace())
 		stop_critical_timing(a0, a1, pc);
@@ -792,22 +673,6 @@ void tracer_preempt_on(unsigned long a0, unsigned long a1)
 void tracer_preempt_off(unsigned long a0, unsigned long a1)
 {
 	int pc = preempt_count();
-#ifdef CONFIG_PREEMPTIRQ_EVENTS
-	struct preempt_store *ps;
-
-	lockdep_off();
-	ps = &per_cpu(the_ps, raw_smp_processor_id());
-	ps->ts = sched_clock();
-	ps->caddr[0] = CALLER_ADDR1;
-	ps->caddr[1] = CALLER_ADDR2;
-	ps->caddr[2] = CALLER_ADDR3;
-	ps->caddr[3] = CALLER_ADDR4;
-	ps->caddr[4] = CALLER_ADDR5;
-	ps->irqs_disabled = irqs_disabled();
-	ps->pid = current->pid;
-	ps->ncsw = current->nvcsw + current->nivcsw;
-	lockdep_on();
-#endif /* CONFIG_PREEMPTIRQ_EVENTS */
 
 	if (preempt_trace(pc) && !irq_trace())
 		start_critical_timing(a0, a1, pc);