Hi Binoy,
2016-08-30 19:28 GMT+09:00 Binoy Jayan <binoy.ja...@linaro.org>:
> Latencies of missed timer offsets. Generate a histogram of missed
> timer offsets in microseconds. This will be a based along with irq
> and preemption latencies to calculate the effective process wakeup
> latencies.
>
> The following filter(s) may be used
>
> 'hist:key=common_pid.execname'
> 'hist:key=common_pid.execname:val=toffset,hitcount'
>
> Signed-off-by: Binoy Jayan <binoy.ja...@linaro.org>
> ---
> include/linux/hrtimer.h | 3 +++
> include/trace/events/latency.h | 29 +++++++++++++++++++++++++++++
> kernel/time/hrtimer.c | 40 ++++++++++++++++++++++++++++++++++++++++
> 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 e89be12..7fca7cd 100644
> --- a/include/trace/events/latency.h
> +++ b/include/trace/events/latency.h
> @@ -29,6 +29,35 @@ 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 *curr,
> + struct task_struct *task),
> +
> + TP_ARGS(toffset, curr, task),
> +
> + TP_STRUCT__entry(
> + __field(long long, toffset)
> + __array(char, ccomm, TASK_COMM_LEN)
> + __field(int, cprio)
> + __array(char, tcomm, TASK_COMM_LEN)
> + __field(int, tprio)
> + ),
> +
> + TP_fast_assign(
> + __entry->toffset = toffset;
> + memcpy(__entry->ccomm, curr->comm, TASK_COMM_LEN);
> + __entry->cprio = curr->prio;
> + 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 curr=%s[%d] thread=%s[%d]",
> + __entry->toffset, __entry->ccomm, __entry->cprio,
> + __entry->tcomm, __entry->tprio)
> +);
> +
> #endif /* _TRACE_HIST_H */
>
> /* This part must be outside protection */
> diff --git a/kernel/time/hrtimer.c b/kernel/time/hrtimer.c
> index 9ba7c82..f3e1d92 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,39 @@ static inline ktime_t hrtimer_update_lowres(struct
> hrtimer *timer, ktime_t tim,
> return tim;
> }
>
> +static inline void trace_latency_hrtimer_mark_ts(struct hrtimer *timer,
> + struct hrtimer_clock_base *new_base,
> + ktime_t tim)
> +{
> +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER)
> + if (trace_latency_hrtimer_interrupt_enabled()) {
You would better use unlikely() here.
> + ktime_t now = new_base->get_time();
> +
> + if (ktime_to_ns(tim) < ktime_to_ns(now))
Wouldn't we need to consider the case of wrap around?
> + timer->praecox = now;
> + else
> + timer->praecox = ktime_set(0, 0);
> + }
> +#endif
> +}
> +
> +static inline void trace_latency_missed_hrtimer(struct hrtimer *timer,
> + ktime_t basenow)
> +{
> +#if defined(CONFIG_PREEMPT_TRACER) || defined(CONFIG_IRQSOFF_TRACER)
> + if (trace_latency_hrtimer_interrupt_enabled())
Here, you'd better add unlikely() too.
> + trace_latency_hrtimer_interrupt(
> + ktime_to_ns(ktime_sub(ktime_to_ns(timer->praecox) ?
> + timer->praecox : hrtimer_get_expires(timer),
> + basenow)),
> + current,
> + timer->function == hrtimer_wakeup ?
> + container_of(timer, struct hrtimer_sleeper,
> + timer)->task : NULL);
> +#endif
> +
> +}
> +
> /**
> * hrtimer_start_range_ns - (re)start an hrtimer on the current CPU
> * @timer: the timer to be added
> @@ -992,6 +1028,8 @@ void hrtimer_start_range_ns(struct hrtimer *timer,
> ktime_t tim,
>
> timer_stats_hrtimer_set_start_info(timer);
>
> + trace_latency_hrtimer_mark_ts(timer, new_base, tim);
Hmm, since these calls are not actual tracepoints, it should not start
with "trace_".
I would like to ask you to use other function name, like
hrtimer_mark_start_timestamp()
> +
> leftmost = enqueue_hrtimer(timer, new_base);
> if (!leftmost)
> goto unlock;
> @@ -1284,6 +1322,8 @@ static void __hrtimer_run_queues(struct
> hrtimer_cpu_base *cpu_base, ktime_t now)
>
> timer = container_of(node, struct hrtimer, node);
>
> + trace_latency_missed_hrtimer(timer, basenow);
Here, too. hrtimer_expired_latency() etc.
BTW, I think "missed" is a bit misleadable, since the timer itself is
not missed,
it may be just not in time. :)
Thank you,
> +
> /*
> * The immediate goal for using the softexpires is
> * minimizing wakeups, not running timers at the
> --
> The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
> a Linux Foundation Collaborative Project
>
--
Masami Hiramatsu
