[ Added Cc to hrtimer maintainer ] On Fri, 2 Sep 2016 18:07:31 +0530 Binoy Jayan <[email protected]> wrote:
> Generate a histogram of the latencies of delayed timer offsets in > nanoseconds. It shows the latency captured due to a delayed timer expire > event. It happens for example when a timer misses its deadline due to > disabled interrupts. A process if scheduled as a result of the timer > expiration suffers this latency. > > The following filter(s) may be used > > 'hist:key=common_pid.execname:val=toffset,hitcount' > 'hist:key=cpu,tcomm:val=toffset:sort=tcomm' > 'hist:key=common_pid.execname,tcomm' > > Signed-off-by: Binoy Jayan <[email protected]> > --- > include/linux/hrtimer.h | 3 +++ > include/trace/events/latency.h | 23 +++++++++++++++++++++ > kernel/time/hrtimer.c | 46 > ++++++++++++++++++++++++++++++++++++++++++ > 3 files changed, 72 insertions(+) > > diff --git a/include/linux/hrtimer.h b/include/linux/hrtimer.h > index 5e00f80..e09de14 100644 > --- a/include/linux/hrtimer.h > +++ b/include/linux/hrtimer.h > @@ -104,6 +104,9 @@ struct hrtimer { > struct hrtimer_clock_base *base; > u8 state; > u8 is_rel; > +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER) > + ktime_t praecox; > +#endif > #ifdef CONFIG_TIMER_STATS > int start_pid; > void *start_site; > diff --git a/include/trace/events/latency.h b/include/trace/events/latency.h > index ca57f06..d616db5 100644 > --- a/include/trace/events/latency.h > +++ b/include/trace/events/latency.h > @@ -44,6 +44,29 @@ DEFINE_EVENT(latency_template, latency_preempt, > TP_PROTO(int ltype, cycles_t latency), > TP_ARGS(ltype, latency)); > > +TRACE_EVENT(latency_hrtimer_interrupt, > + > + TP_PROTO(long long toffset, struct task_struct *task), > + > + TP_ARGS(toffset, task), > + > + TP_STRUCT__entry( > + __field(long long, toffset) > + __array(char, tcomm, TASK_COMM_LEN) > + __field(int, tprio) > + ), > + > + TP_fast_assign( > + __entry->toffset = toffset; > + memcpy(__entry->tcomm, task != NULL ? task->comm : "<none>", > + task != NULL ? TASK_COMM_LEN : 7); > + __entry->tprio = task != NULL ? task->prio : -1; > + ), > + > + TP_printk("toffset=%lld thread=%s[%d]", > + __entry->toffset, __entry->tcomm, __entry->tprio) > +); This probably should be added into the hrtimer interrupt tracepoints and not off in some special tracepoint header. > + > #endif /* _TRACE_HIST_H */ > > /* This part must be outside protection */ > diff --git a/kernel/time/hrtimer.c b/kernel/time/hrtimer.c > index 9ba7c82..04d936b 100644 > --- a/kernel/time/hrtimer.c > +++ b/kernel/time/hrtimer.c > @@ -53,9 +53,12 @@ > #include <asm/uaccess.h> > > #include <trace/events/timer.h> > +#include <trace/events/latency.h> > > #include "tick-internal.h" > > +static enum hrtimer_restart hrtimer_wakeup(struct hrtimer *timer); > + > /* > * The timer bases: > * > @@ -960,6 +963,45 @@ static inline ktime_t hrtimer_update_lowres(struct > hrtimer *timer, ktime_t tim, > return tim; > } > > +static inline void latency_hrtimer_timing_start(struct hrtimer *timer, > + struct hrtimer_clock_base *new_base, > + ktime_t tim) > +{ > +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER) The ideal approach to #ifdefs like this, is not to add them in side each function, as it is confusing to understand, but simply have one: #if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER) static inline void latency_hrtimer_timing_start(..) { > + if (unlikely(trace_latency_hrtimer_interrupt_enabled())) { > + ktime_t now = new_base->get_time(); > + > + if (ktime_to_ns(tim) < ktime_to_ns(now)) > + timer->praecox = now; > + else > + timer->praecox = ktime_set(0, 0); > + } } static inline void latency_hrtimer_timing_stop(..) { [...] } #else static inline void latency_hrtimer_timing_start(..) { } static inline void latency_hrtimer_timing_stop(..) { } #endif But something like this patch is going to need Thomas's approval. -- Steve > +#endif > +} > + > +static inline void latency_hrtimer_timing_stop(struct hrtimer *timer, > + ktime_t basenow) > +{ > +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER) > + long latency; > + > + struct task_struct *task; > + > + if (likely(!trace_latency_hrtimer_interrupt_enabled())) > + return; > + > + latency = ktime_to_ns(ktime_sub(basenow, > + ktime_to_ns(timer->praecox) ? > + timer->praecox : hrtimer_get_expires(timer))); > + > + task = timer->function == hrtimer_wakeup ? > + container_of(timer, struct hrtimer_sleeper, > + timer)->task : NULL; > + if (latency > 0) > + trace_latency_hrtimer_interrupt((u64) latency, task); > +#endif > +} > + > /** > * hrtimer_start_range_ns - (re)start an hrtimer on the current CPU > * @timer: the timer to be added > @@ -992,6 +1034,8 @@ void hrtimer_start_range_ns(struct hrtimer *timer, > ktime_t tim, > > timer_stats_hrtimer_set_start_info(timer); > > + latency_hrtimer_timing_start(timer, new_base, tim); > + > leftmost = enqueue_hrtimer(timer, new_base); > if (!leftmost) > goto unlock; > @@ -1284,6 +1328,8 @@ static void __hrtimer_run_queues(struct > hrtimer_cpu_base *cpu_base, ktime_t now) > > timer = container_of(node, struct hrtimer, node); > > + latency_hrtimer_timing_stop(timer, basenow); > + > /* > * The immediate goal for using the softexpires is > * minimizing wakeups, not running timers at the
