[PATCH v2] time: alarmtimer: Add the trcepoints for alarmtimer

[PATCH v2] time: alarmtimer: Add the trcepoints for alarmtimer

[Baolin Wang]

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.

Signed-off-by: Baolin Wang <baolin.wang@linaro.org>
---
Changes since v1:
 - Fix the kbuild error.
 - Modify the changelog with adding trace log.
---
 include/trace/events/alarmtimer.h |  134 +++++++++++++++++++++++++++++++++++++
 kernel/time/alarmtimer.c          |   21 +++++-
 2 files changed, 152 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..eea4e12
--- /dev/null
+++ b/include/trace/events/alarmtimer.h
@@ -0,0 +1,134 @@
+#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>
+
+#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 int, second)
+		__field(unsigned int, minute)
+		__field(unsigned int, hour)
+		__field(unsigned int, day)
+		__field(unsigned int, mon)
+		__field(unsigned int, year)
+		__field(unsigned int, 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: %u-%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 int, second)
+		__field(unsigned int, minute)
+		__field(unsigned int, hour)
+		__field(unsigned int, day)
+		__field(unsigned int, mon)
+		__field(unsigned int, year)
+		__field(unsigned int, 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: %u-%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..866d668 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,9 @@ static int alarmtimer_suspend(struct device *dev)
 	now = rtc_tm_to_ktime(tm);
 	now = ktime_add(now, min);
 
+	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 +351,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 +380,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 +403,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

Re: [PATCH v2] time: alarmtimer: Add the trcepoints for alarmtimer

[Steven Rostedt]

On Thu, 18 Aug 2016 16:47:39 +0800
Baolin Wang <baolin.wang@linaro.org> wrote:
 since v1:
>  - Fix the kbuild error.
>  - Modify the changelog with adding trace log.
> ---
>  include/trace/events/alarmtimer.h |  134 +++++++++++++++++++++++++++++++++++++
>  kernel/time/alarmtimer.c          |   21 +++++-
>  2 files changed, 152 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..eea4e12
> --- /dev/null
> +++ b/include/trace/events/alarmtimer.h
> @@ -0,0 +1,134 @@
> +#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>
> +
> +#define show_alarm_type(type)	__print_flags(type, " | ",	\
> +	{ 1 << ALARM_REALTIME, "ALARM_REALTIME" },		\
> +	{ 1 << ALARM_BOOTTIME, "ALARM_BOOTTIME" })

As ALARM_REALTIME and ALARM_BOOTTIME are both enums, they will not be
converted for userspace. Can you add the following:

TRACE_DEFINE_ENUM(ALARM_REALTIME);
TRACE_DEFINE_ENUM(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 int, second)
> +		__field(unsigned int, minute)
> +		__field(unsigned int, hour)
> +		__field(unsigned int, day)
> +		__field(unsigned int, mon)
> +		__field(unsigned int, year)
> +		__field(unsigned int, alarm_type)

To save space in the ring buffer, perhaps we can make the above not
take up so much space:

	unsigned char, second
	unsigned char, minute
	unsigned char, hour
	unsigned char, day
	unsigned char, mon
	unsigned char, alarm_type
	unsigned short, year

Why use 32 bits when most of the values fit nicely in one byte, and no
more than a 16 bytes. Also, order doesn't really matter for output, but
works well for compacting, as the above is only 8 bytes total.


> +	),
> +
> +	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: %u-%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 int, second)
> +		__field(unsigned int, minute)
> +		__field(unsigned int, hour)
> +		__field(unsigned int, day)
> +		__field(unsigned int, mon)
> +		__field(unsigned int, year)
> +		__field(unsigned int, alarm_type)

Same here.

> +		__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: %u-%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..866d668 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,9 @@ static int alarmtimer_suspend(struct device *dev)
>  	now = rtc_tm_to_ktime(tm);
>  	now = ktime_add(now, min);
>  
> +	tm_set = rtc_ktime_to_tm(now);
> +	trace_alarmtimer_suspend(&tm_set, type);

To keep from having to call rtc_ktime_to_tm(now) when not tracing, add:

	if (trace_alarmtimer_suspend_enabled()) {
		tm_set = rtc_ktime_to_tm(now);
		trace_alarmtimer_suspend(&tm_set, type);
	}

As trace_alarmtimer_suspend_enabled() is a static key and not a cmp
branch. That is, it's dynamically enabled or disabled and is always a
static branch.

-- Steve


