From fcecef89e5b73dee593515e815e02382d8c67e2a Mon Sep 17 00:00:00 2001 From: Pavankumar Kondeti Date: Thu, 23 Jul 2020 10:31:16 +0530 Subject: [PATCH 1/2] tracing/sched: Clean up preemptoff/irqsoff extensions preemptoff/irqsoff tracers are extended to print call stack, when preemption/irqs are disabled more than a threshold. The subsequent patches brings the same functionality in a GKI friendly manner. So, clean up the existing code that does this. Change-Id: Id86c298d3a044f7c7e99170ea74f79adbe6786a4 Signed-off-by: Pavankumar Kondeti --- include/linux/sched/sysctl.h | 10 --- include/trace/events/preemptirq.h | 67 --------------- kernel/sysctl.c | 46 ---------- kernel/trace/trace_irqsoff.c | 135 ------------------------------ 4 files changed, 258 deletions(-) diff --git a/include/linux/sched/sysctl.h b/include/linux/sched/sysctl.h index d288478995f4..cd531a27bdf1 100644 --- a/include/linux/sched/sysctl.h +++ b/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, diff --git a/include/trace/events/preemptirq.h b/include/trace/events/preemptirq.h index 4d8a539fce93..3f249e150c0c 100644 --- a/include/trace/events/preemptirq.h +++ b/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 diff --git a/kernel/sysctl.c b/kernel/sysctl.c index 4ad247e545ec..ea162a9eb555 100644 --- a/kernel/sysctl.c +++ b/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", diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index f30ef80c9876..f61b23500da1 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/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); From 1f833081fb40a4b9849f096b1503ca69b2e0b195 Mon Sep 17 00:00:00 2001 From: Pavankumar Kondeti Date: Wed, 8 Jul 2020 18:47:54 +0530 Subject: [PATCH 2/2] sched/tracing: GKI friendly long preempt/irq disable traces Hook into preemptirq trace points and print the call stacks of scenarios where preemption/irqs is disabled for more than a use configured threshold. The threshold tunables are available under /proc/sys/preemptirq directory. All the units are in nano seconds. The following commands can be used to enable the trace. The stacktrace trigger prints the stacktrace when the trace event is printed. echo 1 > /d/tracing/events/preemptirq_long/enable echo stacktrace > /d/tracing/events/preemptirq_long/preempt_disable_long/trigger echo stacktrace > /d/tracing/events/preemptirq_long/irq_disable_long/trigger Sample output is copied below. Note that this format works with both systrace and commandline ftrace utilities. init-1 [005] d..2 187.905211: irq_disable_long: delta=15244480(ns) init-1 [005] d..3 187.905216: => test_irq_disable_long => trace_irq_enable_rcuidle => trace_hardirqs_on => console_unlock => vprintk_emit => devkmsg_emit => devkmsg_write => do_iter_readv_writev => do_iter_write => do_writev => __arm64_sys_writev => el0_svc_common => el0_svc_handler => el0_svc kworker/u16:4-419 [000] .N.2 187.905221: preempt_disable_long: delta=4923646(ns) kworker/u16:4-419 [000] .N.3 187.905226: => test_preempt_disable_long => trace_preempt_enable_rcuidle => trace_preempt_on => preempt_count_sub => perf_event_read => __perf_event_read_value => perf_event_read_value => memlat_monitor_work => process_one_work => worker_thread => kthread => ret_from_fork Change-Id: If87a8d65359632b93da10b691e9b83e37000aeb3 Signed-off-by: Pavankumar Kondeti --- include/trace/events/preemptirq_long.h | 42 +++++++ kernel/trace/Makefile | 2 + kernel/trace/preemptirq_long.c | 165 +++++++++++++++++++++++++ 3 files changed, 209 insertions(+) create mode 100644 include/trace/events/preemptirq_long.h create mode 100644 kernel/trace/preemptirq_long.c diff --git a/include/trace/events/preemptirq_long.h b/include/trace/events/preemptirq_long.h new file mode 100644 index 000000000000..fa5d27cc8e8a --- /dev/null +++ b/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 + +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 diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile index b04b40bec355..f9f4512c617d 100644 --- a/kernel/trace/Makefile +++ b/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 diff --git a/kernel/trace/preemptirq_long.c b/kernel/trace/preemptirq_long.c new file mode 100644 index 000000000000..6fa3df7a93c4 --- /dev/null +++ b/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 +#include +#include +#include +#include +#include + +#include +#include + +#define CREATE_TRACE_POINTS +#include + +#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");