From 9ef4c50bb2a346ddd0de7017c532b767f7ed0933 Mon Sep 17 00:00:00 2001 From: Satya Durga Srinivasu Prabhala Date: Thu, 15 Nov 2018 14:15:35 -0800 Subject: [PATCH] sched: Add snapshot of preemption and IRQs disable callers This snapshot is taken from msm-4.19 as of commit 72395648aa0ad18 ("sched: core: Fix usage of cpu core group mask"). Change-Id: I8dc6933a1e3a0835f19c7802930f974d442082a8 Signed-off-by: Satya Durga Srinivasu Prabhala --- include/linux/sched/sysctl.h | 7 ++++ include/trace/events/preemptirq.h | 28 ++++++++++++++++ include/trace/events/sched.h | 32 ++++++++++++++++++ kernel/sched/core.c | 55 ++++++++++++++++++++++++++++++- kernel/sysctl.c | 18 ++++++++++ kernel/trace/trace_irqsoff.c | 44 +++++++++++++++++++++++++ 6 files changed, 183 insertions(+), 1 deletion(-) diff --git a/include/linux/sched/sysctl.h b/include/linux/sched/sysctl.h index d66f20a74d77..fbd4bddfc73e 100644 --- a/include/linux/sched/sysctl.h +++ b/include/linux/sched/sysctl.h @@ -72,6 +72,13 @@ sched_ravg_window_handler(struct ctl_table *table, int write, loff_t *ppos); #endif +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_DEBUG_PREEMPT) +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; +#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 95fba0471e5b..83bca4dc6334 100644 --- a/include/trace/events/preemptirq.h +++ b/include/trace/events/preemptirq.h @@ -62,6 +62,34 @@ 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), + + 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:(%ps<-%ps<-%ps<-%ps)", __entry->delta, + __entry->caddr0, __entry->caddr1, + __entry->caddr2, __entry->caddr3) +); + #endif /* _TRACE_PREEMPTIRQ_H */ #include diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h index 6a4eeafd7797..1d34555cbedc 100644 --- a/include/trace/events/sched.h +++ b/include/trace/events/sched.h @@ -671,6 +671,38 @@ DECLARE_TRACE(sched_overutilized_tp, TP_PROTO(struct root_domain *rd, bool overutilized), TP_ARGS(rd, overutilized)); +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:(%ps<-%ps<-%ps<-%ps)", + __entry->delta, __entry->irqs_disabled, + __entry->caddr0, __entry->caddr1, + __entry->caddr2, __entry->caddr3) +); + #endif /* _TRACE_SCHED_H */ /* This part must be outside protection */ diff --git a/kernel/sched/core.c b/kernel/sched/core.c index 4af0bd4d1524..1b82d2f7bcf0 100644 --- a/kernel/sched/core.c +++ b/kernel/sched/core.c @@ -3847,17 +3847,55 @@ static inline void sched_tick_stop(int cpu) { } #if defined(CONFIG_PREEMPTION) && (defined(CONFIG_DEBUG_PREEMPT) || \ defined(CONFIG_TRACE_PREEMPT_TOGGLE)) +/* + * 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; +}; + +DEFINE_PER_CPU(struct preempt_store, the_ps); + +/* + * This is only called from __schedule() upon context switch. + * + * schedule() calls __schedule() with preemption disabled. + * if we had entered idle and exiting idle now, reset the preemption + * tracking otherwise we may think preemption is disabled the whole time + * when the non idle task re-enables the preemption in schedule(). + */ +static inline void preempt_latency_reset(void) +{ + if (is_idle_task(this_rq()->curr)) + this_cpu_ptr(&the_ps)->ts = 0; +} + /* * If the value passed in is equal to the current preempt count * then we just disabled preemption. Start timing the latency. */ static inline void preempt_latency_start(int val) { + int cpu = raw_smp_processor_id(); + struct preempt_store *ps = &per_cpu(the_ps, cpu); + if (preempt_count() == val) { unsigned long ip = get_lock_parent_ip(); #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); } } @@ -3890,8 +3928,21 @@ NOKPROBE_SYMBOL(preempt_count_add); */ static inline void preempt_latency_stop(int val) { - if (preempt_count() == val) + if (preempt_count() == val) { + struct preempt_store *ps = &per_cpu(the_ps, + raw_smp_processor_id()); + u64 delta = ps->ts ? (sched_clock() - ps->ts) : 0; + + /* + * 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_lock_parent_ip()); + } } void preempt_count_sub(int val) @@ -3919,6 +3970,7 @@ NOKPROBE_SYMBOL(preempt_count_sub); #else static inline void preempt_latency_start(int val) { } static inline void preempt_latency_stop(int val) { } +static inline void preempt_latency_reset(void) { } #endif static inline unsigned long get_preempt_disable_ip(struct task_struct *p) @@ -4153,6 +4205,7 @@ static void __sched notrace __schedule(bool preempt) prev->last_sleep_ts = wallclock; #endif + preempt_latency_reset(); walt_update_task_ravg(prev, rq, PUT_PREV_TASK, wallclock, 0); walt_update_task_ravg(next, rq, PICK_NEXT_TASK, wallclock, 0); rq->nr_switches++; diff --git a/kernel/sysctl.c b/kernel/sysctl.c index db4732e80428..9b3f21eb5c41 100644 --- a/kernel/sysctl.c +++ b/kernel/sysctl.c @@ -339,6 +339,24 @@ static struct ctl_table kern_table[] = { .mode = 0644, .proc_handler = proc_dointvec, }, +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_DEBUG_PREEMPT) + { + .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_dointvec, + }, +#endif #ifdef CONFIG_SCHED_WALT { .procname = "sched_user_hint", diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index a745b0cee5d3..fc002732c38c 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -15,6 +15,9 @@ #include #include #include +#include +#include +#include #include "trace.h" @@ -604,12 +607,41 @@ static void irqsoff_tracer_stop(struct trace_array *tr) } #ifdef CONFIG_IRQSOFF_TRACER +#ifdef CONFIG_PREEMPTIRQ_EVENTS +/* + * irqsoff stack tracing threshold in ns. + * default: 1ms + */ +unsigned int sysctl_irqsoff_tracing_threshold_ns = 1000000UL; + +struct irqsoff_store { + u64 ts; + unsigned long caddr[4]; +}; + +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]); + lockdep_on(); +#endif /* CONFIG_PREEMPTIRQ_EVENTS */ if (!preempt_trace(pc) && irq_trace()) stop_critical_timing(a0, a1, pc); @@ -619,6 +651,18 @@ 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_ADDR0; + is->caddr[1] = CALLER_ADDR1; + is->caddr[2] = CALLER_ADDR2; + is->caddr[3] = CALLER_ADDR3; + lockdep_on(); +#endif /* CONFIG_PREEMPTIRQ_EVENTS */ if (!preempt_trace(pc) && irq_trace()) start_critical_timing(a0, a1, pc);