Re: [PATCH v5 4/4] tracing: Histogram for delayed hrtimer offsets

[Steven Rostedt <rostedt@goodmis.org>]

[ Added Cc to hrtimer maintainer ]

On Fri,  2 Sep 2016 18:07:31 +0530
Binoy Jayan <binoy.jayan@linaro.org> 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 <binoy.jayan@linaro.org>
> ---
>  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