lkml.org 
[lkml]   [2016]   [Sep]   [2]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    From
    Subject[PATCH v5 4/4] tracing: Histogram for delayed hrtimer offsets
    Date
    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)
    +);
    +
    #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)
    + 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);
    + }
    +#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
    --
    The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
    a Linux Foundation Collaborative Project
    \
     
     \ /
      Last update: 2016-09-17 09:58    [W:5.723 / U:0.032 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site