From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S935535AbcJQTEV (ORCPT ); Mon, 17 Oct 2016 15:04:21 -0400 Received: from smtprelay0118.hostedemail.com ([216.40.44.118]:37491 "EHLO smtprelay.hostedemail.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S935258AbcJQTEA (ORCPT ); Mon, 17 Oct 2016 15:04:00 -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:966:968:973:981:988:989:1260:1277:1311:1313:1314:1345:1359:1434:1437:1515:1516:1518:1535:1593:1594:1605:1730:1747:1777:1792:2196:2198:2199:2200:2393:2553:2559:2562:2892:2896:2897:2898:2901:3138:3139:3140:3141:3142:3622:3865:3866:3867:3868:3870:3871:3874:4050:4118:4250:4321:4385:4605:5007:6119:6261:7875:7903:10004:10848:10967:11026:11232:11473:11658:11914:12043:12291:12295:12296:12438:12555:12683:12740:12760:13439:13870:14096:14097:14659:14877:21080:21324:21451:30029:30054:30070:30075: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:2,LUA_SUMMARY:none X-HE-Tag: wine34_57bfa29db05e X-Filterd-Recvd-Size: 7999 Date: Mon, 17 Oct 2016 15:03:56 -0400 From: Steven Rostedt To: Baolin Wang Cc: mingo@redhat.com, john.stultz@linaro.org, tglx@linutronix.de, broonie@kernel.org, linux-kernel@vger.kernel.org Subject: Re: [PATCH v3] time: alarmtimer: Add the trcepoints for alarmtimer Message-ID: <20161017150356.7dd37cae@gandalf.local.home> In-Reply-To: <98ebf1ca60f0af8a4e56b67bedd197e0b4e85c0a.1476182683.git.baolin.wang@linaro.org> References: <98ebf1ca60f0af8a4e56b67bedd197e0b4e85c0a.1476182683.git.baolin.wang@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 On Tue, 11 Oct 2016 18:48:16 +0800 Baolin Wang wrote: > For system debugging, we sometimes want to know who sets one > alarm timer, the time of the timer, when the timer started and > fired and so on. Thus adding tracepoints can help us trace the > alarmtimer information. > > For example, when we debug the system supend/resume, if the > system is always resumed by RTC alarm, we can find out which > process set the alarm timer to resume system by below trace log: > > ...... > > Binder:3292_2-3304 [000] d..2 149.981123: alarmtimer_cancel: > alarmtimer:ffffffc1319a7800 type:ALARM_REALTIME > expires:1325463120000000000 now:1325376810370370245 > > Binder:3292_2-3304 [000] d..2 149.981136: alarmtimer_start: > alarmtimer:ffffffc1319a7800 type:ALARM_REALTIME > expires:1325376840000000000 now:1325376810370384591 > > Binder:3292_9-3953 [000] d..2 150.212991: alarmtimer_cancel: > alarmtimer:ffffffc1319a5a00 type:ALARM_BOOTTIME > expires:179552000000 now:150154008122 > > Binder:3292_9-3953 [000] d..2 150.213006: alarmtimer_start: > alarmtimer:ffffffc1319a5a00 type:ALARM_BOOTTIME > expires:179551000000 now:150154025622 > > ...... > > system_server-3000 [002] ...1 1087.737565: alarmtimer_suspend: > alarmtimer type:ALARM_BOOTTIME expires: 1325376839802714584 > > ...... > > >From the trace log, we can find out the 'Binder:3292_2' process > set one alarm timer which resumes the system. > > Signed-off-by: Baolin Wang > --- > Changes since v2: > - Save time as s64 type. > - Remove 'process_name' parameter and add 'now' parameter. > - Rename the trace event name. > - Remove restart trace event. > - Other optimization. > --- > include/trace/events/alarmtimer.h | 92 +++++++++++++++++++++++++++++++++++++ > kernel/time/alarmtimer.c | 16 ++++++- > 2 files changed, 106 insertions(+), 2 deletions(-) > create mode 100644 include/trace/events/alarmtimer.h > > diff --git a/include/trace/events/alarmtimer.h b/include/trace/events/alarmtimer.h > new file mode 100644 > index 0000000..4c92a3e > --- /dev/null > +++ b/include/trace/events/alarmtimer.h > @@ -0,0 +1,92 @@ > +#undef TRACE_SYSTEM > +#define TRACE_SYSTEM alarmtimer > + > +#if !defined(_TRACE_ALARMTIMER_H) || defined(TRACE_HEADER_MULTI_READ) > +#define _TRACE_ALARMTIMER_H > + > +#include > +#include > +#include > + > +TRACE_DEFINE_ENUM(ALARM_REALTIME); > +TRACE_DEFINE_ENUM(ALARM_BOOTTIME); > + > +#define show_alarm_type(type) __print_flags(type, " | ", \ > + { 1 << ALARM_REALTIME, "ALARM_REALTIME" }, \ > + { 1 << ALARM_BOOTTIME, "ALARM_BOOTTIME" }) Why have the "ALARM_" prefix in the string? We already know that these are "alarm" tracepoints. They just make the lines longer than they need to be. Other than that, from a tracing point of view, this looks fine to me. Acked-by: Steven Rostedt -- Steve > + > +TRACE_EVENT(alarmtimer_suspend, > + > + TP_PROTO(ktime_t expires, int flag), > + > + TP_ARGS(expires, flag), > + > + TP_STRUCT__entry( > + __field(s64, expires) > + __field(unsigned char, alarm_type) > + ), > + > + TP_fast_assign( > + __entry->expires = expires.tv64; > + __entry->alarm_type = flag; > + ), > + > + TP_printk("alarmtimer type:%s expires:%llu", > + show_alarm_type((1 << __entry->alarm_type)), > + __entry->expires > + ) > +); > + > +DECLARE_EVENT_CLASS(alarm_class, > + > + TP_PROTO(struct alarm *alarm, ktime_t now), > + > + TP_ARGS(alarm, now), > + > + TP_STRUCT__entry( > + __field(void *, alarm) > + __field(unsigned char, alarm_type) > + __field(s64, expires) > + __field(s64, now) > + ), > + > + TP_fast_assign( > + __entry->alarm = alarm; > + __entry->alarm_type = alarm->type; > + __entry->expires = alarm->node.expires.tv64; > + __entry->now = now.tv64; > + ), > + > + TP_printk("alarmtimer:%p type:%s expires:%llu now:%llu", > + __entry->alarm, > + show_alarm_type((1 << __entry->alarm_type)), > + __entry->expires, > + __entry->now > + ) > +); > + > +DEFINE_EVENT(alarm_class, alarmtimer_fired, > + > + TP_PROTO(struct alarm *alarm, ktime_t now), > + > + TP_ARGS(alarm, now) > +); > + > +DEFINE_EVENT(alarm_class, alarmtimer_start, > + > + TP_PROTO(struct alarm *alarm, ktime_t now), > + > + TP_ARGS(alarm, now) > +); > + > +DEFINE_EVENT(alarm_class, alarmtimer_cancel, > + > + TP_PROTO(struct alarm *alarm, ktime_t now), > + > + TP_ARGS(alarm, now) > +); > + > +#endif /* _TRACE_ALARMTIMER_H */ > + > +/* This part must be outside protection */ > +#include > diff --git a/kernel/time/alarmtimer.c b/kernel/time/alarmtimer.c > index c3aad68..4e10dad 100644 > --- a/kernel/time/alarmtimer.c > +++ b/kernel/time/alarmtimer.c > @@ -26,6 +26,9 @@ > #include > #include > > +#define CREATE_TRACE_POINTS > +#include > + > /** > * struct alarm_base - Alarm timer bases > * @lock: Lock for syncrhonized access to the base > @@ -194,6 +197,7 @@ static enum hrtimer_restart alarmtimer_fired(struct hrtimer *timer) > } > spin_unlock_irqrestore(&base->lock, flags); > > + trace_alarmtimer_fired(alarm, base->gettime()); > return ret; > > } > @@ -222,7 +226,7 @@ static int alarmtimer_suspend(struct device *dev) > ktime_t min, now; > unsigned long flags; > struct rtc_device *rtc; > - int i; > + int i, type = 0; > int ret; > > spin_lock_irqsave(&freezer_delta_lock, flags); > @@ -247,8 +251,10 @@ static int alarmtimer_suspend(struct device *dev) > if (!next) > continue; > delta = ktime_sub(next->expires, base->gettime()); > - if (!min.tv64 || (delta.tv64 < min.tv64)) > + if (!min.tv64 || (delta.tv64 < min.tv64)) { > min = delta; > + type = i; > + } > } > if (min.tv64 == 0) > return 0; > @@ -264,6 +270,8 @@ static int alarmtimer_suspend(struct device *dev) > now = rtc_tm_to_ktime(tm); > now = ktime_add(now, min); > > + trace_alarmtimer_suspend(now, type); > + > /* Set alarm, if in the past reject suspend briefly to handle */ > ret = rtc_timer_start(rtc, &rtctimer, now, ktime_set(0, 0)); > if (ret < 0) > @@ -342,6 +350,8 @@ void alarm_start(struct alarm *alarm, ktime_t start) > alarmtimer_enqueue(base, alarm); > hrtimer_start(&alarm->timer, alarm->node.expires, HRTIMER_MODE_ABS); > spin_unlock_irqrestore(&base->lock, flags); > + > + trace_alarmtimer_start(alarm, base->gettime()); > } > EXPORT_SYMBOL_GPL(alarm_start); > > @@ -390,6 +400,8 @@ int alarm_try_to_cancel(struct alarm *alarm) > if (ret >= 0) > alarmtimer_dequeue(base, alarm); > spin_unlock_irqrestore(&base->lock, flags); > + > + trace_alarmtimer_cancel(alarm, base->gettime()); > return ret; > } > EXPORT_SYMBOL_GPL(alarm_try_to_cancel);