> +
>  	/* 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 +351,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 +380,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 +403,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);

Re: [PATCH v2] time: alarmtimer: Add the trcepoints for alarmtimer

[Baolin Wang]

Hi Steven,

On 18 August 2016 at 22:33, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Thu, 18 Aug 2016 16:47:39 +0800
> Baolin Wang <baolin.wang@linaro.org> wrote:
>  since v1:
>>  - Fix the kbuild error.
>>  - Modify the changelog with adding trace log.
>> ---
>>  include/trace/events/alarmtimer.h |  134 +++++++++++++++++++++++++++++++++++++
>>  kernel/time/alarmtimer.c          |   21 +++++-
>>  2 files changed, 152 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..eea4e12
>> --- /dev/null
>> +++ b/include/trace/events/alarmtimer.h
>> @@ -0,0 +1,134 @@
>> +#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>
>> +
>> +#define show_alarm_type(type)        __print_flags(type, " | ",      \
>> +     { 1 << ALARM_REALTIME, "ALARM_REALTIME" },              \
>> +     { 1 << ALARM_BOOTTIME, "ALARM_BOOTTIME" })
>
> As ALARM_REALTIME and ALARM_BOOTTIME are both enums, they will not be
> converted for userspace. Can you add the following:
>
> TRACE_DEFINE_ENUM(ALARM_REALTIME);
> TRACE_DEFINE_ENUM(ALARM_BOOTTIME);

OK.

>
>> +
>> +DECLARE_EVENT_CLASS(alarm_setting,
>> +
>> +     TP_PROTO(struct rtc_time *rtc_time, int flag),
>> +
>> +     TP_ARGS(rtc_time, flag),
>> +
>> +     TP_STRUCT__entry(
>> +             __field(unsigned int, second)
>> +             __field(unsigned int, minute)
>> +             __field(unsigned int, hour)
>> +             __field(unsigned int, day)
>> +             __field(unsigned int, mon)
>> +             __field(unsigned int, year)
>> +             __field(unsigned int, alarm_type)
>
> To save space in the ring buffer, perhaps we can make the above not
> take up so much space:
>
>         unsigned char, second
>         unsigned char, minute
>         unsigned char, hour
>         unsigned char, day
>         unsigned char, mon
>         unsigned char, alarm_type
>         unsigned short, year
>
> Why use 32 bits when most of the values fit nicely in one byte, and no
> more than a 16 bytes. Also, order doesn't really matter for output, but
> works well for compacting, as the above is only 8 bytes total.

Make sense. Will fix in next version.

>
>
>> +     ),
>> +
>> +     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: %u-%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 int, second)
>> +             __field(unsigned int, minute)
>> +             __field(unsigned int, hour)
>> +             __field(unsigned int, day)
>> +             __field(unsigned int, mon)
>> +             __field(unsigned int, year)
>> +             __field(unsigned int, alarm_type)
>
> Same here.
>
>> +             __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: %u-%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..866d668 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,9 @@ static int alarmtimer_suspend(struct device *dev)
>>       now = rtc_tm_to_ktime(tm);
>>       now = ktime_add(now, min);
>>
>> +     tm_set = rtc_ktime_to_tm(now);
>> +     trace_alarmtimer_suspend(&tm_set, type);
>
> To keep from having to call rtc_ktime_to_tm(now) when not tracing, add:
>
>         if (trace_alarmtimer_suspend_enabled()) {
>                 tm_set = rtc_ktime_to_tm(now);
>                 trace_alarmtimer_suspend(&tm_set, type);
>         }
>
> As trace_alarmtimer_suspend_enabled() is a static key and not a cmp
> branch. That is, it's dynamically enabled or disabled and is always a
> static branch.

Great, will fix it. Thanks for your comments.

>
> -- Steve
>
>
>> +
>>       /* 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 +351,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 +380,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 +403,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);
>



-- 
Baolin.wang
Best Regards

Re: [PATCH v2] time: alarmtimer: Add the trcepoints for alarmtimer

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 2003 bytes --]

Hi Baolin,

[auto build test ERROR on tip/timers/core]
[also build test ERROR on v4.8-rc3 next-20160822]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]
[Suggest to use git(>=2.9.0) format-patch --base=<commit> (or --base=auto for convenience) to record what (public, well-known) commit your patch series was built on]
[Check https://git-scm.com/docs/git-format-patch for more information]

url:    https://github.com/0day-ci/linux/commits/Baolin-Wang/time-alarmtimer-Add-the-trcepoints-for-alarmtimer/20160818-165619
config: powerpc-c2k_defconfig (attached as .config)
compiler: powerpc-linux-gnu-gcc (Debian 5.4.0-6) 5.4.0 20160609
reproduce:
        wget https://git.kernel.org/cgit/linux/kernel/git/wfg/lkp-tests.git/plain/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # save the attached .config to linux build tree
        make.cross ARCH=powerpc 

All errors (new ones prefixed by >>):

   kernel/built-in.o: In function `perf_trace_alarm_processing':
>> include/trace/events/alarmtimer.h:59: undefined reference to `rtc_ktime_to_tm'
>> include/trace/events/alarmtimer.h:59: undefined reference to `rtc_ktime_to_tm'
>> include/trace/events/alarmtimer.h:59: undefined reference to `rtc_ktime_to_tm'
>> include/trace/events/alarmtimer.h:59: undefined reference to `rtc_ktime_to_tm'
>> include/trace/events/alarmtimer.h:59: undefined reference to `rtc_ktime_to_tm'
   kernel/built-in.o:include/trace/events/alarmtimer.h:59: more undefined references to `rtc_ktime_to_tm' follow

vim +59 include/trace/events/alarmtimer.h

    53	
    54		TP_PROTO(struct rtc_time *time, int flag),
    55	
    56		TP_ARGS(time, flag)
    57	);
    58	
  > 59	DECLARE_EVENT_CLASS(alarm_processing,
    60	
    61		TP_PROTO(struct alarm *alarm, char *process_name),
    62	

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/octet-stream, Size: 18422 bytes --]