diff mbox

[v3] time: alarmtimer: Add the trcepoints for alarmtimer

Message ID 98ebf1ca60f0af8a4e56b67bedd197e0b4e85c0a.1476182683.git.baolin.wang@linaro.org
State Superseded
Headers show

Commit Message

(Exiting) Baolin Wang Oct. 11, 2016, 10:48 a.m. UTC 
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 <baolin.wang@linaro.org>

---
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

-- 
1.7.9.5

Comments

Steven Rostedt Oct. 17, 2016, 7:03 p.m. UTC | #1 
On Tue, 11 Oct 2016 18:48:16 +0800
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: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 <baolin.wang@linaro.org>

> ---

> 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 <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" })


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 <rostedt@goodmis.org>


-- 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 <trace/define_trace.h>

> 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 <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, 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);
(Exiting) Baolin Wang Oct. 18, 2016, 2:24 a.m. UTC | #2 
On 18 October 2016 at 03:03, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Tue, 11 Oct 2016 18:48:16 +0800

> Baolin Wang <baolin.wang@linaro.org> wrote:

>

>> ---

>> 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 <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" })

>

> 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.


Thanks Steven. I will remove the prefix and add your ACK in next version.

-- 
Baolin.wang
Best Regards
diff mbox

Patch

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 <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" })
+
+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 <trace/define_trace.h>
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 <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, 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);