| Message ID | 0d5cedb2f4ad46aa7fb07b990072bacb33517102.1474177609.git.baolin.wang@linaro.org |
|---|---|
| State | New |
| Headers | show |
On 21 September 2016 at 06:27, Thomas Gleixner <tglx@linutronix.de> wrote: > On Sun, 18 Sep 2016, Baolin Wang wrote: >> +DECLARE_EVENT_CLASS(alarm_setting, > > What is alarm_setting? Without looking at the DEFINE_EVENT which uses this > I cannot decode the meaning. Will rename it. > >> + 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; > > What's the value of storing the alarm time in RTC format? As suggested by Steven, change the type of RTC value to save trace buffer. > > What's wrong with simply storing the flat u64 based wall clock time? > Nothing, because you can do the RTC format conversion in user space. > >> +DECLARE_EVENT_CLASS(alarm_processing, > > Again alarm_processing is not telling me anything. Is alarm_class OK? > >> + >> + TP_PROTO(struct alarm *alarm, char *process_name), > > Why do you want to store process_name? The tracer already tracks the name > of the process in which context the tracepoint is taken. So what's the > point of this? Look at the output: > > system_server-2976 [003] d..2 1076.605608: alarmtimer_start: process:system_server > > Completely pointless duplicated information. OK. Will remove it. > >> + >> + 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); >> + __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; > > This is utter crap for various reasons: > > 1) You store the expiry time over and over and in most cases it's simply > pointless. I will remove the 'expires' variable. > > - If the timer is started then we want to store the expiry time. > > - If the timer fires then the programmed expiry time is available from > the start trace point and you miss to store the information which is > really interesting: The actual time at which the timer expires > (REAL/BOOT) > > - If the timer is canceled then the expiry time in the timer is not > interesting at all. All you care is about the fact that the timer has > been canceled. The expiry time can still be retrieved from the start > trace point. > > - The restart tracepoint is redundant as well because either you see: > > start -> expire -> start or start -> start which is clearly a restart. > > If you put the start trace point into alarmtimer_enqueue() then you > spare the extra code size for two tracepoints because that is used in > start and restart Make sense. > > See the hrtimer and timer tracepoints for reference. > > > 2) You store the expiry time again in RTC format. Store the information in > a plain u64 and be done with it. But I still think the RTC format is more readable for debugging alarm timer. > > >> +DEFINE_EVENT(alarm_processing, alarmtimer_fired, >> + >> + TP_PROTO(struct alarm *alarm, char *process_name), > > So you hand in a NULL pointer to this tracepoint to have even more useless > information in the trace. Will remove 'process_name' parameter. > >> @@ -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()) { > > What's the point of this conditional? Avoiding rtc_ktime_to_tm() ? Oh well... > >> + tm_set = rtc_ktime_to_tm(now); >> + trace_alarmtimer_suspend(&tm_set, type); > > "now" is CLOCK_REALTIME based. You store the type of the alarm timer which > is the first to expire and therefor is the one setting the RTC value, but > we don't know which timer it is. Useful - NOT! We can know the timer by comparing the expire time. -- Baolin.wang Best Regards
On 21 September 2016 at 15:26, Thomas Gleixner <tglx@linutronix.de> wrote: > On Wed, 21 Sep 2016, Baolin Wang wrote: >> On 21 September 2016 at 06:27, Thomas Gleixner <tglx@linutronix.de> wrote: >> >> + 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; >> > >> > What's the value of storing the alarm time in RTC format? >> >> As suggested by Steven, change the type of RTC value to save trace buffer. > > A single u64 does not take more storage space than this and it's a single > store. OK. > >> > 2) You store the expiry time again in RTC format. Store the information in >> > a plain u64 and be done with it. >> >> But I still think the RTC format is more readable for debugging alarm timer. > > That's what post processing is for. > >> > What's the point of this conditional? Avoiding rtc_ktime_to_tm() ? Oh well... >> > >> >> + tm_set = rtc_ktime_to_tm(now); >> >> + trace_alarmtimer_suspend(&tm_set, type); >> > >> > "now" is CLOCK_REALTIME based. You store the type of the alarm timer which >> > is the first to expire and therefor is the one setting the RTC value, but >> > we don't know which timer it is. Useful - NOT! >> >> We can know the timer by comparing the expire time. > > Please make it similar to the timer/hrtimer tracing so people can reuse > their postprocessing scripts with minimial tweaks. OK. Thanks. -- Baolin.wang Best Regards
diff --git a/include/trace/events/alarmtimer.h b/include/trace/events/alarmtimer.h new file mode 100644 index 0000000..a7eba5a --- /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->alarm_type = alarm->type; + __assign_str(name, process_name); + __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; + ), + + 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);