| Message ID | d456d1c4b4fceabe961d7db81bca190226173253.1473228276.git.baolin.wang@linaro.org |
|---|---|
| State | Superseded |
| Headers | show |
On Tue, Sep 6, 2016 at 11:06 PM, Baolin Wang <baolin.wang@linaro.org> 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: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. > > Signed-off-by: Baolin Wang <baolin.wang@linaro.org> > Acked-by: Steven Rostedt <rostedt@goodmis.org> > --- > Changes since v3: > - Fix the build error on S390. Since the original change is already applied to tip/timers/core, can you provide an incremental patch (a patch against tip/timers/core) that fixes the issue, rather then resending the entire patch? Also, the "#ifdef CONFIG_RTC_LIB" solution I proposed was sort of a hack, so I'd hope to see something better. One better solution would be to add a dummy static inline implementation of rtc_ktime_to_tm() in include/linux/rtc.h. ie something like: #ifdef CONFIG_RTC_LIB struct rtc_time rtc_ktime_to_tm(ktime_t kt); #else static inline rtc_time rtc_ktime_to_tm(ktime_t kt) { struct rt_time ret; memset(&ret, 0, sizeof(struct rt_time)); return ret; } #endif thanks -john thanks -john
Hi John, On 7 September 2016 at 14:17, John Stultz <john.stultz@linaro.org> wrote: > On Tue, Sep 6, 2016 at 11:06 PM, Baolin Wang <baolin.wang@linaro.org> 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: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. >> >> Signed-off-by: Baolin Wang <baolin.wang@linaro.org> >> Acked-by: Steven Rostedt <rostedt@goodmis.org> >> --- >> Changes since v3: >> - Fix the build error on S390. > > Since the original change is already applied to tip/timers/core, can > you provide an incremental patch (a patch against tip/timers/core) > that fixes the issue, rather then resending the entire patch? OK. > > Also, the "#ifdef CONFIG_RTC_LIB" solution I proposed was sort of a > hack, so I'd hope to see something better. > > One better solution would be to add a dummy static inline > implementation of rtc_ktime_to_tm() in include/linux/rtc.h. > > ie something like: > #ifdef CONFIG_RTC_LIB > struct rtc_time rtc_ktime_to_tm(ktime_t kt); > #else > static inline rtc_time rtc_ktime_to_tm(ktime_t kt) > { > struct rt_time ret; > memset(&ret, 0, sizeof(struct rt_time)); > return ret; > } > #endif Make sense. Thanks. > > thanks > -john > > thanks > -john -- Baolin.wang Best Regards
Hi Thomas, On 8 September 2016 at 00:03, Thomas Gleixner <tglx@linutronix.de> wrote: > On Tue, 6 Sep 2016, John Stultz wrote: >> > Changes since v3: >> > - Fix the build error on S390. >> >> Since the original change is already applied to tip/timers/core, can >> you provide an incremental patch (a patch against tip/timers/core) >> that fixes the issue, rather then resending the entire patch? > > I zapped it from timers/core as it was the top commit. So we can redo it > completely, but we can do it incremental as well. Whatever you prefer. I've send out one incremental patch to fix this issue[1]. Thanks. [1] https://lkml.org/lkml/2016/9/7/828 -- Baolin.wang Best Regards
diff --git a/include/trace/events/alarmtimer.h b/include/trace/events/alarmtimer.h new file mode 100644 index 0000000..7ab9a36 --- /dev/null +++ b/include/trace/events/alarmtimer.h @@ -0,0 +1,146 @@ +#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->alarm_type = alarm->type; + __assign_str(name, process_name); +#ifdef CONFIG_RTC_LIB + __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; +#else + __entry->second = 0; + __entry->minute = 0; + __entry->hour = 0; + __entry->day = 0; + __entry->mon = 0; + __entry->year = 0; +#endif + ), + + 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);