From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752247AbcIBNUZ (ORCPT ); Fri, 2 Sep 2016 09:20:25 -0400 Received: from smtprelay0026.hostedemail.com ([216.40.44.26]:42624 "EHLO smtprelay.hostedemail.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1751055AbcIBNUY (ORCPT ); Fri, 2 Sep 2016 09:20:24 -0400 X-Session-Marker: 726F737465647440676F6F646D69732E6F7267 X-Spam-Summary: 2,0,0,,d41d8cd98f00b204,rostedt@goodmis.org,:::::::::::::,RULES_HIT:2:41:355:379:541:599:800:960:973:988:989:1260:1277:1311:1313:1314:1345:1359:1431:1434:1437:1515:1516:1518:1535:1593:1594:1605:1606:1730:1747:1777:1792:2393:2553:2559:2562:2692:2897:2904:3138:3139:3140:3141:3142:3865:3866:3867:3868:3870:3871:3872:4117:4321:4605:5007:6119:6261:7875:9163:10004:10848:10967:11026:11232:11473:11658:11914:12043:12291:12294:12296:12438:12555:12683:12740:13161:13229:13439:14096:14097:14659:21080:21088:21451:30045:30054:30056:30070:30090:30091,0,RBL:none,CacheIP:none,Bayesian:0.5,0.5,0.5,Netcheck:none,DomainCache:0,MSF:not bulk,SPF:fn,MSBL:0,DNSBL:none,Custom_rules:0:0:0,LFtime:5,LUA_SUMMARY:none X-HE-Tag: land66_3d1174ed13700 X-Filterd-Recvd-Size: 6762 Date: Fri, 2 Sep 2016 09:20:18 -0400 From: Steven Rostedt To: Binoy Jayan Cc: Ingo Molnar , Daniel Wagner , Arnd Bergmann , linux-kernel@vger.kernel.org, Masami , Thomas Gleixner Subject: Re: [PATCH v5 4/4] tracing: Histogram for delayed hrtimer offsets Message-ID: <20160902092018.37e4a7f9@gandalf.local.home> In-Reply-To: <1472819851-12857-5-git-send-email-binoy.jayan@linaro.org> References: <1472819851-12857-1-git-send-email-binoy.jayan@linaro.org> <1472819851-12857-5-git-send-email-binoy.jayan@linaro.org> X-Mailer: Claws Mail 3.13.2 (GTK+ 2.24.30; x86_64-pc-linux-gnu) MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org [ Added Cc to hrtimer maintainer ] On Fri, 2 Sep 2016 18:07:31 +0530 Binoy Jayan 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 > --- > 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 : "", > + 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 > > #include > +#include > > #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