| Message ID | 1472552924-22297-4-git-send-email-binoy.jayan@linaro.org |
|---|---|
| State | New |
| Headers | show |
Hi Binoy, 2016-08-30 19:28 GMT+09:00 Binoy Jayan <binoy.jayan@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.jayan@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
On 30 August 2016 at 19:45, Steven Rostedt <rostedt@goodmis.org> wrote: > On Tue, 30 Aug 2016 15:58:44 +0530 > Binoy Jayan <binoy.jayan@linaro.org> wrote: > >> + >> + TP_STRUCT__entry( >> + __field(long long, toffset) >> + __array(char, ccomm, TASK_COMM_LEN) > > Can curr be different than current? If not, lets not record it. > > -- Steve > Hi Steve, If my understanding is right, I think both are not the same. The predefined field relates to the current process which was interrupted by the hrtimer. This I guess does not have a meaning in this context. Mostly it is the idle process which is interrupted by the hrtimer. But the ccomm field refers to the task woken up by the process. The latencies are measured for this task. So I it is needed. -Binoy
On 30 August 2016 at 16:20, Masami Hiramatsu <masami.hiramatsu@linaro.org> wrote: > Hi Binoy, >> >> +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 >> +} Hi Masami, I always see these values to be relative and not absolute time. I found 'praecox' to be always zero during test. What do you think. Binoy
2016-09-02 21:41 GMT+09:00 Binoy Jayan <binoy.jayan@linaro.org>: > On 30 August 2016 at 16:20, Masami Hiramatsu > <masami.hiramatsu@linaro.org> wrote: >> Hi Binoy, >>> >>> +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 >>> +} > > Hi Masami, > > I always see these values to be relative and not absolute time. I > found 'praecox' to be always zero during test. > What do you think. Ah, right. Since "tim" is expire time (timer target), that should always be "now + x" (x is enough larger than how long setting the hrtimer takes). Or, hrtimer expires before finished to set. :) Thank you, -- Masami Hiramatsu
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()) { + 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); + } +#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()) + 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); + 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); + /* * The immediate goal for using the softexpires is * minimizing wakeups, not running timers at the
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.jayan@linaro.org> --- include/linux/hrtimer.h | 3 +++ include/trace/events/latency.h | 29 +++++++++++++++++++++++++++++ kernel/time/hrtimer.c | 40 ++++++++++++++++++++++++++++++++++++++++ 3 files changed, 72 insertions(+) -- The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum, a Linux Foundation Collaborative Project