From 10e91c5e578fb378b53b8f8e7a3e8d1e6cf6e1f5 Mon Sep 17 00:00:00 2001 From: Pavankumar Kondeti Date: Tue, 9 Jan 2018 11:02:30 +0530 Subject: [PATCH 1/3] sched: Add trace point to track preemption disable callers Add trace point to track preemption disable callers to isolate issues unrelated to scheduler and improve debug turn around time. Change-Id: If9303b7165167e8f79cd339929daf4afc31a61c4 Signed-off-by: Pavankumar Kondeti Signed-off-by: Satya Durga Srinivasu Prabhala Signed-off-by: Lingutla Chandrasekhar --- include/linux/sched/sysctl.h | 4 ++++ include/trace/events/sched.h | 32 ++++++++++++++++++++++++++++++ kernel/sched/core.c | 38 +++++++++++++++++++++++++++++++++++- kernel/sysctl.c | 10 ++++++++++ 4 files changed, 83 insertions(+), 1 deletion(-) diff --git a/include/linux/sched/sysctl.h b/include/linux/sched/sysctl.h index ca7c8041b894..58941b90ebe4 100644 --- a/include/linux/sched/sysctl.h +++ b/include/linux/sched/sysctl.h @@ -85,6 +85,10 @@ extern unsigned int sysctl_sched_short_sleep; #endif /* CONFIG_SCHED_HMP */ +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER) +extern unsigned int sysctl_preemptoff_tracing_threshold_ns; +#endif + enum sched_tunable_scaling { SCHED_TUNABLESCALING_NONE, SCHED_TUNABLESCALING_LOG, diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h index cc0ebe6867a5..8fd96aebfdee 100644 --- a/include/trace/events/sched.h +++ b/include/trace/events/sched.h @@ -1436,6 +1436,38 @@ TRACE_EVENT(sched_isolate, __entry->time, __entry->isolate) ); +TRACE_EVENT(sched_preempt_disable, + + TP_PROTO(u64 delta, bool irqs_disabled, + unsigned long caddr0, unsigned long caddr1, + unsigned long caddr2, unsigned long caddr3), + + TP_ARGS(delta, irqs_disabled, caddr0, caddr1, caddr2, caddr3), + + TP_STRUCT__entry( + __field(u64, delta) + __field(bool, irqs_disabled) + __field(void*, caddr0) + __field(void*, caddr1) + __field(void*, caddr2) + __field(void*, caddr3) + ), + + 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; + ), + + TP_printk("delta=%llu(ns) irqs_d=%d Callers:(%pf<-%pf<-%pf<-%pf)", + __entry->delta, __entry->irqs_disabled, + __entry->caddr0, __entry->caddr1, + __entry->caddr2, __entry->caddr3) +); + TRACE_EVENT(sched_contrib_scale_f, TP_PROTO(int cpu, unsigned long freq_scale_factor, diff --git a/kernel/sched/core.c b/kernel/sched/core.c index fffc50b0191f..c1ecb07de762 100644 --- a/kernel/sched/core.c +++ b/kernel/sched/core.c @@ -3268,9 +3268,24 @@ notrace unsigned long get_parent_ip(unsigned long addr) #if defined(CONFIG_PREEMPT) && (defined(CONFIG_DEBUG_PREEMPT) || \ defined(CONFIG_PREEMPT_TRACER)) +/* + * preemptoff stack tracing threshold in ns. + * default: 1ms + */ +unsigned int sysctl_preemptoff_tracing_threshold_ns = 1000000UL; + +struct preempt_store { + u64 ts; + unsigned long caddr[4]; + bool irqs_disabled; +}; + +static DEFINE_PER_CPU(struct preempt_store, the_ps); void preempt_count_add(int val) { + struct preempt_store *ps = &per_cpu(the_ps, raw_smp_processor_id()); + #ifdef CONFIG_DEBUG_PREEMPT /* * Underflow? @@ -3291,6 +3306,13 @@ void preempt_count_add(int val) #ifdef CONFIG_DEBUG_PREEMPT current->preempt_disable_ip = ip; #endif + ps->ts = sched_clock(); + ps->caddr[0] = CALLER_ADDR0; + ps->caddr[1] = CALLER_ADDR1; + ps->caddr[2] = CALLER_ADDR2; + ps->caddr[3] = CALLER_ADDR3; + ps->irqs_disabled = irqs_disabled(); + trace_preempt_off(CALLER_ADDR0, ip); } } @@ -3313,8 +3335,22 @@ void preempt_count_sub(int val) return; #endif - if (preempt_count() == val) + if (preempt_count() == val) { + struct preempt_store *ps = &per_cpu(the_ps, + raw_smp_processor_id()); + u64 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]); + trace_preempt_on(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1)); + } __preempt_count_sub(val); } EXPORT_SYMBOL(preempt_count_sub); diff --git a/kernel/sysctl.c b/kernel/sysctl.c index bc4ca30ddc21..5ada14880707 100644 --- a/kernel/sysctl.c +++ b/kernel/sysctl.c @@ -291,6 +291,16 @@ static struct ctl_table kern_table[] = { .mode = 0644, .proc_handler = proc_dointvec, }, +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER) + { + .procname = "preemptoff_tracing_threshold_ns", + .data = &sysctl_preemptoff_tracing_threshold_ns, + .maxlen = sizeof(unsigned int), + .mode = 0644, + .proc_handler = proc_dointvec, + }, + +#endif #ifdef CONFIG_SCHED_HMP { .procname = "sched_freq_reporting_policy", From 55c9b3d14f45a276188f0cf168898d2268fd0723 Mon Sep 17 00:00:00 2001 From: Pavankumar Kondeti Date: Mon, 26 Mar 2018 16:59:43 +0530 Subject: [PATCH 2/3] trace/irq: Add trace point to track IRQs disable callers Add trace point to track IRQs disable callers to isolate issues unrelated to scheduler and improve debug turn around time. Change-Id: Ib1ef45d8bed1fc0e128b5ab2051f0c30e8c50ee7 Signed-off-by: Pavankumar Kondeti Signed-off-by: Satya Durga Srinivasu Prabhala Signed-off-by: Lingutla Chandrasekhar --- include/linux/sched/sysctl.h | 1 + include/trace/events/preemptirq.h | 28 +++++++++++++++++++++ kernel/sysctl.c | 8 +++++- kernel/trace/trace_irqsoff.c | 42 +++++++++++++++++++++++++++++++ 4 files changed, 78 insertions(+), 1 deletion(-) diff --git a/include/linux/sched/sysctl.h b/include/linux/sched/sysctl.h index 58941b90ebe4..52d5609bff8e 100644 --- a/include/linux/sched/sysctl.h +++ b/include/linux/sched/sysctl.h @@ -87,6 +87,7 @@ extern unsigned int sysctl_sched_short_sleep; #if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER) extern unsigned int sysctl_preemptoff_tracing_threshold_ns; +extern unsigned int sysctl_irqsoff_tracing_threshold_ns; #endif enum sched_tunable_scaling { diff --git a/include/trace/events/preemptirq.h b/include/trace/events/preemptirq.h index 9c4eb33c5a1d..3c5118011a2c 100644 --- a/include/trace/events/preemptirq.h +++ b/include/trace/events/preemptirq.h @@ -52,6 +52,34 @@ DEFINE_EVENT(preemptirq_template, preempt_enable, TP_ARGS(ip, parent_ip)); #endif +TRACE_EVENT(irqs_disable, + + TP_PROTO(u64 delta, unsigned long caddr0, unsigned long caddr1, + unsigned long caddr2, unsigned long caddr3), + + TP_ARGS(delta, caddr0, caddr1, caddr2, caddr3), + + TP_STRUCT__entry( + __field(u64, delta) + __field(void*, caddr0) + __field(void*, caddr1) + __field(void*, caddr2) + __field(void*, caddr3) + ), + + TP_fast_assign( + __entry->delta = delta; + __entry->caddr0 = (void *)caddr0; + __entry->caddr1 = (void *)caddr1; + __entry->caddr2 = (void *)caddr2; + __entry->caddr3 = (void *)caddr3; + ), + + TP_printk("delta=%llu(ns) Callers:(%pf<-%pf<-%pf<-%pf)", __entry->delta, + __entry->caddr0, __entry->caddr1, + __entry->caddr2, __entry->caddr3) +); + #endif /* _TRACE_PREEMPTIRQ_H */ #include diff --git a/kernel/sysctl.c b/kernel/sysctl.c index 5ada14880707..14f19af9d79a 100644 --- a/kernel/sysctl.c +++ b/kernel/sysctl.c @@ -299,7 +299,13 @@ static struct ctl_table kern_table[] = { .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_dointvec, + }, #endif #ifdef CONFIG_SCHED_HMP { diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index 21b162c07e83..c00137ea939e 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -13,6 +13,7 @@ #include #include #include +#include #include "trace.h" @@ -39,6 +40,12 @@ static int save_flags; static void stop_irqsoff_tracer(struct trace_array *tr, int graph); static int start_irqsoff_tracer(struct trace_array *tr, int graph); +/* + * irqsoff stack tracing threshold in ns. + * default: 1ms + */ +unsigned int sysctl_irqsoff_tracing_threshold_ns = 1000000UL; + #ifdef CONFIG_PREEMPT_TRACER static inline int preempt_trace(void) @@ -454,17 +461,52 @@ void time_hardirqs_off(unsigned long a0, unsigned long a1) #else /* !CONFIG_PROVE_LOCKING */ +#ifdef CONFIG_PREEMPTIRQ_EVENTS +struct irqsoff_store { + u64 ts; + unsigned long caddr[4]; +}; + +static DEFINE_PER_CPU(struct irqsoff_store, the_irqsoff); +#endif /* CONFIG_PREEMPTIRQ_EVENTS */ + /* * We are only interested in hardirq on/off events: */ static inline void tracer_hardirqs_on(void) { +#ifdef CONFIG_PREEMPTIRQ_EVENTS + struct irqsoff_store *is = &per_cpu(the_irqsoff, + raw_smp_processor_id()); + + if (!is->ts) { + is->ts = sched_clock(); + is->caddr[0] = CALLER_ADDR0; + is->caddr[1] = CALLER_ADDR1; + is->caddr[2] = CALLER_ADDR2; + is->caddr[3] = CALLER_ADDR3; + } +#endif /* CONFIG_PREEMPTIRQ_EVENTS */ if (!preempt_trace() && irq_trace()) stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); } static inline void tracer_hardirqs_off(void) { +#ifdef CONFIG_PREEMPTIRQ_EVENTS + struct irqsoff_store *is = &per_cpu(the_irqsoff, + raw_smp_processor_id()); + u64 delta = 0; + + if (is->ts) { + delta = sched_clock() - is->ts; + is->ts = 0; + } + if (delta > sysctl_irqsoff_tracing_threshold_ns) + trace_irqs_disable(delta, is->caddr[0], is->caddr[1], + is->caddr[2], is->caddr[3]); +#endif /* CONFIG_PREEMPTIRQ_EVENTS */ + if (!preempt_trace() && irq_trace()) start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); } From f8bcc90ae91d4a6465dc9cf702566e7856d5353d Mon Sep 17 00:00:00 2001 From: Lingutla Chandrasekhar Date: Mon, 23 Apr 2018 16:22:27 +0530 Subject: [PATCH 3/3] defconfig: Enable preemptirq tracing for msm8998 and sdm660 Enable preemptirq events to trace irqs/preempt disabled callers, which help to debug scheduler latency sensitive issues (ex: audio glitches). Change-Id: I0894b99ee7279cbb5b20639137e0a9b0caa1b0a9 Signed-off-by: Lingutla Chandrasekhar --- arch/arm64/configs/msmcortex_defconfig | 1 + arch/arm64/configs/sdm660_defconfig | 1 + 2 files changed, 2 insertions(+) diff --git a/arch/arm64/configs/msmcortex_defconfig b/arch/arm64/configs/msmcortex_defconfig index 039efa9a16e0..b7480335ebe7 100644 --- a/arch/arm64/configs/msmcortex_defconfig +++ b/arch/arm64/configs/msmcortex_defconfig @@ -694,6 +694,7 @@ CONFIG_IPC_LOGGING=y CONFIG_QCOM_RTB=y CONFIG_QCOM_RTB_SEPARATE_CPUS=y CONFIG_FUNCTION_TRACER=y +CONFIG_PREEMPTIRQ_EVENTS=y CONFIG_IRQSOFF_TRACER=y CONFIG_PREEMPT_TRACER=y CONFIG_BLK_DEV_IO_TRACE=y diff --git a/arch/arm64/configs/sdm660_defconfig b/arch/arm64/configs/sdm660_defconfig index bd7ec3ab3a94..e4ce70eccca9 100644 --- a/arch/arm64/configs/sdm660_defconfig +++ b/arch/arm64/configs/sdm660_defconfig @@ -695,6 +695,7 @@ CONFIG_IPC_LOGGING=y CONFIG_QCOM_RTB=y CONFIG_QCOM_RTB_SEPARATE_CPUS=y CONFIG_FUNCTION_TRACER=y +CONFIG_PREEMPTIRQ_EVENTS=y CONFIG_IRQSOFF_TRACER=y CONFIG_PREEMPT_TRACER=y CONFIG_BLK_DEV_IO_TRACE=y