Hi, On 22 August 2016 at 12:23, Baolin Wang <baolin.w...@linaro.org> wrote: > For system debugging, we usually 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:2976_6-3473 [005] d..2 1076.587732: alarmtimer_start: > process:Binder:2976_6 > alarmtimer type:ALARM_BOOTTIME expires:1234154000000 time: 1970-1-1 0:20:35 > > Binder:2976_7-3480 [002] d..2 1076.592707: alarmtimer_cancel: > process:Binder:2976_7 > alarmtimer type:ALARM_BOOTTIME expires:1325463060000000000 time: 2012-1-2 > 0:11:0 > > Binder:2976_7-3480 [002] d..2 1076.592731: alarmtimer_start: > process:Binder:2976_7 > alarmtimer type:ALARM_BOOTTIME expires:1325378040000000000 time: 2012-1-1 > 0:34:0 > > system_server-2976 [003] d..2 1076.605587: alarmtimer_cancel: > process:system_server > alarmtimer type:ALARM_BOOTTIME expires:1234154000000 time: 1970-1-1 0:20:35 > > system_server-2976 [003] d..2 1076.605608: alarmtimer_start: > process:system_server > alarmtimer type:ALARM_BOOTTIME expires:1234155000000 time: 1970-1-1 0:20:35 > > system_server-3000 [002] ...1 1087.737565: alarmtimer_suspend: alarmtimer > type:ALARM_BOOTTIME > expires time: 2012-1-1 0:34:0 > ...... > > From the trace log, we can find out the 'Binder:2976_7' process set one alarm > timer which resumes the system.
Do you have any comments about this patch? Thanks. > > Signed-off-by: Baolin Wang <baolin.w...@linaro.org> > --- > Changes since v2: > - Add TRACE_DEFINE_ENUM() macros. > - Change the time variables type to save space in the ring buffer. > - Add trace_alarmtimer_suspend_enabled() in case of tracing is not enabled. > > Changes since v1: > - Fix the kbuild error. > - Modify the changelog with adding trace log. > --- > include/trace/events/alarmtimer.h | 137 > +++++++++++++++++++++++++++++++++++++ > kernel/time/alarmtimer.c | 23 ++++++- > 2 files changed, 157 insertions(+), 3 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..6a34bc9 > --- /dev/null > +++ b/include/trace/events/alarmtimer.h > @@ -0,0 +1,137 @@ > +#undef TRACE_SYSTEM > +#define TRACE_SYSTEM alarmtimer > + > +#if !defined(_TRACE_ALARMTIMER_H) || defined(TRACE_HEADER_MULTI_READ) > +#define _TRACE_ALARMTIMER_H > + > +#include <linux/alarmtimer.h> > +#include <linux/rtc.h> > +#include <linux/tracepoint.h> > + > +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" }) > + > +DECLARE_EVENT_CLASS(alarm_setting, > + > + TP_PROTO(struct rtc_time *rtc_time, int flag), > + > + TP_ARGS(rtc_time, flag), > + > + TP_STRUCT__entry( > + __field(unsigned char, second) > + __field(unsigned char, minute) > + __field(unsigned char, hour) > + __field(unsigned char, day) > + __field(unsigned char, mon) > + __field(unsigned short, year) > + __field(unsigned char, alarm_type) > + ), > + > + TP_fast_assign( > + __entry->second = rtc_time->tm_sec; > + __entry->minute = rtc_time->tm_min; > + __entry->hour = rtc_time->tm_hour; > + __entry->day = rtc_time->tm_mday; > + __entry->mon = rtc_time->tm_mon; > + __entry->year = rtc_time->tm_year; > + __entry->alarm_type = flag; > + ), > + > + TP_printk("alarmtimer type:%s expires time: %hu-%u-%u %u:%u:%u", > + show_alarm_type((1 << __entry->alarm_type)), > + __entry->year + 1900, > + __entry->mon + 1, > + __entry->day, > + __entry->hour, > + __entry->minute, > + __entry->second > + ) > +); > + > +DEFINE_EVENT(alarm_setting, alarmtimer_suspend, > + > + TP_PROTO(struct rtc_time *time, int flag), > + > + TP_ARGS(time, flag) > +); > + > +DECLARE_EVENT_CLASS(alarm_processing, > + > + TP_PROTO(struct alarm *alarm, char *process_name), > + > + TP_ARGS(alarm, process_name), > + > + TP_STRUCT__entry( > + __field(unsigned long long, expires) > + __field(unsigned char, second) > + __field(unsigned char, minute) > + __field(unsigned char, hour) > + __field(unsigned char, day) > + __field(unsigned char, mon) > + __field(unsigned short, year) > + __field(unsigned char, alarm_type) > + __string(name, process_name) > + ), > + > + TP_fast_assign( > + __entry->expires = alarm->node.expires.tv64; > + __entry->second = rtc_ktime_to_tm(alarm->node.expires).tm_sec; > + __entry->minute = rtc_ktime_to_tm(alarm->node.expires).tm_min; > + __entry->hour = rtc_ktime_to_tm(alarm->node.expires).tm_hour; > + __entry->day = rtc_ktime_to_tm(alarm->node.expires).tm_mday; > + __entry->mon = rtc_ktime_to_tm(alarm->node.expires).tm_mon; > + __entry->year = rtc_ktime_to_tm(alarm->node.expires).tm_year; > + __entry->alarm_type = alarm->type; > + __assign_str(name, process_name); > + ), > + > + TP_printk("process:%s alarmtimer type:%s expires:%llu " > + "time: %hu-%u-%u %u:%u:%u", > + __get_str(name), > + show_alarm_type((1 << __entry->alarm_type)), > + __entry->expires, > + __entry->year + 1900, > + __entry->mon + 1, > + __entry->day, > + __entry->hour, > + __entry->minute, > + __entry->second > + ) > +); > + > +DEFINE_EVENT(alarm_processing, alarmtimer_fired, > + > + TP_PROTO(struct alarm *alarm, char *process_name), > + > + TP_ARGS(alarm, process_name) > +); > + > +DEFINE_EVENT(alarm_processing, alarmtimer_start, > + > + TP_PROTO(struct alarm *alarm, char *process_name), > + > + TP_ARGS(alarm, process_name) > +); > + > +DEFINE_EVENT(alarm_processing, alarmtimer_restart, > + > + TP_PROTO(struct alarm *alarm, char *process_name), > + > + TP_ARGS(alarm, process_name) > +); > + > +DEFINE_EVENT(alarm_processing, alarmtimer_cancel, > + > + TP_PROTO(struct alarm *alarm, char *process_name), > + > + TP_ARGS(alarm, process_name) > +); > + > +#endif /* _TRACE_ALARMTIMER_H */ > + > +/* This part must be outside protection */ > +#include <trace/define_trace.h> > diff --git a/kernel/time/alarmtimer.c b/kernel/time/alarmtimer.c > index c3aad68..7cd15eb 100644 > --- a/kernel/time/alarmtimer.c > +++ b/kernel/time/alarmtimer.c > @@ -26,6 +26,9 @@ > #include <linux/workqueue.h> > #include <linux/freezer.h> > > +#define CREATE_TRACE_POINTS > +#include <trace/events/alarmtimer.h> > + > /** > * 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, NULL); > return ret; > > } > @@ -218,11 +222,11 @@ EXPORT_SYMBOL_GPL(alarm_expires_remaining); > */ > static int alarmtimer_suspend(struct device *dev) > { > - struct rtc_time tm; > + struct rtc_time tm, tm_set; > 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,11 @@ static int alarmtimer_suspend(struct device *dev) > now = rtc_tm_to_ktime(tm); > now = ktime_add(now, min); > > + if (trace_alarmtimer_suspend_enabled()) { > + tm_set = rtc_ktime_to_tm(now); > + trace_alarmtimer_suspend(&tm_set, 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 +353,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, current->comm); > } > EXPORT_SYMBOL_GPL(alarm_start); > > @@ -369,6 +382,8 @@ void alarm_restart(struct alarm *alarm) > hrtimer_restart(&alarm->timer); > alarmtimer_enqueue(base, alarm); > spin_unlock_irqrestore(&base->lock, flags); > + > + trace_alarmtimer_restart(alarm, current->comm); > } > EXPORT_SYMBOL_GPL(alarm_restart); > > @@ -390,6 +405,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, current->comm); > return ret; > } > EXPORT_SYMBOL_GPL(alarm_try_to_cancel); > -- > 1.7.9.5 > -- Baolin.wang Best Regards